Benchmarking SQL Server operations

Sometimes you’re stuck trying to optimize a large stored procedure and the first step in optimizations is to figure out where the time is being spent. It’s not always where you expect, and going at it haphazardly doesn’t cut it.

The answer is of course benchmarking (timing), to figure out where the time is spent, and to figure out if your “fix” improved performance or not.

First of all, declare the variables you’ll need. Do this at the top of the the procedure/script that you’re benchmarking;

declare
  @totalTime datetime=GetDate(),
  @partTime datetime=GetDate()

Then drop in scripts like these throughout the code you’re benchmarking;

print ' Timing: [insert_descroption_here]'
print ' * Total time='+convert(varchar(10), datediff(ms, @totalTime,GetDate()))
print ' * Last Part='+convert(varchar(10), datediff(ms, @partTime,GetDate()))
set @partTime=GetDate()

Once you’ve found a block that takes an inordinate amount of time, either try to figure out how to optimize it, or insert more benchmarking points to pinpoint the actual culprit.

Here’s an example;

declare
  @totalTime datetime=GetDate(),
  @partTime datetime=GetDate()

-- Simulates actual script
WAITFOR DELAY '00:00:00:50' -- 50ms delay

print ' Timing: [Initiated]'
print ' * Total time='+convert(varchar(10), datediff(ms, @totalTime,GetDate()))
print ' * Last Part='+convert(varchar(10), datediff(ms, @partTime,GetDate()))
set @partTime=GetDate()

-- Simulates actual script
WAITFOR DELAY '00:00:10:00' -- 10s delay

print ' Timing: [Collected base data]'
print ' * Total time='+convert(varchar(10), datediff(ms, @totalTime,GetDate()))
print ' * Last Part='+convert(varchar(10), datediff(ms, @partTime,GetDate()))
set @partTime=GetDate()

-- Simulates actual script
WAITFOR DELAY '00:00:00:50' -- 50ms delay

print ' Timing: [Compute sums]'
print ' * Total time='+convert(varchar(10), datediff(ms, @totalTime,GetDate()))
print ' * Last Part='+convert(varchar(10), datediff(ms, @partTime,GetDate()))
set @partTime=GetDate()

print 'Done!'

This script produces this output;

Timing: [Initiated]

* Total time=50

* Last Part=50

Timing: [Collected base data]

* Total time=10043

* Last Part=9993

Timing: [Compute sums]

* Total time=10096

* Last Part=53

Done!

As you’ll notice, it’s the part up to “Collected base data” that’s slow, so that’s where you should start either benchmarking further or actually optimizing!

About mfagerlund
Writes code in my sleep - and sometimes it even compiles!

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: