PASS is trying to find better ways to reach out to SQL Bloggers. They’re going to experiment with taking advantage of the new subgroup features offered by LinkedIn. Membership to the subgroup will come fromthose currently listed in the PASS blog directory. If you’re looking to get into a tighter, more direct, communication with the PASS organization, be sure you’ve got a LinkedIn account and that you get your blog listed on the PASS web site (requirements are pretty simple, blog regularly about SQL Server topics).
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.
UPDATE: This post is incorrect. Adam nailed it in the comments. I explain my mistake here.
A question came up over at SQL Server Central where someone was wondering if it was possible to know when a given statement within a batch started. Immediately I thought, oh yeah, that’s easy, use the sys.dm_exec_requests dynamic management view (DMV). Done.
Wrong. The original poster pointed out that I had assumed that the values present in the DMV represented statement level values, but they show the batch. While the DMV shows a start_time, that time is the start of the current batch, not the statement within the batch. Now the question was, where else might I get this data? I next tried sys.dm_exec_sessions because it has the last_request_start_time value. Sure enough this worked.
Don’t believe me? This time I tested it. First, I set up a batch that ran a few longish queries:
BACKUP DATABASE AdventureWorks TO DISK = 'c:\bu\ad.bak' WITH INIT; DBCC CHECKALLOC(AdventureWorks); DBCC CHECKDB(AdventureWorks); DBCC CHECKCATALOG(AdventureWorks); BACKUP DATABASE AdventureWorks TO DISK = 'c:\bu\ad.bak' WITH INIT;
Then I wrote a little loop that would insert data from both DMV’s, once every second for a minute:
SET NOCOUNT ON; TRUNCATE TABLE dbo.dmR; TRUNCATE TABLE dbo.dmS; DECLARE @CheckTime DATETIME = DATEADD(ss,60,GETDATE()) ,@CurrTime DATETIME = GETDATE(); WHILE @CurrTime < @CheckTime BEGIN INSERT INTO ... SELECT ... FROM sys.dm_exec_sessions INSERT INTO ... SELECT ... FROM sys.dm_exec_requests WAITFOR DELAY '00:00:01'; SET @CurrTime = GETDATE(); END
Then it was a question of hitting the go button. The results are pretty clear. If you look at sys.dm_exec_requests data, you’ll see the start_time doesn’t change, but, the work being performed, visible in the command and plan_handle columns changes. You can also see the statement_start_offset and statement_end_offset changing. These values will allow you to pull data in combination with the sys.dm_exec_sql_text() dynamic management function.
start_time command statement_start_offset statement_end_offset plan_handle 2009-07-28 10:42:09.447 BACKUP DATABASE 0 138 0x060001007D931719B8C0BF0D000000000000000000000000 2009-07-28 10:42:09.447 DBCC 140 206 0x060001007D931719B8C0BF0D000000000000000000000000 2009-07-28 10:42:09.447 DBCC 140 206 0x06000F00AF16F10FB8C04D0D000000000000000000000000 2009-07-28 10:42:09.447 DBCC 208 268 0x060001007D931719B8C0BF0D000000000000000000000000
But, as you can see, the start_time stays the same. Looking at the last_request_start_time and last_request_end_time in the sys.dm_exec_sessions DMV, you can see these values changing in conjunction with the changing values in sys.dm_exec_requests.
last_request_start_time last_request_end_time 2009-07-28 10:35:21.500 2009-07-28 10:35:51.170 2009-07-28 10:42:09.447 2009-07-28 10:35:51.170
I’ll leave at as an excercise for the reader (or for another post for myself) to put together the DMV’s and DMF’s that would allow you to combine this data and show exactly which statement was being executed at which moment. The point, it is possible to determine exactly which statement is currently being executed within a batch process, and when that statement started.
Steve Jones, through a series of comments, emails, blackmail, back-alley deals & tons of whining, agreed to let me review a brief case, the Maxpedition Hard Use Gear Aggressor Attache. The review is up over at SQL Server Central and a video I made of the bag should be up shortly.
I love Maxpedition products, even if the names (Agressor, come on) can be a bit off-putting. The products are very well designed and extremely well built. They’re worth your time & money.
Do you know how to start a conversation or how to join one? I usually wait for a pause and then blurt out whatever point I thought was missed, missing, or insufficiently covered. In other words, don’t come to me for advice. The fact of the matter is, while the legend of misanthropic, barely washed, hardly lucid, but frighteningly competent IT personnel is alive and strong, in reality, we need to speak to each other, our peers, and worse yet, the business people. Developing social skills is a must. Further, with the economy being what it is (and looks to be for some time to come) you probably need to put those social skills to work building up a network, people you can help and, hopefully never needed, can help you.
If you can’t get that kind of information from the Scary DBA (although why suggesting beating someone with a stout stick until they give up the full set of requirements is a bad plan doesn’t make much sense to me), then where should you go?
I am so glad you asked that question (yes, you asked it, or should I get the bigger stick). At the PASS Summit this year (and you’re going right?) a special pre-conference meeting will be taking place. Andy Warren is responsible for putting it together. He’s been working on his own communication & networking skills and blogging about them regularly. They guy he’s been working with, Don Gabor, will be hosting a special two-hour session, right before the opening night party, on improving your communication skills, specifically around conversations, starting them, working the room, etc. He says he can teach you to remember names, a particular weakness of mine. I usually just refer to people as “that admin guy”, “that developer, you know, the one with the weak SQL skills” or “the business guy who won’t give us all the requirements.” Actually I remember his name, it’s Pell. But I digress.
I’m pretty excited to be taking part in this session. If you’re attending the conference, which we’ve already established that you’re going to, you might want to try this session out too. It sure can’t hurt (unless you get teamed up with me) and it will probably help.
Do you want to get a glimpse into how the Microsoft Field Engineers would go about troubleshooting performance issues on your server? Then go and read this blog entry by Denzil Ribeiro. Not only is this an excellent how-to on troubleshooting performance problems, but Mr. Ribeiro provides multiple links that describe the concepts he’s dealing with further, making it a great piece of documentation.
The MS Field Engineer blog is not terribly active, but what gets posted there is worth reading. If you don’t have it on your feed list, you should.
Recently I’ve been seeing a lot of people with bad execution plans, desperately trying to tune them, but they were unable to explain why they had such bad plans. More often than no these were larger queries, with a number of derived tables, CTE’s, CROSS APPLY, etc. In most cases the statistics appeared to be fine (this is usually checked by comparing estimated & actual rows within the operations in the execution plan) and the plans themselves didn’t look crazy, but the execution plans were flat out, not good.
If you’re looking at a plan and it doesn’t make much sense, one option that most people don’t check… SQL Server didn’t have enough time to complete optimization. The optimizer is a pretty amazing bit of code. The scary volume of work it does in frightenly short periods of time is quite awesome. However, it doesn’t always get done. To quickly check this situation you need to determine the “Reason For Early Termination Of Statement Optimization.” In the graphical execution plans this is found by going to the final operator in the plan, usually an INSERT, UPDATE, DELETE, or SELECT operator. Most people know to hover the mouse over the operator & get interesting little facts, but most people forget about checking the properties. Right click on this, or any other operator, and select Properties from the context menu. This will open the properties window, which looks something like this:
Right near the bottom you can see that this execution plan is showing an early termination reason of “Time Out.” That means that the optimizer didn’t finish optimizing. When the optimizer is running, it tries a whole series of different joins, join order, filters, what have you, all through some mathematic process that I’m not even remotely qualified to describe. But if it runs out of time, it goes with the last one it had. The last one it had might be the worst possible plan for this query, but because it hit a time out…
You can also find this right in the XML for the execution plan. In the Batch/Statements/StmtSimple property find the @StatementOptmEarlyAbortReason. It will show the same thing, “Time Out,” when the optimizer has run out of time.
You can get other early abort reasons, but the best one is “GoodEnoughPlanFound.” That means that the optimizer was able to complete it’s job. That doesn’t mean you have a good plan, but it means that you don’t have some interim pile of junk that is doing you more harm than good.
What can you do to fix this? Write simpler queries.
OK. Maybe that’s not helpful. Try to simplify the query. You may not be able to. If not, you might try rearranging the query, changing the join order. Yes, as everyone says, join order doesn’t matter, but the full statement is “Join order doesn’t normally matter.” Sometimes it can make a real difference. You may also have to supply some query hints, join hints, etc., to try to nudge the optimizer along.
The Twitter account is back, but I don’t have an explanation for why I was shut down or why I was re-enabled. Nothing to see here. Move along.
My Twitter account was suspended for some reason. I turned to waste three minutes of time and found that I was cut off. This is a bit of a shock.
And thus were the Berserkers born.
Or, for the more film-oriented, Skynet becomes self-aware.
It’s been one of those days. A bit of humor and a nice dose of SF are good for the soul.