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.

Commands, Batches, and the Mysteries of Text (A Month of Activity Monitoring, Part 10 of 30)

This post is part 10 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.


Remember the saga of SPID 54? In case you’ve forgotten its sad tale, let’s revisit:

F1_02_Activity_Monitor

There it is. 54. Doing something, as usual. And of course, that something is not exactly apparent from the above sp_who2 output.

This is such a major defect that when I wrote Who is Active I decided to show query text by default even if it slightly slowed things down in some cases. This can be disabled—we’ll get to that in a later post—but I don’t think anyone does that very often.

To understand the differences between the options, consider the following batch:

SELECT *
FROM sys.tables

WAITFOR DELAY '10:10:10'

SELECT *
FROM sys.databases
GO

Running this batch on session 53, then running sp_WhoIsActive on another session, the following is output:

F10_01_default

The [sql_text] column, by default, outputs the text of the statement that is currently running. We can instead decide to see the entire batch, by setting @get_full_inner_text:

EXEC sp_WhoIsActive
    @get_full_inner_text = 1

F10_01_full_text

Why is this option called “get full inner text” rather than “get full batch?” It’s assumed that in most systems (hopefully) the majority of code running will be stored procedure calls rather than ad hoc batches. Let’s see what happens in that case:

USE tempdb
GO

CREATE PROC test_proc
AS
BEGIN
    SELECT *
    FROM sys.tables

    WAITFOR DELAY '10:10:10'

    SELECT *
    FROM sys.databases
END
GO

EXEC test_proc
GO

Running Who is Active with the default mode outputs pretty much the same exact thing as before:

F10_03_default

Setting the @get_full_inner_text option now returns the entire text of the stored procedure—or the “full inner text.”

F10_03_full_text

If you’re wondering what <?query means and why the results are returned in XML format, consider a nicely laid-out piece of code like the following:

SELECT
    *
FROM sys.databases
WHERE
    database_id IN
    (
        SELECT
            dbid
        FROM sys.sysprocesses
        WHERE
            loginame = 'Adam'
    )

If I were to query the various DMVs to get this text without formatting it as XML, the results would be rather ugly once I copied and pasted it out of the SSMS grid:

F10_04_bad_paste

XML in SQL Server Management Studio has the nice property of maintaining the formatting of text nodes. Clicking on the hyperlinked XML in the [sql_text] column, rather than attempting to copy and paste, has a much nicer result:

F10_04_xml

One other consideration is what happens when dealing with nested modules. Consider:

USE tempdb
GO

--Create two "inner" procs

CREATE PROC inner_test_proc1
AS
BEGIN
    WAITFOR DELAY '10:10:10'
END
GO

CREATE PROC inner_test_proc2
AS
BEGIN
    WAITFOR DELAY '20:20:20'
END
GO

--Create one "outer" proc to call the others

CREATE PROC outer_test_proc
    @x INT
AS
BEGIN
    IF @x = 1
        EXEC inner_test_proc1
    ELSE
        EXEC inner_test_proc2
END
GO

--Call the “outer” test proc
EXEC outer_test_proc 2
GO

If you run this batch, then run Who is Active, you’ll see output like the following:

F10_05_outer1

The [sql_text] column shows the WAITFOR command currently running. Its value is always scoped to the innermost scope—the currently running batch or module. But what if we want to get a bit more information about what call the application made to get us to this point? To get more information, use the @get_outer_command option:

EXEC sp_WhoIsActive
    @get_outer_command = 1

F10_05_outer2

This option introduces a new column called [sql_command], which reflects the outer batch or stored procedure call that was issued by the application or user. Like the [sql_text] column, it’s clickable XML, so that you can retrieve the original format of the batch.

Two other considerations for the [sql_text] column:

  • The SQL text in the plan cache will sometimes be locked. Who is Active will wait up to 5ms and then time out, setting the value of the [sql_text] column to “<timeout_exceeded />”
  • Certain system features, such as automatic statistics updates, may cause surprising results to be returned in the [sql_text] column. For example, rebuilding an index will result in text along the lines of “insert [dbo].[yourTable] select * from [dbo].[yourTable].” If you see something like this, do not be alarmed! Take a deep breath and use the @get_outer_command option to find out what’s really going on.

 

Homework

The sysprocesses [waittype] and [lastwaittype] columns are a bit confusing. One is a binary value that must be mapped, and the other is text-based. In almost all cases where the binary is not equal to 0x0000, the mapped text value of the [waittype] will be the same as the value in the [lastwaittype] column. These two columns can be different in only a handful of cases, where the worker (represented by the [lastwaittype] column) has a different wait than the task (represented by the [waittype] column). For more information on workers and tasks, see my post on the topic in a couple of days. And if you would like to see a situation where these two values are different, set up a program running locally to a target SQL Server instance that causes NETWORK_IO waits. The shared memory provider's implementation of this wait is one of the areas where the task and worker register different waits.

Today’s challenge: write a batch—or series of batches—that will make the [sql_text] column show the <timeout_exceeded /> value. Put your solution in the comments below.

Published Sunday, April 10, 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

 

Adam Machanic said:

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

April 12, 2011 9:41 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

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