THE SQL Server Blog Spot on the Web

Welcome to SQLblog.com - The SQL Server blog spot on the web Sign in | |
in Search

Adam Machanic

Adam Machanic, Boston-based SQL Server developer, shares his experiences with programming, monitoring, and performance tuning SQL Server. And the occasional battle with the query optimizer.

Active Request, Sleeping Session (A Month of Activity Monitoring, Part 8 of 30)

This post is part 8 of a 30-part series about the Who is Active stored procedure. A new post will run each day during the month of April, 2011. After April all of these posts will be edited and combined into a single document to become the basis of the Who is Active documentation.


The life cycle of a connection can be represented by a few simple phases:

  • Connect
  • Query
  • Sleep
  • (Repeat query and sleep as needed)
  • Disconnect

Who is Active, being a real-time activity monitoring tool, is designed to help track activity in those middle phases. The procedure doesn’t capture statistics about connections, and similarly it can’t report (very well) on anything that has already disconnected.

Most of the time—assuming that your workload is relatively normal—the majority of the sessions that you'll see reported by Who is Active will be in the Query phase. But due to open transactions, queries in the Sleep phase may also sneak in. And in some extreme cases, you might even see a query in the Disconnect phase. More on that in a bit.

So why does this matter? It all boils down to a simple question: How should session-level data be represented? The legacy sysprocesses view more or less mashed everything together. The execution context DMVs, on the other hand, split things up so that data from the Query phase is found in a request-level view, and aggregate data updated as soon as the Sleep phase begins, in a session-level view. My choices were, therefore, as follows:

  • Mash everything together, like sysprocesses
  • Treat sleeping sessions and active requests differently
  • Create two columns for each metric: one for session-level data and another for request-level data

The first option was out before I even thought through the possibilities. As I mentioned in the first post in this series, I find the quality of data reported by sysprocesses to be, well, lacking.

The third option seemed interesting, but one of my goals with Who is Active was to keep things simple and easily digestible. Having a million columns kind of defeats that purpose.

So in the end, my only choice was the middle path: the data from sleeping sessions and active requests is both reported by Who is Active, but never at the same time for the same session. This is one of those things that’s best represented by an image:

F7_01_active_sleeping

The most important thing to look at in this example is the [status] column—so I’ve dragged it all the way over. If the status is “sleeping,” it means that all of the values reported by Who is Active for that session are session-level metrics. If the status is anything other than “sleeping” (most commonly “running,” “runnable,” or “suspended”), then the values reported are all request-level metrics.

In this case, starting from the left:

  • [dd hh:mm:ss.mss] for a sleeping session refers to the amount of time elapsed since login time. For a request it’s the amount of time the entire batch—not just the current statement—has been running.
  • [sql_text] for a sleeping session is the last batch run on behalf of the session. For a request it’s the currently-running statement (at least, by default).
  • [wait_info] is always NULL for a sleeping session.
  • [CPU] and [reads] are session-level metrics (aggregates across all requests processed since login) for sleeping sessions, and request-level metrics (relevant only as far as the current request) for active requests.

The same can be said for virtually every metric reported by Who is Active. When in doubt, check out the [status] column. If you find that Who is Active is returning a lot of sleeping sessions due to your workload, you might want to move the [status] column a bit to the left in the default output, so that it’s easier to quickly check. I don’t usually find that to be necessary, so it’s toward the middle in the current default settings.

There is one other state that a session can be in and still get reported by Who is Active: an almost-completed state. Who is Active collects data in two phases, and in newer builds I decided that if some activity is caught on the first pass, it should be reported even if the session has disconnected, or a new and different request started, by the second pass. The second phase generally begins only a few milliseconds after the first, but on active OLTP systems it’s common for most requests to not even take that long. The goal is to report as much data as possible. These almost-completed (or almost-disconnected) sessions look like this:

F7_02_disconnected

The status is “suspended,” because that’s what it was in the first collection phase—so it looks like a normal active request. The giveaway that something changed by the second phase? CPU, reads, and writes are all NULL. That means that a suitable matching row didn’t exist in either sys.dm_exec_requests or sys.dm_exec_sessions by the time the second phase kicked in—so the session must have either disconnected or started a new request. When this happens the [dd hh:mm:ss.mss] column reports the time elapsed since the session originally logged in. It’s the only interesting time metric I can get when this occurs.

As a final note: if you see a lot of sleeping sessions showing up in the default Who is Active view, you might want to ask some questions of your application developer colleagues. Why is the application beginning transactions and letting them sit around for long periods of time? This is generally not a great I idea, for a number of reasons that I hope are rather obvious to anyone reading this post.

 
 

Homework

Yesterday’s goal was to find the OS thread ID without using the legacy sysprocesses DMV. This is a nice challenge because it forces you to really dig in to some of the less common SQLOS views, and to play with the various addresses you can find therein. One solution for this problem is:

