No really. When did this statement start?

July 31, 2009 at 8:07 am (SQL Server 2005, SQL Server 2008, SQLServerPedia Syndication) (, , , , , )


I thought I had an interesting answer to the question. Unfortunately Adam Machanic, who has been working in this specific area quite a bit longer than I have, and, let’s face it, is a bit smarter, pointed out (in the comments) the possibility that I didn’t have this quite right.

I ran all his tests and sure enough, it wasn’t working the same way that I saw it work. First, I tried modifying his query so that it ran the SELECT statements from the DMV’s between the operations, but this didn’t change the results, start_time and last_request_start_time were the same. From a scientific stand-point, if no one can replicate your results, the experiment failed.

So I went back and tried again. To be sure I got things right and wasn’t, somehow, querying the wrong server or looking at the wrong spid, I added a couple of checks, specifically I queried the spid I was working with from my first query: SELECT @@SPID.

Unlike Adam’s tests, I continued running mine with two connections. I wanted to see multiple entries while the test was running. The results from sys.dm_exec_requests showed what I had seen before. There were 25 rows,  All of them showing the exact same start_time. The command, sql_handle, wait_time, cpu_time and all the other values that you would have expected to change, did. Elapsed time and logical_reads for example show a steadily increasing value, as you would expect.

Turning to sys.dm_exec_sessions, it showed more data, 40 rows instead of 25, just because it continued to record a session for the whole time I was querying the view since the spid wasn’t dropped. I finally saw the problem. It was the way I tested. I started the query against the DMV’s before I started the query that was generating the load. Because of this, the initial queries against the sys.dm_exec_sessions showed a different start & end time, unrelated to the test. Then the test ran and a second set of values were generated when the test completed. What I had attributed to the time it took for individual statements to complete and then be registered was not. It was just the different batches finishing, not the statements.

Nuts. 100% wrong. That’ll make Tim Ford happy though.

Unfortunately I’m back to where I was. Is there a way to tell when a statement started? I don’t know of a dynamic method for doing so. Obviously you could run a trace to get the statement start event, but you’ll be collecting a lot of data depending on how you set up that trace, so it wouldn’t be a good approach for everyday troubleshooting. I’ll keep looking.

13 Comments

  1. Aaron Bertrand said,

    Well if you are going to be dumping all of the data into a table every 10 seconds or every minute, you can certainly tell when the active *statement* (parsing sys.dm_exec_sql_text.text each time) has changed. This will only be accurate to your polling interval, but for long-running batches this may be good enough.

  2. scarydba said,

    Yeah, that’s a possibility. Thanks. But the answer I thought I had was to the question, “I’ve got a batch that’s running long, and it’s on a particular statement, how do I tell when that statement started”. Without something, what you suggest, profiler, you can’t, as near as I can tell.

  3. Adam Machanic said,

    I appreciate the vote of confidence! :-)

    I’m breathing a huge sigh of relief. And that said, file a Connect bug and let us know what it is. It would definitely be nice if such a thing DID exist.

  4. When did this statement start? « Home of the Scary DBA said,

    […] of the Scary DBA Intimidating databases and developers « Attache/Brief Case Review No really. When did this statement start? […]

  5. Hugo Shebbeare said,

    Thank you for the great post – self deprecation is very good when trying to lead the community, and you do that rather well :)

  6. scarydba said,

    Thanks. I didn’t really mean it to be too deprecating, but, flat out, I was wrong. That information needed to be communicated lest the bad info gain a life of it’s own.

  7. John Vanda said,

    The dm_exec_requests DMV contains the column transaction_id. I was able to join that DMV to sys.dm_tran_active_transaction, which has a [transaction_begin_time] column. This column might be storing the time entry you’re looking for. I’m not sure. I just saw your blog post and got curious and started messing around a bit.

  8. scarydba said,

    Hmmm… I’ll have to look into it. I suspect though that the transaction start time will be the same as the batch start time. Still, another avenue of inquiry. Thanks!

  9. John Vanda said,

    It’s definitely different. It’s just “not always there” (There were times when I ran the cross apply from dm_exec_sql_text to dm_exec_requests where the inner join to dm_tran_active_transactions returned nothing for the spid in question). I created an sproc to insert 1M records into a table, then do it again . While it was doing the initial insert, the transaction_start_time was higher than er.[start_time] by 10ms, and during the second insert, the transaction_start_time was higher (than the er.[start_time]) by about 34s. The er.[start_time] remained constant.

  10. scarydba said,

    I’m running my tests and gathering data from the dm_tran_active_transactions as you suggest. I’ll let you know how it goes.

  11. John Vanda said,

    Hopefully I’m not off-base. I just started working with the DMVs a few months ago, so I’m learning my way around a bit :-)

  12. scarydba said,

    From what I can see… I think it’s catching the statement start times for those statements that operate within a transaction, but not all statements. Hmmm… I’ll go ahead and move this to a blog post. It’s worth discussing a little more in public.

  13. scarydba said,

    Posted a follow-up here: https://scarydba.wordpress.com/2009/08/11/some-statement-start-times/

    Good catch on the transaction_id Mr. Vanda. You got full credit.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: