January 27, 2014 at 12:25 pm
I've created a server side trace, and i'm looking for things that are "slow"
Here's a simple snapshot of my data, where i'm getting "ElapsedSeconds" by date-diffing the start and end times;
I was kind of under the impression that CPU was the time spent on the query, but i'm seeing exceptions to any correlation, and just want a sanity check.
;WITH MyCTE([ElapsedSeconds],[EventClassDescrip],[EventSubClassDescrip],[(No column name)],[Duration],[StartTime],[EndTime],[Reads],[Writes],[CPU])
AS
(
SELECT '17','RPC:Completed',NULL,'exec dbo.spRep_ChartStatusSumm...','16848866','2014-01-10 16:26:01.510','2014-01-10 16:26:18.357','10580159','488','15562' UNION ALL
SELECT '12','SQL:BatchCompleted',NULL,'Insert into RuleActionBeforeAp...','12516601','2014-01-10 16:50:01.360','2014-01-10 16:50:13.877','285424','0','10000' UNION ALL
SELECT '11','RPC:Completed',NULL,'exec sp_executesql N''INSERT IN...','10796482','2014-01-13 08:03:05.497','2014-01-13 08:03:16.293','19','1','0' UNION ALL
SELECT '25','RPC:Completed',NULL,'exec sp_executesql N''UPDATE [d...','25427177','2014-01-13 10:37:18.257','2014-01-13 10:37:43.683','12','0','0' UNION ALL
SELECT '12','RPC:Completed',NULL,'exec sp_executesql N''INSERT IN...','11434032','2014-01-13 11:00:06.960','2014-01-13 11:00:18.393','157','4','0' UNION ALL
SELECT '11','RPC:Completed',NULL,'exec sp_executesql N''SELECT [t...','11192128','2014-01-13 12:01:19.450','2014-01-13 12:01:30.643','71','0','16' UNION ALL
SELECT '11','RPC:Completed',NULL,'exec sp_executesql N''SELECT [t...','11035540','2014-01-13 12:01:19.640','2014-01-13 12:01:30.677','4153','0','16' UNION ALL
SELECT '21','RPC:Completed',NULL,'exec sp_executesql N''UPDATE [d...','21079153','2014-01-13 12:08:25.303','2014-01-13 12:08:46.383','122','23','0' )
SELECT * FROM MyCTE;
so according to what i read, a duration is 1000 * CPU, and CPU is milliseconds.
My first row above of 15.532 would therefore be is 15.5 milliseconds, which roughly equals my 17 seconds datediff, but for many other rows, as seen above, have a CPU which is wildly lower(zero!) than the elapsed seconds i am calculating.
What other parameter am i missing here for finding "slow" queries from a trace?
if you are second guessing my calculation, for reference, this is what i was using:
INSERT INTO master.dbo.monitor_SlowTraces(...)
SELECT
DATEDIFF(SECOND, StartTime, EndTime) AS ElapsedSeconds,
*
FROM master.dbo.VW_Trace02
WHERE DATEDIFF(SECOND, StartTime, EndTime) > 10
ORDER BY
StartTime
Lowell
January 27, 2014 at 2:38 pm
I have been running some tests with profiler and set statistics time on and so far all of my Execution Times are reported as being the same as what profiler is reporting in CPU, but interesting enough it doesn't add the parse and compile time only the time it took to execute. The only times I came up with zero was when it took less than a ms, so not sure if that helps.
Update: Sorry read the question a little better, I had many cases where the execution took 0ms of CPU, but could take 100 ms for elapsed time. So just because the query took some amount of time > 1 ms doesn't mean that it would be reported in the CPU column. I would run those statement in SSMS with set statistics time on and compare the results with profiler.
January 27, 2014 at 2:48 pm
I'm not sure myself, which is why i was asking;
the examples i put out are what is wierd for me. If a query takes ten seconds, i'd kind of expect a reason, ie waiting for resources, larger cpu time due to complexity, massive number of rows, etc.
i do see that regardless of the CPU, the duration seems to still map roughly to the time in seconds / 1M, so i've got that going for me.
now i found this post that shows a bit more about what i'm encountering:
cpu of zero, it seems might be the query was cached, but duration
is useful in that it reports the entire query's "round-trip" execution time. This includes the total time from initial invocation, compilation & execution and also the that time taken by the application to consume any resultset (entirely). The obvious problem with this measurement is that it is subject to significant external factors such as network latency, application performance etc. It is also subject to the same blocking / waiting problems associated with the CPU measurement.
so the query is slow, not because of the query, but due to otehr factors.
THAT's what i can dig into better, now that i know.
Lowell
January 27, 2014 at 5:07 pm
Lowell,
I'm sure you already know this but there are times that CPU can be quite a lot more than elapsed time, specifically when SQL parallelizes a query. That doesn't seem to fit your circumstances but I just thought I'd throw it out there.
My thought question: Have you ever been told that your query runs too fast?
My advice:
INDEXing a poor-performing query is like putting sugar on cat food. Yeah, it probably tastes better but are you sure you want to eat it?
The path of least resistance can be a slippery slope. Take care that fixing your fixes of fixes doesn't snowball and end up costing you more than fixing the root cause would have in the first place.
Need to UNPIVOT? Why not CROSS APPLY VALUES instead?[/url]
Since random numbers are too important to be left to chance, let's generate some![/url]
Learn to understand recursive CTEs by example.[/url]
[url url=http://www.sqlservercentral.com/articles/St
January 28, 2014 at 12:32 am
CPU is the amount of time the query spends actually executing on the CPU(s). Duration is the elapsed time (or datediff start time and end time), this includes time the query spent waiting.
Gail Shaw
Microsoft Certified Master: SQL Server, MVP, M.Sc (Comp Sci)
SQL In The Wild: Discussions on DB performance with occasional diversions into recoverability
Viewing 5 posts - 1 through 4 (of 4 total)
You must be logged in to reply to this topic. Login to reply