SELECT
    t.os_thread_id
FROM sys.dm_os_threads AS t
INNER JOIN sys.dm_os_workers AS w ON
    w.worker_address = t.worker_address
INNER JOIN sys.dm_os_tasks AS ta ON
    ta.task_address = w.task_address
WHERE
    ta.session_id = @@SPID

Today I’m going to ask you to share some information from your production instance, or instances, with your fellow readers and me. Run the following query, if you don’t mind, and paste the results into the comments below. These numbers will help me understand whether I should be tuning Who is Active for instances with larger/longer queries, or for instances with much shorter queries.

SELECT
    AVG(total_elapsed_time) AS avg_total,
    AVG(min_elapsed_time) AS avg_min,
    AVG(max_elapsed_time) AS avg_max,
    MIN(min_elapsed_time) AS min_min,
    MAX(max_elapsed_time) AS max_max,
    COUNT(*) AS total_stats
FROM sys.dm_exec_query_stats
FOR XML PATH('time')

 

Published Friday, April 08, 2011 11:00 AM by Adam Machanic

Comment Notification

If you would like to receive an email when updates are made to this post, please register here

Subscribe to this post's comments using RSS

Comments

 

Jeff York said:

<time>

 <avg_total>139586</avg_total>

 <avg_min>8166</avg_min>

 <avg_max>44772</avg_max>

 <min_min>0</min_min>

 <max_max>600004882</max_max>

 <total_stats>31387</total_stats>

</time>

April 8, 2011 11:34 AM
 

Chris said:

<time>

 <avg_total>1182174</avg_total>

 <avg_min>20863</avg_min>

 <avg_max>125767</avg_max>

 <min_min>0</min_min>

 <max_max>233555665</max_max>

 <total_stats>35622</total_stats>

</time>

April 8, 2011 11:49 AM
 

Srdjan said:

<time>

 <avg_total>165614</avg_total>

 <avg_min>4068</avg_min>

 <avg_max>11144</avg_max>

 <min_min>4</min_min>

 <max_max>36331573</max_max>

 <total_stats>11014</total_stats>

</time>

April 8, 2011 1:25 PM
 

Sankar Reddy said:

<time>

<avg_total>26534094</avg_total>

<avg_min>48282</avg_min>

<avg_max>379208</avg_max>

<min_min>0</min_min>

<max_max>601375977</max_max>

<total_stats>7134</total_stats>

</time>

<time>

 <avg_total>18814983</avg_total>

 <avg_min>584624</avg_min>

 <avg_max>754379</avg_max>

 <min_min>0</min_min>

 <max_max>941254883</max_max>

 <total_stats>13225</total_stats>

</time>

<time>

 <avg_total>382198</avg_total>

 <avg_min>1251</avg_min>

 <avg_max>34765</avg_max>

 <min_min>0</min_min>

 <max_max>150887696</max_max>

 <total_stats>4874</total_stats>

</time>

<time>

 <avg_total>13825</avg_total>

 <avg_min>768</avg_min>

 <avg_max>12190</avg_max>

 <min_min>0</min_min>

 <max_max>1944336</max_max>

 <total_stats>178</total_stats>

</time>

<time>

 <avg_total>129010</avg_total>

 <avg_min>1662</avg_min>

 <avg_max>87329</avg_max>

 <min_min>0</min_min>

 <max_max>2006836</max_max>

 <total_stats>47</total_stats>

</time>

<time>

 <avg_total>10340820</avg_total>

 <avg_min>0</avg_min>

 <avg_max>2015136</avg_max>

 <min_min>0</min_min>

 <max_max>2015625</max_max>

 <total_stats>2</total_stats>

</time>

<time>

 <avg_total>270290</avg_total>

 <avg_min>3954</avg_min>

 <avg_max>32815</avg_max>

 <min_min>0</min_min>

 <max_max>600723633</max_max>

 <total_stats>42793</total_stats>

</time>

April 8, 2011 2:29 PM
 

Chris said:

<time>

 <avg_total>862925</avg_total>

 <avg_min>2793</avg_min>

 <avg_max>32330</avg_max>

 <min_min>0</min_min>

 <max_max>197649414</max_max>

 <total_stats>9139</total_stats>

</time>

April 8, 2011 4:14 PM
 

Michael said:

Server was restarted yesterday so counts are low:

<time>

 <avg_total>2095945</avg_total>

 <avg_min>1176836</avg_min>

 <avg_max>1333943</avg_max>

 <min_min>0</min_min>

 <max_max>6471953125</max_max>

 <total_stats>15492</total_stats>

</time>

April 8, 2011 5:31 PM
 

namraja said:

