A union of curiosity and data science

Knowledgebase and brain dump of a database engineer


A slow query log for SQL Server

 
 
SQL Server Profiler Trace for catching people who are querying my tables without specifying locking hints.
I'll catch you and I'm watching you........ 
 
This  trace is one tool in finding server bottle necks.  The job below functions like  this... 
1. Creates a trace on the hour every hour.
2. The trace captures querys' and procedure calls with a duration greater than 5 seconds.
3. The job also deletes any traces > 12 hours old through VBScript.
 
The Job:
 
/* created by Don Rickman 2/10/2011 */


USE
[msdb]

GO

 

/****** Object: Job [@@@ Hourly Trace for Auditing]    Script Date: 02/10/2011 16:29:24 ******/

BEGIN TRANSACTION

DECLARE @ReturnCode INT

SELECT @ReturnCode = 0

/****** Object: JobCategory [[Uncategorized (Local)]]]    Script Date: 02/10/2011 16:29:24 ******/

IF NOT EXISTS (SELECT name FROM msdb.dbo.syscategories WHERE name=N'[Uncategorized (Local)]' AND category_class=1)

BEGIN

EXEC @ReturnCode = msdb.dbo.sp_add_category @class=N'JOB', @type=N'LOCAL', @name=N'[Uncategorized (Local)]'

IF (@@ERROR <> 0 OR @ReturnCode <> 0) GOTO QuitWithRollback

 

END

 

DECLARE @jobId BINARY(16)

EXEC @ReturnCode = msdb.dbo.sp_add_job @job_name=N'@@@ Hourly Trace for Auditing',

            @enabled=1,

            @notify_level_eventlog=0,

            @notify_level_email=0,

            @notify_level_netsend=0,

            @notify_level_page=0,

            @delete_level=0,

            @description=N'Trace to catch transactions... 12 hour window. Each trace is scheduled to end after an hour. the delete script deletes files older than 12 hours. the trace filter duration > 5 seconds.',

            @category_name=N'[Uncategorized (Local)]',

            @owner_login_name=N'sa', @job_id = @jobId OUTPUT

IF (@@ERROR <> 0 OR @ReturnCode <> 0) GOTO QuitWithRollback

/****** Object: Step [hourly trace creation]    Script Date: 02/10/2011 16:29:24 ******/

EXEC @ReturnCode = msdb.dbo.sp_add_jobstep @job_id=@jobId, @step_name=N'hourly trace creation',

            @step_id=1,

            @cmdexec_success_code=0,

            @on_success_action=4,

            @on_success_step_id=2,

            @on_fail_action=2,

            @on_fail_step_id=0,

            @retry_attempts=0,

            @retry_interval=0,

            @os_run_priority=0, @subsystem=N'TSQL',

            @command=N'

-- create the trace file for this hour.

-- this should be scheduled to run every hour and creates a new trace.

-- set the variables

declare @rc int

declare @TraceID int

declare @maxfilesize bigint

set @maxfilesize = 10000

 

declare @end_time datetime

--set @end_time = dateadd(hour, 1,getdate())

 set @end_time = dateadd(minute, 61,getdate())

 

 

declare @start_time varchar(12)

