Time spent in app, time spent in SQL Server

Application teams will sometimes believe they have a database issue when a recurring feed starts to perform poorly. Typically they will call on the DBA to perform a trace to identify the poorest performing SQL calls. When the trace is run and the analysis completed you may find that there are no obvious SQL issues. All the statements perform well. The performance problem may not necessarily reside on the database tier. It may reside on the application tier. It may be that the application tier is doing a large amount of number crunching or string processing between the recurring SQL calls. It may be the case that these routines have suddenly become the slow step in the feed.

Having performed the SQL trace it would be great if, in addition to the duration of the SQL calls, we could determine the elapsed time between SQL calls. One method for obtaining this figure is by subtracting the start time of an SQL call from the end time of the previous SQL call. If you export the trace data to a table and filter on, for example, the application name, SPID, hostname or proc name that is doing the load and order by start time you can use the LAG function to obtain the elapsed time between SQL calls.

In the following trace code the procedure that is performing the load is named myproc. The last two columns in the final result set show the total time spent doing SQL work and the total time spent in the application between the SQL calls.

WITH ctetracetimes AS
(
SELECT
starttime,
endtime,
LAG(endtime) OVER (ORDER BY starttime) AS previousendtime
FROM dbo.tracetbl
WHERE objectname = 'myproc'
),
cteappandsqltimes AS
(
SELECT
starttime,
endtime,
previousendtime,
DATEDIFF(millisecond,starttime,endtime) AS timespentsql,
DATEDIFF(millisecond,previousendtime,starttime) AS timespentapp
FROM ctetracetimes
)
SELECT *,
SUM(timespentsql) OVER() AS sumtimespentsql,
SUM(timespentapp) OVER() AS sumtimespentapp
FROM cteappandsqltimes
ORDER BY starttime

The results for repeated execution of the myproc stored procedure were as follows:

You can see that 50,000 milliseconds was spent doing the SQL related work (processing the stored procedure ten times) but over 150,000 milliseconds was spent in the application tier in between the SQL calls.

This type of analysis may be quite enlightening even for what you consider to be your well performing feeds. You may be making the assumption that the vast majority of your feed time is associated with database processing when, in fact, it is associated with application processing time. For example, one of my own feeds had a total elapsed time of twenty minutes. When the above analysis was performed the SQL time was only two minutes. Eighteen minutes was being spent in the application tier. A poorly performing number crunching routine was identified. It was then optimised to reduce the overall run-time of the feed.