No really. When did this statement start?

Home / SQL Server 2005 / No really. When did this statement start?

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

  • 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.

  • scarydba

    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.

  • 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.

  • Hugo Shebbeare

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

  • scarydba

    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.

  • John Vanda

    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.

  • scarydba

    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!

  • John Vanda

    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.

  • scarydba

    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.

  • John Vanda

    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 🙂

  • scarydba

    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.

OK, fine, but what do you think?