What interval does SQL Server Profiler's "duration" refer to?

Question

I've been having strange things on a production server. Clients (all on the local LAN) are getting timeout errors on queries that should have no problem at all.

• it happens during times of low CPU usage (<1%)
• and when there is low hard drive I/O (<1%)

I spent an afternoon watching traces live in SQL Server Profiler, and the absolute epitome of the non-sense was the batch:

SELECT GETDATE() As ServerDate

Where profiler shows the numbers:

• CPU: 0
• Reads: 0
• Writes: 0
• Duration: 17,130 ms
• StartTime: 2017-02-28 15:00:20.777
• EndTime: 2017-02-28 15:00:37.907

What can possibly be going on in this database engine that perfectly benign queries take too long?

• anti-virus software?
• a VMWare hypervisor that doesn't schedule the virtual machine for 17 seconds?
• a kernel model stall for 17 seconds that doesn't show up in Task Manager?

Because even if the server were busy, a query that takes:

• zero cpu
• zero reads
• zero writes
• and has no side effect on any pages in memory

should not take 17 seconds to complete.

Duration

The only way forward is to try to figure out what duration means.

What does duration mean? Is it:

• Start: after entire batch has been received by the database engine
• End: after the query is complete

or is it:

• Start: after entire batch has been received by the database engine
• End: after the last byte has been sent to the client

or is it:

• Start: after entire batch has been received by the database engine
• End: after the last byte has been received by the client

(but then how does SQL Server know when the last byte has been "received" by the client).

Because given that:

• there's nothing wrong on the server
• there's nothing wrong on the database
• there's nothing wrong on the client

there must be something wrong in between. So I need to know exactly what conceptual events SQL Server uses to denote the start and end.

Locks

• Duration from SQL Server 2005 traces is stored (i.e. when you save the trace to a table or file) in microseconds (one-millionth of a second)
• Duration in Profiler is presented (i.e. on screen and in a screenshot) in milliseconds (one-thousandth of a second)

Of course, milliseconds vs microseconds was not my question.

Given that the only lock that getdate() takes is:

• Acquire: S (shared) lock on D (database)
• Release: S (shared) lock on D (database)

If the issues were due to locking:

• can anyone suggest why acquiring a shared lock on a database might take 17 seconds
• and if it were due to a 17 second delay acquiring a shared database lock
• why other batches can continue to acquire/release shared database locks without a stall?
• and if the stall was due to taking 17 seconds to acquire a lock
• what I can do about it?

That also wasn't my question. My question is tautological.

Tautology

My question as written is pretty simple:

What does duration mean?

Of course that's trivial to answer:

duration is EndTime - StartTime.

Which means I'm actually asking (without being pedantic):

• during what stage of query execution is StartTime timestamp recorded?
• during what stage of query execution is EndTime timestamp recorded?

If I can get an answer to that, my question next will be to find all events that go in between.

Bonus Chatter

It might be helpful to see a timeline of all events during select getdate():

1. Acquire Shared Database lock
2. Release Shared Database lock
3. SP:CacheMiss
4. SQL:BatchStarting
5. SQL:StmtStarting
6. SQL:StmtCompleted
7. SQL:BatchCompleted

Of course, this is just one, non-repeatable, random, example of queries that take an inordinate amount of time to run.

Bonus Reading

• SQL Server insert randomly takes 10+ seconds to complete? (closed by grumpy people)
• SQL Profiler CPU / duration units (it's 17,000 ms)
• View and Analyze Traces with SQL Server Profiler

Answer 1

Duration from SQL Server 2005 traces is stored in microseconds (one-millionth of a second) while Duration from SQL Server 2000 is stored in milliseconds (one-thousandth of a second). CPU is always stored in milliseconds.

The typical cause for long durations with no work is blocking: someone else has a lock on a row.

To find out why queries are waiting, skip Profiler and head to Adam Machanic's sp_WhoIsActive. It shows you what queries are running right now, and the wait_info column tells you what they're waiting on (and for how long). If you see LCK*, then it's blocking.