<time>

 <avg_total>6869934</avg_total>

 <avg_min>528188</avg_min>

 <avg_max>1831242</avg_max>

 <min_min>3</min_min>

 <max_max>7025659629</max_max>

 <total_stats>12994</total_stats>

</time>

<time>

 <avg_total>5532677</avg_total>

 <avg_min>603139</avg_min>

 <avg_max>792353</avg_max>

 <min_min>0</min_min>

 <max_max>2568274349</max_max>

 <total_stats>57944</total_stats>

</time>

April 9, 2011 2:57 PM
 

George said:

<time>

<avg_total>227330</avg_total>

<avg_min>47312</avg_min>

<avg_max>82609</avg_max>

<min_min>0</min_min>

<max_max>600673829</max_max>

<total_stats>38655</total_stats>

</time>

April 9, 2011 9:44 PM
 

Alvaro said:

<time>

 <avg_total>1792570</avg_total>

 <avg_min>122323</avg_min>

 <avg_max>159202</avg_max>

 <min_min>1</min_min>

 <max_max>1639573662</max_max>

 <total_stats>99944</total_stats>

</time>

April 11, 2011 5:21 AM
 

Fabricio Lima said:

<time>

 <avg_total>9741620</avg_total>

 <avg_min>26870</avg_min>

 <avg_max>414240</avg_max>

 <min_min>1</min_min>

 <max_max>603658341</max_max>

 <total_stats>4663</total_stats>

</time>

April 11, 2011 1:00 PM
 

Calvin said:

<time>

 <avg_total>866008</avg_total>

 <avg_min>10895</avg_min>

 <avg_max>92887</avg_max>

 <min_min>0</min_min>

 <max_max>13201171</max_max>

 <total_stats>591</total_stats>

</time>

<time>

 <avg_total>2767665</avg_total>

 <avg_min>1625</avg_min>

 <avg_max>90274</avg_max>

 <min_min>0</min_min>

 <max_max>599994140</max_max>

 <total_stats>7261</total_stats>

</time>

<time>

 <avg_total>368355456</avg_total>

 <avg_min>2881</avg_min>

 <avg_max>19027</avg_max>

 <min_min>0</min_min>

 <max_max>1768554</max_max>

 <total_stats>161</total_stats>

</time>

April 12, 2011 10:33 AM
 

Clyde Jin said:

<time>

 <avg_total>3020341</avg_total>

 <avg_min>9720</avg_min>

 <avg_max>157467</avg_max>

 <min_min>0</min_min>

 <max_max>7486087179</max_max>

 <total_stats>85928</total_stats>

</time>

April 12, 2011 10:33 AM
 

Patrick said:

<time>

 <avg_total>259316330</avg_total>

 <avg_min>140868</avg_min>

 <avg_max>32967763</avg_max>

 <min_min>0</min_min>

 <max_max>1663169055000</max_max>

 <total_stats>51106</total_stats>

</time>

April 13, 2011 1:18 PM
 

Woodler said:

<time>

 <avg_total>19862</avg_total>

 <avg_min>550</avg_min>

 <avg_max>4759</avg_max>

 <min_min>0</min_min>

 <max_max>405600</max_max>

 <total_stats>12410</total_stats>

</time>

April 14, 2011 5:49 AM
 

Adam Machanic said:

Thanks, all, for taking the time to run the query and for pasting the XML back here.

April 15, 2011 10:47 AM
 

MyChoreBoy said:

<time>

 <avg_total>21367621</avg_total>

 <avg_min>393321</avg_min>

 <avg_max>642318</avg_max>

 <min_min>0</min_min>

 <max_max>721951171</max_max>

 <total_stats>6953</total_stats>

</time>

April 19, 2011 1:31 PM
 

John said:

Thanks for the blog and the tool Adam.  I'm a few days behind, but if you still want more results here is a sampling of mine...kind of all over the board.

<time>

 <avg_total>26474279</avg_total>

 <avg_min>19519832</avg_min>

 <avg_max>21040860</avg_max>

 <min_min>0</min_min>

 <max_max>7501082031</max_max>

 <total_stats>2385</total_stats>

</time>

<time>

 <avg_total>554602</avg_total>

 <avg_min>28025</avg_min>

 <avg_max>96354</avg_max>

 <min_min>0</min_min>

 <max_max>600015625</max_max>

 <total_stats>14287</total_stats>

</time>

<time>

 <avg_total>3372854</avg_total>

 <avg_min>173265</avg_min>

 <avg_max>323275</avg_max>

 <min_min>0</min_min>

 <max_max>1213653320</max_max>

 <total_stats>7463</total_stats>

</time>

<time>

 <avg_total>403215</avg_total>

 <avg_min>107058</avg_min>

 <avg_max>128744</avg_max>

 <min_min>0</min_min>

 <max_max>1377140767</max_max>

 <total_stats>49047</total_stats>