set @start_time = substring(replace(replace(replace(convert(varchar(32), getdate(), 120), ''-'', ''''), '':'', ''''), '' '', ''''), 1, 12)

 

 

declare @current_trace_file nvarchar(256)

--THIS SHOULD BE THE LOCACTION OF THE CURRENT TRACE

set @current_trace_file = N''L:\Profiler_Logs\current_trace_file_'' + @start_time

 

 

--- create the trace

exec @rc = sp_trace_create @TraceID output, 0, @current_trace_file , @maxfilesize, @end_time

 

 

if (@rc != 0) goto error

 

-- Client side File and Table cannot be scripted

 

-- Set the events

declare @on bit

set @on = 1

 

exec sp_trace_setevent @TraceID, 10, 15, @on

exec sp_trace_setevent @TraceID, 10, 16, @on

exec sp_trace_setevent @TraceID, 10, 9, @on

exec sp_trace_setevent @TraceID, 10, 17, @on

exec sp_trace_setevent @TraceID, 10, 2, @on

exec sp_trace_setevent @TraceID, 10, 10, @on

exec sp_trace_setevent @TraceID, 10, 18, @on

exec sp_trace_setevent @TraceID, 10, 34, @on

exec sp_trace_setevent @TraceID, 10, 3, @on

exec sp_trace_setevent @TraceID, 10, 11, @on

exec sp_trace_setevent @TraceID, 10, 35, @on

exec sp_trace_setevent @TraceID, 10, 12, @on

exec sp_trace_setevent @TraceID, 10, 13, @on

exec sp_trace_setevent @TraceID, 10, 6, @on

exec sp_trace_setevent @TraceID, 10, 14, @on

exec sp_trace_setevent @TraceID, 12, 15, @on

exec sp_trace_setevent @TraceID, 12, 16, @on

exec sp_trace_setevent @TraceID, 12, 1, @on

exec sp_trace_setevent @TraceID, 12, 9, @on

exec sp_trace_setevent @TraceID, 12, 17, @on

exec sp_trace_setevent @TraceID, 12, 6, @on

exec sp_trace_setevent @TraceID, 12, 10, @on

exec sp_trace_setevent @TraceID, 12, 14, @on

exec sp_trace_setevent @TraceID, 12, 18, @on

exec sp_trace_setevent @TraceID, 12, 3, @on

exec sp_trace_setevent @TraceID, 12, 11, @on

exec sp_trace_setevent @TraceID, 12, 35, @on

exec sp_trace_setevent @TraceID, 12, 12, @on

exec sp_trace_setevent @TraceID, 12, 13, @on

exec sp_trace_setevent @TraceID, 13, 12, @on

exec sp_trace_setevent @TraceID, 13, 1, @on

exec sp_trace_setevent @TraceID, 13, 9, @on

exec sp_trace_setevent @TraceID, 13, 6, @on

exec sp_trace_setevent @TraceID, 13, 10, @on

exec sp_trace_setevent @TraceID, 13, 14, @on

exec sp_trace_setevent @TraceID, 13, 3, @on

exec sp_trace_setevent @TraceID, 13, 11, @on

exec sp_trace_setevent @TraceID, 13, 35, @on

 

exec sp_trace_setevent @TraceID, 13, 8, @on
 

 

 

-- Set the Filters

declare @intfilter int

declare @bigintfilter bigint

 

exec sp_trace_setfilter @TraceID, 10, 0, 7, N''SQL Server Profiler%''

exec sp_trace_setfilter @TraceID, 1, 0, 7, N''exec sp_reset_connection''

 

set @bigintfilter = 2000000 -- 5 seconds

exec sp_trace_setfilter @TraceID, 13, 0, 4, @bigintfilter

 

 

-- Set the trace status to start

exec sp_trace_setstatus @TraceID, 1

 

-- display trace id for future references

select TraceID=@TraceID

goto finish

 

error:

select ErrorCode=@rc

 

finish:

go

 

 

',

            @database_name=N'msdb',

            @flags=0

IF (@@ERROR <> 0 OR @ReturnCode <> 0) GOTO QuitWithRollback

/****** Object: Step [delete old files]    Script Date: 02/10/2011 16:29:24 ******/

EXEC @ReturnCode = msdb.dbo.sp_add_jobstep @job_id=@jobId, @step_name=N'delete old files',

            @step_id=2,

            @cmdexec_success_code=0,

            @on_success_action=1,

            @on_success_step_id=0,

            @on_fail_action=2,

            @on_fail_step_id=0,

            @retry_attempts=0,

            @retry_interval=0,

            @os_run_priority=0, @subsystem=N'ActiveScripting',

            @command=N'

''''remove old files.

 

Dim FSO, deleteafter, flocation

 

flocation = "L:\Profiler_Logs"

 

deleteafter = 12 '' hours

 

Set FSO = CreateObject("Scripting.FileSystemObject")

 

Set dir = FSO.getFolder(flocation)

 

 

For Each file In dir.files

''check to see if it''s a trace file older than deleteafter amount of hours.

      If InStr(file.name, "current_trace_file_") And DateDiff("h", file.datecreated, Now()) > deleteafter Then

                  file.delete

            ''End If

      End if

next

 

set fso = nothing

set dir = nothing

',

            @database_name=N'VBScript',

            @flags=0

IF (@@ERROR <> 0 OR @ReturnCode <> 0) GOTO QuitWithRollback

EXEC @ReturnCode = msdb.dbo.sp_update_job @job_id = @jobId, @start_step_id = 1

IF (@@ERROR <> 0 OR @ReturnCode <> 0) GOTO QuitWithRollback

EXEC @ReturnCode = msdb.dbo.sp_add_jobschedule @job_id=@jobId, @name=N'hourly trace schedule',

            @enabled=1,

            @freq_type=4,

            @freq_interval=1,

            @freq_subday_type=8,

            @freq_subday_interval=1,

            @freq_relative_interval=0,

            @freq_recurrence_factor=0,

            @active_start_date=20110210,

            @active_end_date=99991231,

            @active_start_time=160000,

            @active_end_time=155959,

            @schedule_uid=N'80eaf0e4-74ba-45fb-8bbb-2d9a7afa3655'

IF (@@ERROR <> 0 OR @ReturnCode <> 0) GOTO QuitWithRollback

EXEC @ReturnCode = msdb.dbo.sp_add_jobserver @job_id = @jobId, @server_name = N'(local)'

IF (@@ERROR <> 0 OR @ReturnCode <> 0) GOTO QuitWithRollback

COMMIT TRANSACTION

GOTO EndSave

QuitWithRollback:

    IF (@@TRANCOUNT > 0) ROLLBACK TRANSACTION

EndSave:

 

GO

 

 

 

 
 
The job creates a file in the directory specified every hour. You'll need to modify the directory location in each of the scripts to point at a location of your desire.

 
 
My primary production system currently averages 30k transactions a minute. 
Poorly selected transaction isolation levels could cause transactions to take an excessive amount of time. These logs provide me with information which enables me to identify the offenders. This is one weapon in an arsenal for attacking DB performance issues.
 
Procedure to get the data
 
/* created by Don Rickman 2/17/2011
This proc is limited to a specific hour.
Attempting to set a end date time greater than the start hour will supply results for the given hour only.
*/


create
procedure find_hourly_trace_offenders

@start_date_time datetime

, @end_date_time datetime = null

, @duration_threshold_seconds int = 30

as

begin

           

      declare @file_name varchar(256)    

      declare @start_time varchar(12)

      set @start_time = substring(replace(replace(replace(convert(varchar(32), @start_date_time, 120), '-', ''), ':', ''), ' ', ''), 1,10)

      set @file_name = 'L:\Profiler_Logs\current_trace_file_' + @start_time + '00.trc'

     

      if isdate(@end_date_time) = 0 set @end_date_time = dateadd(minute, 10, @start_date_time)

 

      SELECT

 SPID, StartTime, EndTime, TextData, Reads, Writes, CPU, Duration, Hostname, DatabaseID, DatabaseName,  ObjectName, LoginName, NTUserName, ApplicationName, ServerName, EventClass

      FROM ::fn_trace_gettable(@file_name, default)

      where duration is not null

      and duration > (@duration_threshold_seconds*1000)*1000

      and StartTime between @start_date_time and @end_date_time

end

 

GO



Example Usage:
Find Long Running Queries exec find_hourly_trace_offenders

      @start_date_time = '2011-02-17 09:10:00.000'

      , @duration_threshold_seconds = 30

 
 
 
We've created a lightweight trace which captures information that can be used for debugging and troubleshooting. Have fun with it.
 
One great thing about querying the trace file: You can do it real time, while the file is still being used for an active trace.