Страницы

вторник, 25 декабря 2012 г.

Лог работы sql-операторов

Программистов и администраторов баз данных часто интересует вопрос о том как в течение определенного периода времени работают те или иные запросы, зашитые в кодах хранимых процедур баз данных. То есть иметь информацию о том сколько времени выполняются запросы, сколько записей обрабатывают.

При таком подходе можно получить статистику о длительности выполнения запросов при различном числе активных соединений, и нагрузке на сервер. Также может быть ценна информация о том насколько часто определенные запросы выполняются по инициативе клиентских соединений.

Как удобнее всего внедрить такую систему логирования? Первое, что приходит в голову, это создать таблицу с логами и в коде хранимой процедуры до и после определенного sql-оператора добавить вставки в таблицу логов:

Сперва создаем таблицу для логов:

create table dbo.SqlLog
(
      ProcName    nvarchar ( 400 )        not null,
      CurrentDate datetime                not null default getdate (),
      IdRec       int identity ( 1, 1  not null,
      RowId       int identity ( 1, 1 )   not null,
      Descr       nvarchar ( 100 )        not null,
      RecCount    int                     not null default ( 0 ),
      constraint PK_SqlLog_ProcName_CurrentDate primary key clustered
          ( ProcName asc, CurrentDate asc, IdRec asc )
          with ( fillfactor = 80 )
) on [PRIMARY]

Предположим есть процедура, содержащая следующий sql-оператор:
update dbo.Customers
      set cType = 1
      where CreateDate >= '2012-02-03'

Теперь добавим код для логирования данных:
insert into dbo.SqlLog ( ProcName, Descr )
      values ( N'CustomersAttrSet', N'начало обновления типа' )
update dbo.Customers
      set cType = 1
      where CreateDate >= '2012-02-03'
insert into dbo.SqlLog ( ProcName, Descr, RecCount )
      values ( N'CustomersAttrSet', N'окончание обновления типа', @@rowcount )

Задача решена, таблица SqlLog будет содержать данные о времени начала и окончания работы оператора update определенной хранимой процедуры и о том, сколько записей было обработано. Тем не менее описанный способ имеет определенные недостатки.

Если база данных содержит сотни хранимых процедур, некоторые из которых могут состоять из нескольких тысяч строк, то процесс добавления вставок может оказаться слишком долгим. Кроме того, при этом по каждой строке таблицы логов необходимо понять, какой sql-инструкции она соответствует. В примере выше это реализовано посредством поля Descr. Хотелось бы, чтобы процесс был автоматизирован. Именно такой автоматизации посвящена данная статья.

Вместо того, чтобы выполнять какие-либо действия по логированию, это можно поручить программе "SQL Server Profiler". Если специальным образом настроить трассу, то она может логировать самые разные события, связанные с запуском хранимых процедур. Кроме того, процесс создания такой трассы можно реализовать с помощью Transact-SQL. Тут добрую службу могут сослужить хранимые процедуры sp_trace_create, sp_trace_setstatus, sp_trace_setfilter. Итак, приступим к разработке.


Для начала создадим схему, которая будет содержать все необходимые нам объекты:


create schema Audit
      authorization dbo

Код выше создает схему Audit, назначая ей в качестве владельца владельца текущей базы данных. Теперь необходимо создать хранимую процедуру, при запуске которой для текущего соединения активируется механизм слежения за запросами, исполняемыми внутри хранимых процедур.
create proc Audit.StartScriptWatch
with encryption
as
begin
      set nocount, xact_abort on
     
      declare @traceid int, @FileName nvarchar ( 256 ) = N'C:\Users\Владимир\Desktop\' + cast ( @@spid as nvarchar ( 100 ) ),
            @value int = cast ( @@spid as int ), @maxfilesize bigint = 2, @eventid int = 45
     
      exec sp_trace_create @traceid = @traceid out, @optuins = 2,
            @tracefile = @FileName, @maxfilesize = @maxfilesize, @stoptime = null, @filecount = 2
     
      exec sp_trace_setfilter @traceid = @traceid, @columnid = 12, @logial_operator = 0,
            @comparison_operator = 0, @value = @value
     
      exec sp_trace_setevent @traceid = @traceid, @eventid = @eventid, @columnid = 1, @on = 1
      exec sp_trace_setevent @traceid = @traceid, @eventid = @eventid, @columnid = 6, @on = 1
      exec sp_trace_setevent @traceid = @traceid, @eventid = @eventid, @columnid = 7, @on = 1
      exec sp_trace_setevent @traceid = @traceid, @eventid = @eventid, @columnid = 8, @on = 1
      exec sp_trace_setevent @traceid = @traceid, @eventid = @eventid, @columnid = 11, @on = 1
      exec sp_trace_setevent @traceid = @traceid, @eventid = @eventid, @columnid = 13, @on = 1
      exec sp_trace_setevent @traceid = @traceid, @eventid = @eventid, @columnid = 14, @on = 1
      exec sp_trace_setevent @traceid = @traceid, @eventid = @eventid, @columnid = 15, @on = 1
      exec sp_trace_setevent @traceid = @traceid, @eventid = @eventid, @columnid = 16, @on = 1
      exec sp_trace_setevent @traceid = @traceid, @eventid = @eventid, @columnid = 17, @on = 1
      exec sp_trace_setevent @traceid = @traceid, @eventid = @eventid, @columnid = 18, @on = 1
      exec sp_trace_setevent @traceid = @traceid, @eventid = @eventid, @columnid = 22, @on = 1
      exec sp_trace_setevent @traceid = @traceid, @eventid = @eventid, @columnid = 11, @on = 1
      exec sp_trace_setevent @traceid = @traceid, @eventid = @eventid, @columnid = 29, @on = 1
      exec sp_trace_setevent @traceid = @traceid, @eventid = @eventid, @columnid = 48, @on = 1
     
      exec sp_trace_setstatus @traceid = @traceid, @status = 1
     
end
go

Перед продолжением изложения давайте обсудим код процедуры. Как и аннонсировалось выше всю работу по логированию будет выполнять трасса профилировщика. 

С помощью хранимой процедуры sp_trace_create создаем на сервере трассу. Пока для нее не заданы параметры и она не запущена. Процедура по отслеживанию изменений может запускаться в нескольких сессиях, поэтому имя трассировочного файла должно быть уникальным, в нашем случае в имя зашит идентификатор серверного соединения. Также необходимо задать фильтр, чтобы трасса отслеживала лишь события одной сессии, для этого вызывается хранимая процедура sp_trace_setfilter. Данные трассы, предстают перед пользователем в программу SQL Server Profiler в табличном виде. В таком же виде информация трассы сохраняется в трассировочный файл. Поэтому в процедуре sp_trace_setfilter необходимо указать номер столбца, к которому применяется фильтр. В нашем случае это столбец с номером сессии, его идентификатор можно найти в системном представлении sys.trace_columns.

С помощью хранимой процедуры sp_trace_setevent указываем для каких столбцов трассы требуется возвращать данные. Будем логировать информацию следующих столбцов: текстовое выражение выполненного запроса, имя входа в Windows и домен, имя компьютера, с которого выполняется запрос, имя входа на сервер, время выполнения запроса, время его начала и окончания, число операций чтения, записи, затраченное процессорное время, идентификатор объекта, который содержит запрос (хранимая процедуры), уровень вложенности, число записей, обработанных запросом. Идентификаторы всех этих столбцов указываются в параметре sp_trace_setevent и их также можно найти в представлении sys.trace_columns. Помимо этого в процедуре sp_trace_setevent необходимо указать при каком событии трасса должна логировать работу соединения. Для нашей задачи событие это окончания работы запроса в теле хранимой процедуры. Номер этого события можно найти в представлении sys.trace_events. Итак, все готово для включения трассы, что и делается с помощью хранимой процедуры sp_trace_setstatus.

После того как процедуры Audit.StartScriptWatch завершает свою работу можно вызывать штатные процедуры сервера, за запросами которых требуется следить. Когда процедуры завершат свою работу требуется вызвать хранимую процедуру, которая остановит процесс слежения, импортирует данные из трассировочного файла в специальную таблицу и удалит трассу с сервера. Сперва создадим таблицу с историей логов:

create table Audit.WatchLog
(
      TextData          nvarchar ( max )             not null,
      NTUserName        nvarchar ( 200 )             not null,
      NTDomainName      nvarchar ( 200 )             not null,
      HostName          nvarchar ( 200 )             not null,
      LoginName         nvarchar ( 200 )             not null,
      Duration          bigint                       not null,
      StartTime         datetime                     not null,
      EndTime           datetime                     not null,
      Reads             bigint                       not null,
      Writes            bigint                       not null,
      CPU               bigint                       not null,
      ObjectID          bigint                       not null,
      ServerName        nvarchar ( 200 )             not null,
      NestLevel         int                          not null,
      RowCounts         bigint                       not null,
      RowId             bigint identity ( 1, 1 )     not null,
     
      constraint PK_WatchLog_ObjectID_StartTime_RowId primary key clustered ( ObjectID asc, StartTime asc, RowId asc )
            with ( fillfactor = 80 )
) on [PRIMARY]

Теперь создадим хранимую процедуру остановки трассы и импорта данных в таблицу:
alter proc Audit.StopScriptWatch
with encryption
as
begin
    set nocount, xact_abort on
    
    declare @traceid int, @FileName nvarchar ( 256 ) = N'C:\Users\EdynakVV\Desktop\' + cast ( @@spid as nvarchar ( 100 ) ),
          @cmd varchar ( 8000 )
    
    select @traceid = id
    from sys.traces
    where [path] = @FileName + N'.trc'
   
    if @traceid is null
            return
    
    insert into Audit.WatchLog ( TextData, NTUserName, NTDomainName, HostName, LoginName, Duration, StartTime, EndTime, Reads, Writes,
            CPU, ObjectID, ServerName, NestLevel, RowCounts )
            select
                  TextData,
                  isnull ( NTUserName, N'unknown' ),
                  isnull ( NTDomainName, N'unknown' ),
                  isnull ( HostName, N'unknown' ),
                  isnull ( LoginName, N'unknown' ),
                  isnull ( Duration, -1 ),
                  isnull ( StartTime, '1900-01-01' ),
                  isnull ( EndTime, '1900-01-01' ),
                  isnull ( Reads, -1 ),
                  isnull ( Writes, -1 ),
                  isnull ( CPU, -1 ),
                  isnull ( ObjectID, -1 ),
                  isnull ( ServerName, N'unknown' ),
                  isnull ( NestLevel, -1 ),
                  isnull ( RowCounts, -1 )
            from sys.fn_trace_gettable ( @FileName + N'.trc', null )
            where TextData is not null
     
    exec sp_trace_setstatus @traceid = @traceid, @status = 0
    exec sp_trace_setstatus @traceid = @traceid, @status = 2
   
    set @cmd = N'Del "' + @FileName + N'.trc' + '"'
    exec master.dbo.xp_cmdshell @cmd
end
go

Итак, автоматизированная система отслеживания характера выполнения запросов (время выполнения, число обрабатываемых записей и прочее) готова! Можно самостоятельно отредактировать процедуры для возможности включения дополнительных столбцов и/или фильтров, слежения за иными событиями.





Комментариев нет:

Отправить комментарий