</time>

April 20, 2011 4:14 PM
 

David Howard said:

<time>

 <avg_total>345579</avg_total>

 <avg_min>227361</avg_min>

 <avg_max>258244</avg_max>

 <min_min>0</min_min>

 <max_max>14200316406</max_max>

 <total_stats>69141</total_stats>

</time>

April 21, 2011 2:46 PM
 

Barny said:

<time><avg_total>65137979</avg_total><avg_min>16790002</avg_min><avg_max>23919424</avg_max><min_min>1</min_min><max_max>16592161701</max_max><total_stats>3058</total_stats></time>

April 26, 2011 4:37 AM
 

Adam Machanic said:

This post is part 30 of a 30-part series about the Who is Active stored procedure. A new post will run

April 30, 2011 11:45 AM
 

John Stanley said:

<time>

 <avg_total>381860</avg_total>

 <avg_min>6260</avg_min>

 <avg_max>23816</avg_max>

 <min_min>4</min_min>

 <max_max>601124930</max_max>

 <total_stats>58682</total_stats>

</time>

May 17, 2011 9:40 AM
 

Anton said:

<time>

 <avg_total>161106</avg_total>

 <avg_min>16309</avg_min>

 <avg_max>43152</avg_max>

 <min_min>0</min_min>

 <max_max>5181641</max_max>

 <total_stats>1914</total_stats>

</time>

June 15, 2011 5:37 PM
 

reader said:

<time>

 <avg_total>2732887</avg_total>

 <avg_min>11434</avg_min>

 <avg_max>43464</avg_max>

 <min_min>4</min_min>

 <max_max>112866885</max_max>

 <total_stats>35243</total_stats>

</time>

August 5, 2011 1:49 PM
 

Adam W said:

<time>

 <avg_total>17119867</avg_total>

 <avg_min>8973</avg_min>

 <avg_max>321737</avg_max>

 <min_min>3</min_min>

 <max_max>600219818</max_max>

 <total_stats>28339</total_stats>

</time>

November 21, 2011 4:43 PM
 

Nadia said:

<time><avg_total>7129531</avg_total><avg_min>9106</avg_min><avg_max>138603</avg_max><min_min>0</min_min><max_max>603839844</max_max><total_stats>53615</total_stats></time>

February 15, 2012 12:49 PM
 

yazalpizar said:

Prod server:

<time>

 <avg_total>3688008</avg_total>

 <avg_min>19725</avg_min>

 <avg_max>141714</avg_max>

 <min_min>0</min_min>

 <max_max>2114197239</max_max>

 <total_stats>60209</total_stats>

</time>

Test server:

<time>

 <avg_total>1702154</avg_total>

 <avg_min>69230</avg_min>

 <avg_max>308920</avg_max>

 <min_min>0</min_min>

 <max_max>600035156</max_max>

 <total_stats>6462</total_stats>

</time>

March 15, 2013 5:52 AM
 

Tiago said:

Prod Server:

<time>

 <avg_total>5723106</avg_total>

 <avg_min>22759</avg_min>

 <avg_max>122039</avg_max>

 <min_min>2</min_min>

 <max_max>1074079088</max_max>

 <total_stats>31966</total_stats>

</time>

<time>

 <avg_total>3001623</avg_total>

 <avg_min>369102</avg_min>

 <avg_max>1064351</avg_max>

 <min_min>0</min_min>

 <max_max>1441361441</max_max>

 <total_stats>15980</total_stats>

</time>

<time>

 <avg_total>515299</avg_total>

 <avg_min>49183</avg_min>

 <avg_max>75345</avg_max>

 <min_min>2</min_min>

 <max_max>600012033</max_max>

 <total_stats>32961</total_stats>

</time>

April 24, 2013 7:25 AM

Leave a Comment

(required) 
(required) 
Submit

About Adam Machanic

Adam Machanic is a Boston-based SQL Server developer, writer, and speaker. He focuses on large-scale data warehouse performance and development, and is author of the award-winning SQL Server monitoring stored procedure, sp_WhoIsActive. Adam has written for numerous web sites and magazines, including SQLblog, Simple Talk, Search SQL Server, SQL Server Professional, CoDe, and VSJ. He has also contributed to several books on SQL Server, including "SQL Server 2008 Internals" (Microsoft Press, 2009) and "Expert SQL Server 2005 Development" (Apress, 2007). Adam regularly speaks at conferences and training events on a variety of SQL Server topics. He is a Microsoft Most Valuable Professional (MVP) for SQL Server, a Microsoft Certified IT Professional (MCITP), and an alumnus of the INETA North American Speakers Bureau.

This Blog

Syndication

Powered by Community Server (Commercial Edition), by Telligent Systems
  Privacy Statement