One of the common goto methods for query specific slowness which can be replicated via an application can be to start up a trace or extended events session whilst replicating the issue, we all know about the dangers of running these sessions without sufficient filtering so ensuring that correct filtering is applied and sessions are monitored whilst running for short periods of time can really help identify exactly what the app is doing during replication of the issue.

But what exactly is a slow running query? over 1 second? over 2 seconds? well it all depends, In the past I have had to dig into trace files provided to me that were ran for the duration of a user replicating slowness within an application, one mistake I used to make was looking straight for the high duration queries. I would load the trace file and straight away add a filter on the duration column for something trivial such as greater than 50ms, bad idea! if I was lucky I may have found the slow running culprit/s but more often I found the issue to be somewhat hidden at first glance.

Its always worth checking for repeated calls, what if there is a stored procedure that runs for 50ms but is called over and over again with the only change being the parameter value passed, 100 calls to that proc soon becomes 5 seconds! and that’s not taking into account what I call round trip (please don’t beat me up over the terminology 🙂 ) what I call round trip is the time it takes from completion of a call to SQL to the beginning of the next call, lets say for arguments sake that it takes 10ms per call to call the next one.

Query: 50ms x 100 calls = 5000ms

Round trip: 10ms x 100 calls = 1000ms

That’s another second! we are now looking at a total of 6 seconds, the above is just an example of how it works you could of course focus some effort on making the proc faster but 50ms is already quick! I would imagine that in this case you may want to focus you efforts on why the proc is being called 100 times in the first place as you may find that you are on the wrong end of an object oriented dev with limited SQL knowledge who just loves to loop!

I know I joke but I have seen this approach and its not pretty, especially when the procedure is so simple and it could have been called just once without the parameter and then the results dealt with inside of the app.

So back to the topic of the round trip below is an example of some really janky code I wrote in powershell It will connect to my SQL instance and perform a bunch of calls to a stored procedure but I have made the powershell script force a small wait in between calls, I will then demonstrate what this looks like in profiler and furthermore how you can query the results to identify issues with roundtrip.

I know I could have included the save to table option in the trace definition in the first place but I just wanted to demonstrate that it can be done after too.

With all my trace data stored inside a table in SQL I am now able to do some better analysis, for this demo its easy to see in the trace but when you have a trace file that has lots of different calls it can be difficult to see.

As you can see the total duration in this example was 3.9 seconds with almost 50% of the time waiting on the client, of course these sorts of numbers could be completely normal for you so its up to you to determine what can be deemed as slow.

Here are the queries I used:

--Shoe raw data including Roundtrip per call and Duration per call
SELECT [RowNumber]
,[TextData]
,[StartTime]
,[EndTime]
,DATEDIFF(Millisecond,LAG(EndTime,1,StartTime) OVER (ORDER BY [RowNumber] ASC),StartTime) AS Roundtrip
,[Duration] / 1000 AS QueryDuration
--,[NTUserName]
--,[LoginName]
FROM [dbo].[RoundTripDemo]
WHERE TextData IS NOT NULL --Using to filter my trace start and finish rows
SELECT
SUM(RoundTrip) AS RoundTrip,
SUM(Duration) AS QueryDuration,
SUM(RoundTrip)+SUM(Duration) AS TotalDuration
FROM
(
SELECT
RowNumber,
Duration/1000 AS Duration,
StartTime,
EndTime,
DATEDIFF(Millisecond,LAG(EndTime,1,StartTime) OVER (ORDER BY RowNumber ASC),StartTime) AS RoundTrip
FROM [dbo].[RoundTripDemo]
WHERE TextData IS NOT NULL --Using to filter my trace start and finish rows
) as Roundtripdata

Of course with all this in mind please do not just assume that the round trip could be the app, it could also be network related slowness or perhaps you have a middle tier setup that relays out to the client and vise versa this would add more complexity to you investigations however the purpose of this exercise is purely to identify if there is an issue outside of the queries themselves.

David Fowler

David is a DBA with over 14 years production experience of SQL Server, from version 6.5 through to 2016. He has worked in a number of different settings and is currently the technical lead at one of the largest software companies in the UK.

Adrian Buckman

After working in the motor trade for over 11 years Adrian decided to give it all up to persue a dream of working in I.T. Adrian has over 4 years of experience working with SQL server and loves all things SQL, Adrian currently works as a Database Administrator for one of the UK’s Largest Software Companies