extended events rpc_completed duration does not matching with rpc_starting

Question

Does rpc_completed duration (micro_sec) = rpc_starting.timestamp - rpc_completed.timestamp? In my case, I saw a big difference between them. Duration is only few millsec, where rpc_starting.timestamp - rpc_completed.timestamp is 6 - 10 sec.

I am on enterprise 2016 sp2-cu14, the duration field is in microsecond. I did similar thing for catching sp_statement_starting and sp_statement_completed, sp_batch_starting/sp_batch_completed inside rpc_starting and rpc_completed. it shows the same situation. My question is "which one tell me how much time the query actually took? Is it Duration in sp_statement_completed or the difference between starting and completed?"

Answer 1

I don't believe the duration column represents the difference in time of the timestamp_UTC column between the rpc_starting and rpc_completed events. Assuming you're on any version of SQL Server still relevant (2008 R2+) that column is in units of microseconds (anything older version and it's in milliseconds), and therefore is a very small value in your examples (e.g. 1,872 microseconds = 0.00187 seconds).

My guess based on Microsoft's description is that is literally how long it took that particular event to occur and be recorded.

Answer 2

My question is "which one tell me how much time the query actually took? Is it Duration in sp_statement_completed or the difference between starting and completed?"

"Duration" in the sp_statement_completed event is how long the query actually took at the server. It doesn't include the time spent sending results to the client (usually, see here for details).

I'm not 100% sure why the Extended Events timestamp column shows such a large discrepancy between the "starting" and "completed" events, but that's not where you want to focus your attention.