Search results matching tags 'SQL Server 2008', 'Extended Events', and 'SQL Server Denali'

Parsing the sqlserver.sql_text Action in Extended Events by Offsets

jmkehayias — Mon, 31 Jan 2011 02:05:43 GMT

A couple of weeks back I received an email from a member of the community who was reading the XEvent a Day blog series and had a couple of interesting questions about Extended Events. This person had created an Event Session that captured the sqlserver.sql_statement_completed and sqlserver.sql_statement_starting Events and wanted to know how to do a correlation between the related Events so that the offset information from the starting Event could be used to find the statement of the completed Event to know the specific statement and its reads, cpu and write information from the sqlserver.sql_statement_completed Event. Confused yet? Since it doesn’t really read well what the intent was, lets look at the columns that are output by both of these Events, and it will make more sense. I am going to break this post into two sections, SQL Server 2008 and SQL Server Denali, because there are significant differences between the two with regard to Extended Events and specifically these two events.

SQL Server 2008

In SQL Server 2008, the sqlserver.sql_statement_starting Event has the following output columns:

select name, column_id, type_name
from sys.dm_xe_object_columns
where object_name = 'sql_statement_starting'
  and column_type <> 'readonly'

The sqlserver.sql_statement_completed Event has the following output columns:

select name, column_id, type_name
from sys.dm_xe_object_columns
where object_name = 'sql_statement_completed'
  and column_type <> 'readonly'

The intent as I understood it was to use the offset and offset_end from the sqlserver.sql_statement_starting Event with the information in the sqlserver.sql_statement_completed Event and I could only assume the sqlserver.sql_text Action. When I got the email I replied back to use the sqlserver.tsql_stack Action to get the offset information with the sqlserver.sql_statement_completed Event and use that to parse the statement from the sqlserver.sql_text Action. I didn’t have time to play with it at the moment, but I promised to write a blog post showing how to do it later that day.

When I got a free minute where I could write a demo to blog about for this I ran into some problems with the results that I got from parsing the sql_text data that was returned by Extended Events. To show this, lets create an Event Session and run a test multi-statement batch so that we have to some sample Event Data to do processing on.

IF EXISTS (SELECT 1 FROM sys.dm_xe_sessions WHERE name = 'SQLStmtEvents')
    DROP EVENT SESSION SQLStmtEvents ON SERVER
GO
-- Create our Event Session for current Session_ID
DECLARE @SqlCmd NVARCHAR(MAX) = N'
CREATE EVENT SESSION SQLStmtEvents
ON SERVER
ADD EVENT sqlserver.sql_statement_completed
(    ACTION (sqlserver.sql_text, sqlserver.tsql_stack)
    WHERE (sqlserver.session_id = '+CAST(@@SPID AS NVARCHAR(4))+')    ),
ADD EVENT sqlserver.sql_statement_starting
(    ACTION (sqlserver.sql_text, sqlserver.tsql_stack)
    WHERE (sqlserver.session_id = '+CAST(@@SPID AS NVARCHAR(4))+')    )
ADD target package0.ring_buffer
WITH (MAX_DISPATCH_LATENCY=5SECONDS, TRACK_CAUSALITY=ON)';
EXEC(@SqlCmd);
GO
-- Start the Event Session
ALTER EVENT SESSION SQLStmtEvents
ON SERVER
STATE=START;
GO
-- Run a multi-statement Batch
SELECT * 
FROM sys.objects

SELECT * 
FROM master..spt_values
WHERE type = N'P'

SELECT *
FROM INFORMATION_SCHEMA.TABLES
GO

With the Event Session created I did quick check to validate that the offset information held in the tsql_stack matched the offset information returned by the sql_statement_starting Event. The tsql_stack returns an XML document that is similar to the following:

<frame level="1" handle="0x020000004765D81E643DBDA1E90A8F634B78C042FF805374" line="2" offsetStart="64" offsetEnd="124" />

After validating the offsets matched, I wrote out the parser for the Event Data and sql_text as follows:

-- Extract the Event information from the Event Session 
SELECT 
    event_name, 
    timestamp, 
    cpu, 
    duration, 
    reads, 
    writes, 
    state, 
    ISNULL(offset, tsql_stack.value('(frame/@offsetStart)[1]', 'int')) as offset,
    ISNULL(offset_end, tsql_stack.value('(frame/@offsetEnd)[1]', 'int')) as offset_end,
    ISNULL(nest_level, tsql_stack.value('(frame/@level)[1]', 'int')) as nest_level,
    SUBSTRING(sql_text,    
                (ISNULL(offset, tsql_stack.value('(frame/@offsetStart)[1]', 'int'))/2)+1, 
                ((CASE ISNULL(offset_end, tsql_stack.value('(frame/@offsetEnd)[1]', 'int')) 
                    WHEN -1 THEN DATALENGTH(sql_text) 
                    ELSE ISNULL(offset_end, tsql_stack.value('(frame/@offsetEnd)[1]', 'int')) 
                  END - ISNULL(offset, tsql_stack.value('(frame/@offsetStart)[1]', 'int')))/2) + 1) AS statement_text_Xevents,
    sql_text,
    event_sequence,
    activity_id
FROM
(
    SELECT 
        event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,
        DATEADD(hh, 
            DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), 
            event_data.value('(event/@timestamp)[1]', 'datetime2')) AS [timestamp],
        COALESCE(event_data.value('(event/data[@name="database_id"]/value)[1]', 'int'), 
            event_data.value('(event/action[@name="database_id"]/value)[1]', 'int')) AS database_id,
        event_data.value('(event/action[@name="session_id"]/value)[1]', 'int') AS [session_id],
        event_data.value('(event/data[@name="cpu"]/value)[1]', 'int') AS [cpu],
        event_data.value('(event/data[@name="duration"]/value)[1]', 'bigint') AS [duration],
        event_data.value('(event/data[@name="reads"]/value)[1]', 'bigint') AS [reads],
        event_data.value('(event/data[@name="writes"]/value)[1]', 'bigint') AS [writes],
        event_data.value('(event/data[@name="state"]/text)[1]', 'nvarchar(4000)') AS [state],
        event_data.value('(event/data[@name="offset"]/value)[1]', 'int') AS [offset],
        event_data.value('(event/data[@name="offset_end"]/value)[1]', 'int') AS [offset_end],
        event_data.value('(event/data[@name="nest_level"]/value)[1]', 'int') AS [nest_level],
        CAST(event_data.value('(event/action[@name="tsql_stack"]/value)[1]', 'nvarchar(4000)') AS XML) AS [tsql_stack],
        event_data.value('(event/action[@name="sql_text"]/value)[1]', 'nvarchar(max)') AS [sql_text],
        event_data.value('(event/data[@name="source_database_id"]/value)[1]', 'int') AS [source_database_id],
        event_data.value('(event/data[@name="object_id"]/value)[1]', 'int') AS [object_id],
        event_data.value('(event/data[@name="object_type"]/text)[1]', 'int') AS [object_type],
        CAST(SUBSTRING(event_data.value('(event/action[@name="attach_activity_id"]/value)[1]', 'varchar(50)'), 1, 36) AS uniqueidentifier) as activity_id,
        CAST(SUBSTRING(event_data.value('(event/action[@name="attach_activity_id"]/value)[1]', 'varchar(50)'), 38, 10) AS int) as event_sequence
    FROM 
    (   SELECT XEvent.query('.') AS event_data 
        FROM 
        (    -- Cast the target_data to XML 
            SELECT CAST(target_data AS XML) AS TargetData 
            FROM sys.dm_xe_session_targets st 
            JOIN sys.dm_xe_sessions s 
                ON s.address = st.event_session_address 
            WHERE name = 'SQLStmtEvents' 
              AND target_name = 'ring_buffer'
        ) AS Data 
        -- Split out the Event Nodes 
        CROSS APPLY TargetData.nodes ('RingBufferTarget/event') AS XEventData (XEvent)   
    ) AS tab (event_data)
) AS results

If you run these two examples, you will notice immediately that something is not right with the statement_text_XEvents data, it didn’t parse out correctly.

I also validated that this same behavior exists in SQL Server Denali CTP1. To look at this further and determine where exactly the problem might be, I used the plan_handle from the tsql_stack to get the sql text from sys.dm_exec_sql_text() and then offset parse that in the same manner to validate that the offset information is not the problem.

SELECT 
    event_name, 
    tsql_stack.value('(frame/@offsetStart)[1]', 'int') AS offset,
    tsql_stack.value('(frame/@offsetEnd)[1]', 'int') AS offset_end,
    tsql_stack.value('(frame/@level)[1]', 'int') AS nest_level,
    SUBSTRING(sql_text,    
                (tsql_stack.value('(frame/@offsetStart)[1]', 'int')/2)+1, 
                ((CASE tsql_stack.value('(frame/@offsetEnd)[1]', 'int')
                    WHEN -1 THEN DATALENGTH(sql_text) 
                    ELSE tsql_stack.value('(frame/@offsetEnd)[1]', 'int')
                  END - tsql_stack.value('(frame/@offsetStart)[1]', 'int'))/2) + 1) AS statement_text_Xevents,
    SUBSTRING(st.text, (tsql_stack.value('(/frame/@offsetStart)[1]', 'int')/2)+1, 
        ((CASE tsql_stack.value('(/frame/@offsetEnd)[1]', 'int')
          WHEN -1 THEN DATALENGTH(st.text)
         ELSE tsql_stack.value('(/frame/@offsetEnd)[1]', 'int')
         END - tsql_stack.value('(/frame/@offsetStart)[1]', 'int'))/2) + 1) AS statement_text_from_cache, 
         sql_text
FROM
(
    SELECT 
        event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,
        CAST(event_data.value('(event/action[@name="tsql_stack"]/value)[1]', 'nvarchar(4000)') AS XML) AS [tsql_stack],
        event_data.value('(event/action[@name="sql_text"]/value)[1]', 'nvarchar(max)') AS [sql_text]
    FROM 
    (   SELECT XEvent.query('.') AS event_data 
        FROM 
        (    -- Cast the target_data to XML 
            SELECT CAST(target_data AS XML) AS TargetData 
            FROM sys.dm_xe_session_targets st 
            JOIN sys.dm_xe_sessions s 
                ON s.address = st.event_session_address 
            WHERE name = 'SQLStmtEvents' 
              AND target_name = 'ring_buffer'
        ) AS Data 
        -- Split out the Event Nodes 
        CROSS APPLY TargetData.nodes ('RingBufferTarget/event') AS XEventData (XEvent)   
    ) AS tab (event_data)
) AS results
CROSS APPLY sys.dm_exec_sql_text(tsql_stack.value('xs:hexBinary(substring((/frame/@handle)[1], 3))', 'varbinary(max)')) AS st

The information from the cache is correct, so there has to be something different about the sql_text Action output. To figure out what that was, I changed my script slightly so that it would parse out each character in the text from cache and the sql_text Action to see what was different and where:

-- Extract the Event information from the Event Session 
SELECT 
    sv.number AS Position, 
    ASCII(SUBSTRING(text, sv.number+1, 1)) AS cache_text,
    ASCII(SUBSTRING(sql_text, sv.number+1, 1)) AS sql_text
FROM
(
    SELECT 
        CAST(event_data.value('(event/action[@name="tsql_stack"]/value)[1]', 'nvarchar(4000)') AS XML) AS [tsql_stack],
        event_data.value('(event/action[@name="sql_text"]/value)[1]', 'nvarchar(max)') AS [sql_text]
    FROM 
    (   -- Get only one of the events this time
        SELECT TOP 1 XEvent.query('.') AS event_data 
        FROM 
        (    -- Cast the target_data to XML 
            SELECT CAST(target_data AS XML) AS TargetData 
            FROM sys.dm_xe_session_targets st 
            JOIN sys.dm_xe_sessions s 
                ON s.address = st.event_session_address 
            WHERE name = 'SQLStmtEvents' 
              AND target_name = 'ring_buffer'
        ) AS Data 
        -- Split out the Event Nodes 
        CROSS APPLY TargetData.nodes ('RingBufferTarget/event') AS XEventData (XEvent)   
    ) AS tab (event_data)
) AS results
CROSS APPLY sys.dm_exec_sql_text(tsql_stack.value('xs:hexBinary(substring((/frame/@handle)[1], 3))', 'varbinary(max)')) AS st
CROSS JOIN master.dbo.spt_values AS sv
WHERE sv.type = 'P'
  AND sv.number <= DATALENGTH(text)

What I found was that the carriage returns are missing from the sql_text Action in Extended Events. We can work around that by doing a REPLACE(sql_text, CHAR(10), CHAR(13)+CHAR(10)) operation to return the carriage returns to the output.

-- Extract the Event information from the Event Session 
SELECT 
    event_name, 
    timestamp, 
    cpu, 
    duration, 
    reads, 
    writes, 
    state, 
    SUBSTRING(sql_text,    
                (tsql_stack.value('(frame/@offsetStart)[1]', 'int')/2)+1, 
                ((CASE tsql_stack.value('(frame/@offsetEnd)[1]', 'int')
                    WHEN -1 THEN DATALENGTH(sql_text) 
                    ELSE tsql_stack.value('(frame/@offsetEnd)[1]', 'int') 
                  END - tsql_stack.value('(frame/@offsetStart)[1]', 'int'))/2) + 1) AS statement_text_Xevents,
    SUBSTRING(st.text, (tsql_stack.value('(/frame/@offsetStart)[1]', 'int')/2)+1, 
        ((CASE tsql_stack.value('(/frame/@offsetEnd)[1]', 'int')
          WHEN -1 THEN DATALENGTH(st.text)
         ELSE tsql_stack.value('(/frame/@offsetEnd)[1]', 'int')
         END - tsql_stack.value('(/frame/@offsetStart)[1]', 'int'))/2) + 1) AS statement_text_from_cache,
    sql_text,    
    event_sequence,
    activity_id
FROM
(
    SELECT 
        event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,
        DATEADD(hh, 
            DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), 
            event_data.value('(event/@timestamp)[1]', 'datetime2')) AS [timestamp],
        COALESCE(event_data.value('(event/data[@name="database_id"]/value)[1]', 'int'), 
            event_data.value('(event/action[@name="database_id"]/value)[1]', 'int')) AS database_id,
        event_data.value('(event/action[@name="session_id"]/value)[1]', 'int') AS [session_id],
        event_data.value('(event/data[@name="cpu"]/value)[1]', 'int') AS [cpu],
        event_data.value('(event/data[@name="duration"]/value)[1]', 'bigint') AS [duration],
        event_data.value('(event/data[@name="reads"]/value)[1]', 'bigint') AS [reads],
        event_data.value('(event/data[@name="writes"]/value)[1]', 'bigint') AS [writes],
        event_data.value('(event/data[@name="state"]/text)[1]', 'nvarchar(4000)') AS [state],
        event_data.value('(event/data[@name="offset"]/value)[1]', 'int') AS [offset],
        event_data.value('(event/data[@name="offset_end"]/value)[1]', 'int') AS [offset_end],
        event_data.value('(event/data[@name="nest_level"]/value)[1]', 'int') AS [nest_level],
        CAST(event_data.value('(event/action[@name="tsql_stack"]/value)[1]', 'nvarchar(4000)') AS XML) AS [tsql_stack],
        REPLACE(event_data.value('(event/action[@name="sql_text"]/value)[1]', 'nvarchar(max)'), CHAR(10), CHAR(13)+CHAR(10)) AS [sql_text],
        event_data.value('(event/data[@name="source_database_id"]/value)[1]', 'int') AS [source_database_id],
        event_data.value('(event/data[@name="object_id"]/value)[1]', 'int') AS [object_id],
        event_data.value('(event/data[@name="object_type"]/text)[1]', 'int') AS [object_type],
        CAST(SUBSTRING(event_data.value('(event/action[@name="attach_activity_id"]/value)[1]', 'varchar(50)'), 1, 36) AS uniqueidentifier) as activity_id,
        CAST(SUBSTRING(event_data.value('(event/action[@name="attach_activity_id"]/value)[1]', 'varchar(50)'), 38, 10) AS int) as event_sequence
    FROM 
    (   SELECT XEvent.query('.') AS event_data 
        FROM 
        (    -- Cast the target_data to XML 
            SELECT CAST(target_data AS XML) AS TargetData 
            FROM sys.dm_xe_session_targets st 
            JOIN sys.dm_xe_sessions s 
                ON s.address = st.event_session_address 
            WHERE name = 'SQLStmtEvents' 
              AND target_name = 'ring_buffer'
        ) AS Data 
        -- Split out the Event Nodes 
        CROSS APPLY TargetData.nodes ('RingBufferTarget/event') AS XEventData (XEvent)   
    ) AS tab (event_data)
) AS results
CROSS APPLY sys.dm_exec_sql_text(tsql_stack.value('xs:hexBinary(substring((/frame/@handle)[1], 3))', 'varbinary(max)')) AS st

I filed this as a bug on Connect titled Extended Events sqlserver.sql_text Action is not Offset Parseable after trading a couple of emails with Mike Wachal about this, and he has already replied to the connect item stating that they are looking at the difference between the two operations in the engine.

SQL Server Denali

I was hesitant to even bother filing this as a bug because in SQL Server Denali CTP1, none of this is necessary to collect the statement, since the statement exists as a customizable column on the Events.

In Denali CTP1, the sql_statement_starting Event has the following columns:

select name, column_id, type_name, column_type
from sys.dm_xe_object_columns
where object_name = 'sql_statement_starting'
  and column_type <> 'readonly'

The sql_statement_completed Event has the following columns:

select name, column_id, type_name, column_type
from sys.dm_xe_object_columns
where object_name = 'sql_statement_completed'
  and column_type <> 'readonly'

If you compare the columns output by the sql_statement_completed Event in Denali CTP1, you will notice that it has significantly more columns in its base column payload, as well as having the statement as a customizable column. In Denali CTP1, the only thing necessary to get the specific TSQL statement that is executing is to turn collection of the customizable column statement on using the collect_statement column.

IF EXISTS (SELECT 1 FROM sys.dm_xe_sessions WHERE name = 'SQLStmtEvents')
    DROP EVENT SESSION SQLStmtEvents ON SERVER
GO
DECLARE @SqlCmd NVARCHAR(MAX) = N'
CREATE EVENT SESSION SQLStmtEvents
ON SERVER
ADD EVENT sqlserver.sql_statement_completed
(    SET collect_statement=1
    ACTION (sqlserver.sql_text, sqlserver.tsql_stack)
    WHERE (sqlserver.session_id = '+CAST(@@SPID AS NVARCHAR(4))+')    ),
ADD EVENT sqlserver.sql_statement_starting
(    SET collect_statement=1
    ACTION (sqlserver.sql_text, sqlserver.tsql_stack)
    WHERE (sqlserver.session_id = '+CAST(@@SPID AS NVARCHAR(4))+')    )
ADD target package0.ring_buffer
WITH (MAX_DISPATCH_LATENCY=5SECONDS, TRACK_CAUSALITY=ON)';
EXEC(@SqlCmd);
GO
ALTER EVENT SESSION SQLStmtEvents
ON SERVER
STATE=START;
GO

SELECT * 
FROM sys.objects

SELECT * 
FROM master..spt_values
WHERE type = N'P'

SELECT *
FROM INFORMATION_SCHEMA.TABLES
GO

With this turned on, all we have to do is query the Event Data and parse out the statement column to know the specific statement that was executing.

-- Extract the Event information from the Event Session 
SELECT 
    event_name, 
    timestamp, 
    cpu, 
    duration, 
    reads, 
    writes, 
    state, 
    statement,
    activity_id,
    event_sequence
FROM
(
    SELECT 
        event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,
        DATEADD(hh, 
            DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), 
            event_data.value('(event/@timestamp)[1]', 'datetime2')) AS [timestamp],
        event_data.value('(event/data[@name="cpu"]/value)[1]', 'int') AS [cpu],
        event_data.value('(event/data[@name="duration"]/value)[1]', 'bigint') AS [duration],
        event_data.value('(event/data[@name="reads"]/value)[1]', 'bigint') AS [reads],
        event_data.value('(event/data[@name="writes"]/value)[1]', 'bigint') AS [writes],
        event_data.value('(event/data[@name="state"]/text)[1]', 'nvarchar(4000)') AS [state],
        event_data.value('(event/data[@name="statement"]/value)[1]', 'nvarchar(max)') AS [statement],
        CAST(SUBSTRING(event_data.value('(event/action[@name="attach_activity_id"]/value)[1]', 'varchar(50)'), 1, 36) AS uniqueidentifier) as activity_id,
        CAST(SUBSTRING(event_data.value('(event/action[@name="attach_activity_id"]/value)[1]', 'varchar(50)'), 38, 10) AS int) as event_sequence
    FROM 
    (   SELECT XEvent.query('.') AS event_data 
        FROM 
        (    -- Cast the target_data to XML 
            SELECT CAST(target_data AS XML) AS TargetData 
            FROM sys.dm_xe_session_targets st 
            JOIN sys.dm_xe_sessions s 
                ON s.address = st.event_session_address 
            WHERE name = 'SQLStmtEvents' 
              AND target_name = 'ring_buffer'
        ) AS Data 
        -- Split out the Event Nodes 
        CROSS APPLY TargetData.nodes ('RingBufferTarget/event') AS XEventData (XEvent)   
    ) AS tab (event_data)
) AS results

The new statement column in Denali CTP 1 eliminates the need to do offset parsing of the sql_text Action entirely. Knowing that, it really became clear to me that the addition of the offset information in the Event’s base column payload was really useless, and for that I submitted a different Connect feedback item Extended Events - Remove data from Event output that is available by Actions. You might ask why does this matter? It matters because for everytime the Event fires, this information is included in the Event Data for the Event. Since Event Data is materialized as XML, this becomes needless bloat of the Event Data output for the Event and it really is useless information. If you really wanted to collect the offset information, you could add the tsql_stack Action to the Events to collect it, so there is no reason for the Event to carry this information by default.

So there you have it. How to parse the sqlserver.sql_text Action in SQL Server 2008 using offset information to isolate the actual executing statement from a multi-statement batch using a work around, and why its not necessary to do this in SQL Server Denali going forward.

An XEvent a Day (31 of 31) – Event Session DDL Events

jmkehayias — Fri, 31 Dec 2010 19:00:00 GMT

To close out this month’s series on Extended Events we’ll look at the DDL Events for the Event Session DDL operations, and how those can be used to track changes to Event Sessions and determine all of the possible outputs that could exist from an Extended Event Session. One of my least favorite quirks about Extended Events is that there is no way to determine the Events and Actions that may exist inside a Target, except to parse all of the the captured data. Information about the Event Session does exist in the Session Definition Catalog Views and Active Session DMV’s, but as you change an Event Sessions Events and Actions while it is running, the information in these change as well, so it is possible that a Target has Events and Actions that are not returned by the current information available about the Event Session. This is where the DDL Events for the Event Session DDL operations can be useful, if the appropriate framework is deployed.

The DDL Events for Extended Events are not currently documented in the Books Online. I only recently learned about them from Mike Wachal during a discussion about what I thought was missing from Extended Events. This is simply an oversight in the documentation, and something that Mike has stated will be fixed, it doesn’t mean that the DDL Events are undocumented and subject to change without notice like other undocumented features of SQL Server. We can find the DDL Events for Extended Events in the sys.event_notification_event_types.

SELECT
    type,
    type_name,
    parent_type
FROM sys.event_notification_event_types
WHERE type_name LIKE '%SESSION%'

These can be used just like any other DDL Event to create a DDL Trigger or Event Notification that takes action when one of the DDL operations occurs. We can use this to log the DDL to track our changes over time, and we can also use it to create a tracking table of the possible outputs from our Event Session, ensuring that we know what information it may have collected when we parse the Event data from the Targets. We can also use this information to simplify the generation of our XQuery XPATH statements to parse the data from the Targets with a little extra work.

In all of my servers, I have a standard database named sqladmin that I keep DBA related information and objects. For the examples, I will create this database and use it in all the code. If you have a different database, the scripts can easily be changed to create the objects in that database. The first thing we’ll do is create our database, and two tables, one for tracking the DDL operations and the other for tracking all of the possible outputs for our Event Session.

CREATE DATABASE sqladmin
GO
USE sqladmin
GO
CREATE TABLE dbo.XEvents_DDLOperations
( DDLEventData XML, 
  ChangeDate DATETIME DEFAULT(CURRENT_TIMESTAMP), 
  LoginName NVARCHAR(256) DEFAULT(SUSER_SNAME()),
  ProgramName NVARCHAR(256) DEFAULT(program_name())
);
GO
CREATE TABLE XEvents_SessionOutputs
(
    EventSessionName NVARCHAR(256),
    EventName NVARCHAR(256),
    EventID INT,
    ColumnID INT,
    ColumnName NVARCHAR(256),
    NodeType NVARCHAR(10),
    DataType NVARCHAR(50),
    XMLLocation NVARCHAR(10),
    TypePrecidence INT
)
GO

The XEvents_SessionOutputs table will have multiple rows for each Event Session defined on the server that track the EventName, the output ColumnName, the NodeType for the data element in the Event XML, the SQL DataType returned by the output, the XMLLocation for where the data of interest exists, and a TypePrecidence value that can be used when multiple Events return the same Data Element with different DataTypes, ensuring that we can pick the most compatible DataType for the output column. The table also tracks the Event ID in the Event Session for the Event, the Column ID for the output column so that grouping and ordering can be performed during code generation from this table.

To get the SQL DataType that an output returns, we have to look at the output type_name in the Extended Events metadata for the output column or Action. To make this easier to do and allow for code reuse, I create a view that maps the type_name in Extended Events to corresponding SQL DataType. Since Maps can be a type_name in Extended Events, the view queries the sys.dm_xe_map_values DMV and calculates the maximum length of the map_value column for each Map, and then uses the nvarchar datatype and rounds the length up to the nearest power of 10 (ok, it doesn’t actually round but that is the effect of the math operations). For the actual Event data columns in the base payload, the type_name is transposed to the equivalent SQL DataType that is compatible with XQuery.

CREATE VIEW dbo.XETypeToSQLType 
AS
    SELECT 
        XETypeName = mv.name, 
        SQLTypeName = 'nvarchar('+CAST(MAX(LEN(mv.map_value))-(MAX(LEN(mv.map_value))%10) + 10 AS VARCHAR(4))+')',
        XMLLocation = 'text',
        TypePrecidence = 5
    FROM sys.dm_xe_object_columns oc
    LEFT JOIN sys.dm_xe_map_values mv
        ON oc.type_package_guid = mv.object_package_guid
            AND oc.type_name = mv.name
    WHERE oc.column_type = 'data'
      AND mv.name IS NOT NULL
    GROUP BY mv.name
UNION ALL
    SELECT 
        XETypeName = o.name,
        SQLTypeName = CASE 
                            WHEN TYPE_NAME IN ('int8', 'int16', 'int32', 'uint8', 
                                    'uint16', 'uint32', 'float32') 
                                THEN 'int'
                            WHEN TYPE_NAME IN ('int64', 'uint64', 'float64')
                                THEN 'bigint'
                            WHEN TYPE_NAME = 'boolean'
                                THEN 'nvarchar(10)' --true/false returned
                            WHEN TYPE_NAME = 'guid'
                                THEN 'uniqueidentifier'
                            ELSE 'nvarchar(4000)'
                        END,
        XMLLocation = 'value',
        TypePrecidence = CASE 
                            WHEN TYPE_NAME IN ('int8', 'int16', 'int32', 'uint8', 
                                    'uint16', 'uint32', 'float32') 
                                THEN 1
                            WHEN TYPE_NAME IN ('int64', 'uint64', 'float64')
                                THEN 2
                            WHEN TYPE_NAME = 'boolean'
                                THEN 3 --true/false returned
                            WHEN TYPE_NAME = 'guid'
                                THEN 3
                            ELSE 5
                         END
    FROM sys.dm_xe_objects o
    WHERE object_type = 'type'
      AND TYPE_NAME != 'null'
GO

Using this view, we can create another view that queries the Session Definition Catalog Views, to retrieve the output columns for an Event Session in a format that matches our XEvents_SessionOutputs table.

CREATE VIEW dbo.XESession_OutputsFromDMVs
AS
        -- Find a list of all the possible output columns
        SELECT 
            ses.name AS EventSessionName,
            sese.name AS EventName,
            sese.event_id AS EventID,
            oc.column_id AS ColumnID,
            oc.name AS ColumnName,
            'data' AS NodeType,
            xetst.SQLTypeName AS DataType,
            xetst.XMLLocation,
            xetst.TypePrecidence
        FROM sys.server_event_sessions AS ses
        JOIN sys.server_event_session_events AS sese
            ON ses.event_session_id = sese.event_session_id
        JOIN sys.dm_xe_packages AS p 
            ON sese.package = p.name
        JOIN sys.dm_xe_object_columns AS oc 
            ON oc.object_name = sese.name
                AND oc.object_package_guid = p.guid
        JOIN XETypeToSQLType AS xetst
            ON oc.type_name = xetst.XETypeName
        WHERE oc.column_type = 'data'
    UNION
        SELECT 
            ses.name,
            sese.name,
            sesa.event_id,
            999 AS column_id,
            sesa.name,
            'action',
            xetst.SQLTypeName,
            xetst.XMLLocation,
            xetst.TypePrecidence
        FROM sys.server_event_sessions AS ses
        JOIN sys.server_event_session_events AS sese
            ON ses.event_session_id = sese.event_session_id
        JOIN sys.server_event_session_actions AS sesa
            ON ses.event_session_id = sesa.event_session_id
                AND sesa.event_id = sese.event_id
        JOIN sys.dm_xe_packages AS p
            ON sesa.package = p.name
        JOIN sys.dm_xe_objects AS o
            ON p.guid = o.package_guid
                AND sesa.name = o.name
        JOIN XETypeToSQLType AS xetst
            ON o.type_name = xetst.XETypeName
        WHERE o.object_type = 'action'
GO

We can then create a Server Level DDL Trigger for the DDL_EVENT_SESSION_EVENTS group that will log the DDL operation to the XEvents_DDLOperations table, and at the same time populate the output information in the XEvents_SessionOutputs table when an Event Session is created, add any new outputs when an Event Session is altered, and delete the Event Session information when an Event Session is dropped. By adding new outputs when a Event Session is altered, we maintain a record of the original outputs, even if the Event was dropped from the Event Session.

CREATE TRIGGER XEvents_DDLTrigger
ON ALL SERVER 
FOR DDL_EVENT_SESSION_EVENTS
AS
BEGIN
    SET NOCOUNT ON;
    DECLARE @EventData XML = EVENTDATA();
    INSERT INTO sqladmin.dbo.XEvents_DDLOperations (DDLEventData)
    VALUES (@EventData);

    DECLARE @EventType NVARCHAR(256) = @EventData.value('(EVENT_INSTANCE/EventType)[1]', 'nvarchar(256)')
    DECLARE @SessionName NVARCHAR(256) = @EventData.value('(EVENT_INSTANCE/ObjectName)[1]', 'nvarchar(256)')

    IF @EventType = 'CREATE_EVENT_SESSION'
    BEGIN
        INSERT INTO sqladmin.dbo.XEvents_SessionOutputs 
            (EventSessionName, EventName, EventID, ColumnID, ColumnName, NodeType,
             DataType, XMLLocation, TypePrecidence)
        SELECT EventSessionName, EventName, EventID, ColumnID, ColumnName, NodeType,
             DataType, XMLLocation, TypePrecidence
        FROM sqladmin.dbo.XESession_OutputsFromDMVs
        WHERE EventSessionName = @SessionName
    END

    IF @EventType = 'ALTER_EVENT_SESSION'
    BEGIN
        -- Add any new outputs to the Table
        INSERT INTO sqladmin.dbo.XEvents_SessionOutputs
            (EventSessionName, EventName, EventID, ColumnID, ColumnName, NodeType,
             DataType, XMLLocation, TypePrecidence)
        SELECT vdmv.EventSessionName, vdmv.EventName, vdmv.EventID, vdmv.ColumnID, vdmv.ColumnName, vdmv.NodeType,
             vdmv.DataType, vdmv.XMLLocation, vdmv.TypePrecidence
        FROM sqladmin.dbo.XESession_OutputsFromDMVs vdmv
        LEFT JOIN sqladmin.dbo.XEvents_SessionOutputs xeso
            ON vdmv.EventSessionName = xeso.EventSessionName
                AND vdmv.EventName = xeso.EventName
                AND vdmv.ColumnName = vdmv.ColumnName
        WHERE vdmv.EventSessionName = @SessionName
          AND xeso.EventSessionName IS NULL
    END

    IF @EventType = 'DROP_EVENT_SESSION'
    BEGIN
        -- Delete the Output data for the Event Session
        DELETE sqladmin.dbo.XEvents_SessionOutputs
        WHERE EventSessionName = @SessionName
    END
END
GO

If we recreate the TrackResourceWaits Event Session from yesterday’s post and then query the XEvents_SessionOutputs table, we can see the outputs that we can expect from that Event Session:

SELECT *
FROM sqladmin.dbo.XEvents_SessionOutputs
WHERE EventSessionName = 'TrackResourceWaits'

Using this information, we can also write a query to generate our XQuery statements for each of the outputs, as well as a column definition stub if we wanted to create a table to hold this information for analysis.

SELECT 
    'event_data.value(''(event/'+NodeType+'[@name="'+ColumnName+'"]/'+XMLLocation+')[1]'', '''+DataType+''') AS '+QUOTENAME(ColumnName)+',' AS XQuery,
    QUOTENAME(ColumnName)+' '+DataType+', ' AS ColumnDefinition
FROM
(
    SELECT 
        ROW_NUMBER() OVER (PARTITION BY ColumnName ORDER BY TypePrecidence DESC) AS partitionid,
        EventSessionName,
        EventID,
        ColumnID,
        ColumnName,
        NodeType,
        DataType,
        XMLLocation
    FROM sqladmin.dbo.XEvents_SessionOutputs
) AS tab
WHERE EventSessionName = 'TrackResourceWaits'
  AND partitionid = 1
ORDER BY EventID, ColumnID

The information in the XQuery column can be copied and pasted into our TSQL Script for parsing the Event Data from the ring_buffer, pair_matching, or asynchronous_file_target Targets. You could also use this as the basis for writing your own Extended Events Target Data code generator, similar to the one that Adam Machanic created a year ago.

That’s it for this months series on Extended Events. You can find links to all of the posts on the round up post from December 1, An XEvent A Day: 31 days of Extended Events. Hopefully its been informative, and you now have a better understanding of how Extended Events can be used inside of SQL Server 2008, 2008R2, and in Denali CTP1.

An XEvent a Day (30 of 31) – Tracking Session and Statement Level Waits

jmkehayias — Fri, 31 Dec 2010 02:00:00 GMT

While attending PASS Summit this year, I got the opportunity to hang out with Brent Ozar (Blog|Twitter) one afternoon while he did some work for Yanni Robel (Blog|Twitter). After looking at the wait stats information, Brent pointed out some potential problem points, and based on that information I pulled up my code for my PASS session the next day on Wait Statistics and Extended Events and made some changes to one of the demo’s so that the Event Session only focused on those potentially problematic waits that had been identified, and sent Brent the DDL so that he could give Extended Events a shot. Within a few minutes, we were able track down to the statement level in a couple of stored procedures, the causes of those waits, and after some analysis Brent was able to offer some suggestions to Yanni about how to reduce the waits.

Understanding how SQL Server waits to continue execution can be key to improving performance since time spent waiting is time lost during the execution of a SQL Statement. I love looking at wait statistics and the chapter that I wrote for SQL Server 2008 Internals and Troubleshooting was SQL Server Waits and Extended Events. Information about wait statistics has been available in SQL Server for a long time, and many of the vendors that develop monitoring applications for SQL Server have polling methods that query sys.dm_os_waiting_tasks or sys.sysprocesses to capture wait information about the tasks that are currently active in the system. However one of the shortcomings of a polling method is that it misses a lot of the wait information because it is a point in time snapshot only. If the polling interval is every second, only the active waits that exist at that second are captured, and any waits that occur between the polling interval is missed. This information is still accumulated in sys.dm_os_wait_stats, but it is impossible to track it back to the statement level from that DMV.

Extended Events offers us the ability to capture information about waits without missing any of the information. Already in this series we’ve seen how to use Extended Events with the Bucketizer Target to count the occurrences of waits by type. This isn’t really a great use of Extended Events since sys.dm_os_wait_stats counts the occurrences of the wait types already, and a differential analysis of the information contained in sys.dm_os_wait_stats can provide this information. The purpose of that example was to discuss the bug that existed in the RTM release of SQL Server 2008 more than it was to provide a sensible use for the target. However, if we wanted to break our waits down by database, we could bucket on the database_id, and begin to understand which database had the most waits associated with it, but not by the individual wait type. To get to that level of information, we need to collect all of the waits and the associated information for them to do further analysis.

There are two Events in Extended Events associated with wait types; sqlos.wait_info and sqlos.wait_info_external. Looking at the description of the Events in the Metadata DMV’s we can get an idea of when each Event will fire.

SELECT name, description 
FROM sys.dm_xe_objects
WHERE name LIKE 'wait_info%'

The sqlos.wait_info_external Event will fire for wait types that begin with PREEMPTIVE_ in the name, and the sqlos.wait_info Event will fire for the other wait types that occur on the server. Glenn Alan Berry (Blog|Twitter) has a great script that filters queries sys.dm_os_wait_stats and filters out common waits that are not generally problematic. You can find his script on his blog post Updated SQL 2005 and 2008 Diagnostic Queries. You can use this script to identify the most common waits on a server, and then use that information to build an Event Session that captures the session and statement information for those individual wait types. In SQL Server 2008, there are 484 wait types listed in sys.dm_os_wait_stats and there are 599 map_value’s for the wait_types Map in sys.dm_xe_map_values. The reason this is different is that the Map was created from the header file for the wait types and there are padded values that exist in the Map that don’t really correspond to wait types that exist in SQL Server. However, there are also a couple of Maps for the wait_types that don’t match the wait type in sys.dm_os_wait_stats, the most notable being the ASYNC_NETWORK_IO to NETWORK_IO.

To build the Event Session, we just need to query sys.dm_map_values for our wait_types and use the map_key's in the Predicate definition of the sqlos.wait_info or sqlos.wait_info_external Event as appropriate. We can also do the same thing to build a generic Event Session that tracks the most common resource related waits.

SELECT map_key, map_value 
FROM sys.dm_xe_map_values
WHERE name = 'wait_types'
  AND ((map_key > 0 AND map_key < 22) -- LCK_ waits
            OR (map_key > 31 AND map_key < 38) -- LATCH_ waits
            OR (map_key > 47 AND map_key < 54) -- PAGELATCH_ waits
            OR (map_key > 63 AND map_key < 70) -- PAGEIOLATCH_ waits
            OR (map_key > 96 AND map_key < 100) -- IO (Disk/Network) waits
            OR (map_key = 107) -- RESOURCE_SEMAPHORE waits
            OR (map_key = 113) -- SOS_WORKER waits
            OR (map_key = 120) -- SOS_SCHEDULER_YIELD waits
            OR (map_key = 178) -- WRITELOG waits
            OR (map_key > 174 AND map_key < 177) -- FCB_REPLICA_ waits
            OR (map_key = 186) -- CMEMTHREAD waits
            OR (map_key = 187) -- CXPACKET waits
            OR (map_key = 207) -- TRACEWRITE waits
            OR (map_key = 269) -- RESOURCE_SEMAPHORE_MUTEX waits
            OR (map_key = 283) -- RESOURCE_SEMAPHORE_QUERY_COMPILE waits
            OR (map_key = 284) -- RESOURCE_SEMAPHORE_SMALL_QUERY waits
        )

Once we have the list of map_key’s defined, we can do a replace in SSMS and change map_key to wait_type and define the predicate for the sqlos.wait_info Event for our Event Session.

CREATE EVENT SESSION [TrackResourceWaits] ON SERVER 
ADD EVENT  sqlos.wait_info
(    -- Capture the database_id, session_id, plan_handle, and sql_text
    ACTION(sqlserver.database_id,sqlserver.session_id,sqlserver.sql_text,sqlserver.plan_handle)
    WHERE
        (opcode = 1 --End Events Only
            AND duration > 100 -- had to accumulate 100ms of time
            AND ((wait_type > 0 AND wait_type < 22) -- LCK_ waits
                    OR (wait_type > 31 AND wait_type < 38) -- LATCH_ waits
                    OR (wait_type > 47 AND wait_type < 54) -- PAGELATCH_ waits
                    OR (wait_type > 63 AND wait_type < 70) -- PAGEIOLATCH_ waits
                    OR (wait_type > 96 AND wait_type < 100) -- IO (Disk/Network) waits
                    OR (wait_type = 107) -- RESOURCE_SEMAPHORE waits
                    OR (wait_type = 113) -- SOS_WORKER waits
                    OR (wait_type = 120) -- SOS_SCHEDULER_YIELD waits
                    OR (wait_type = 178) -- WRITELOG waits
                    OR (wait_type > 174 AND wait_type < 177) -- FCB_REPLICA_ waits
                    OR (wait_type = 186) -- CMEMTHREAD waits
                    OR (wait_type = 187) -- CXPACKET waits
                    OR (wait_type = 207) -- TRACEWRITE waits
                    OR (wait_type = 269) -- RESOURCE_SEMAPHORE_MUTEX waits
                    OR (wait_type = 283) -- RESOURCE_SEMAPHORE_QUERY_COMPILE waits
                    OR (wait_type = 284) -- RESOURCE_SEMAPHORE_SMALL_QUERY waits
                )
        )
)
ADD TARGET package0.ring_buffer(SET max_memory=4096)
WITH (EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,
      MAX_DISPATCH_LATENCY=5 SECONDS)
GO

Now that we have the Event Session defined, we can start it as needed to collect the resource wait information for our system. The only concern with this Event Session is the Target being used. If the Event Session is going to run for a long period of time, or if the waits on the server being monitored occur in large quantities, the Target should be changed away from the ring_buffer to the asynchronous_file_target. I configured this session to only collect waits that exceed 100ms in duration. If you want waits that have shorter durations this can easily be changed. If you set the duration to be > 0 a lot of 1-5ms waits will be collected that aren’t generally interesting. To query the wait information from this Event Session using the ring_buffer:

-- Extract the Event information from the Event Session 
SELECT 
    event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,
    DATEADD(hh, 
        DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), 
        event_data.value('(event/@timestamp)[1]', 'datetime2')) AS [timestamp],
    COALESCE(event_data.value('(event/data[@name="database_id"]/value)[1]', 'int'), 
        event_data.value('(event/action[@name="database_id"]/value)[1]', 'int')) AS database_id,
    event_data.value('(event/action[@name="session_id"]/value)[1]', 'int') AS [session_id],
    event_data.value('(event/data[@name="wait_type"]/text)[1]', 'nvarchar(4000)') AS [wait_type],
    event_data.value('(event/data[@name="opcode"]/text)[1]', 'nvarchar(4000)') AS [opcode],
    event_data.value('(event/data[@name="duration"]/value)[1]', 'bigint') AS [duration],
    event_data.value('(event/data[@name="max_duration"]/value)[1]', 'bigint') AS [max_duration],
    event_data.value('(event/data[@name="total_duration"]/value)[1]', 'bigint') AS [total_duration],
    event_data.value('(event/data[@name="signal_duration"]/value)[1]', 'bigint') AS [signal_duration],
    event_data.value('(event/data[@name="completed_count"]/value)[1]', 'bigint') AS [completed_count],
    event_data.value('(event/action[@name="plan_handle"]/value)[1]', 'nvarchar(4000)') AS [plan_handle],
    event_data.value('(event/action[@name="sql_text"]/value)[1]', 'nvarchar(4000)') AS [sql_text]
FROM 
(    SELECT XEvent.query('.') AS event_data 
    FROM 
    (    -- Cast the target_data to XML 
        SELECT CAST(target_data AS XML) AS TargetData 
        FROM sys.dm_xe_session_targets st 
        JOIN sys.dm_xe_sessions s 
            ON s.address = st.event_session_address 
        WHERE name = 'TrackResourceWaits' 
          AND target_name = 'ring_buffer'
    ) AS Data 
    -- Split out the Event Nodes 
    CROSS APPLY TargetData.nodes ('RingBufferTarget/event') AS XEventData (XEvent)   
) AS tab (event_data)

In the result set, you will notice that some of the wait_info Events do not have an associated session_id, database_id, plan_handle, or sql_text value. Depending on where the wait actually occurs in code, this information is not available to the firing Event, for example, the NETWORK_IO Event generally does not successfully collect these Actions.

While collecting session and statement level waits like this is certainly interesting, there are some considerations that have to be made whenever you look at wait information like this. The first consideration is that, while a specific session or statement waited on a resource, that doesn’t necessarily mean that the problem exists within that session or statement. Take for example a query that has to wait 500ms on ASYNC_IO_COMPLETION waits. At the same time that query is executing there are 10 DSS queries running that scan large ranges of data from the database data files and generate a lot of IO activity. Where exactly is the problem? The root problem is that there is a disk IO bottleneck, but not necessarily related to the query that is waiting on disk IO, it could be another query performing Table Scan that is leading to the heavy IO activity.

An XEvent a Day (29 of 31) – The Future – Looking at Database Startup in Denali

jmkehayias — Thu, 30 Dec 2010 02:30:00 GMT

As I have said previously in this series, one of my favorite aspects of Extended Events is that it allows you to look at what is going on under the covers in SQL Server, at a level that has never previously been possible. SQL Server Denali CTP1 includes a number of new Events that expand on the information that we can learn about how SQL Server operates and in today’s blog post we’ll look at how we can use those Events to look at what happens when a database starts up inside of SQL Server.

First lets create our Event Session, which will collect a large number of events that relate to the operations that occur when a database starts in SQL Server.

DECLARE @sqlcmd nvarchar(max) =
'IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE
name=''MonitorStartupLogRecovery'')
   DROP EVENT SESSION [MonitorStartupLogRecovery] ON SERVER;
CREATE EVENT SESSION [MonitorStartupLogRecovery]
ON SERVER
ADD EVENT sqlserver.database_started 
(WHERE (database_id = ' + CAST(DB_ID('AdventureWorks2008R2') AS varchar(3)) + ')),
ADD EVENT sqlserver.databases_log_file_used_size_changed 
(WHERE (database_id = ' + CAST(DB_ID('AdventureWorks2008R2') AS varchar(3)) + ')),
ADD EVENT sqlserver.databases_log_flush 
(WHERE (database_id = ' + CAST(DB_ID('AdventureWorks2008R2') AS varchar(3)) + ')),
ADD EVENT sqlserver.databases_log_flush_wait 
(WHERE (database_id = ' + CAST(DB_ID('AdventureWorks2008R2') AS varchar(3)) + ')),
ADD EVENT sqlserver.file_read 
(WHERE (database_id = ' + CAST(DB_ID('AdventureWorks2008R2') AS varchar(3)) + ')),
ADD EVENT sqlserver.file_read_completed 
(WHERE (database_id = ' + CAST(DB_ID('AdventureWorks2008R2') AS varchar(3)) + ')),
ADD EVENT sqlserver.file_write_completed 
(WHERE (database_id = ' + CAST(DB_ID('AdventureWorks2008R2') AS varchar(3)) + ')),
ADD EVENT sqlserver.file_written 
(WHERE (database_id = ' + CAST(DB_ID('AdventureWorks2008R2') AS varchar(3)) + ')),
ADD EVENT sqlserver.log_block_cache 
(WHERE (database_id = ' + CAST(DB_ID('AdventureWorks2008R2') AS varchar(3)) + ')),
ADD EVENT sqlserver.log_block_consume 
(WHERE (database_id = ' + CAST(DB_ID('AdventureWorks2008R2') AS varchar(3)) + ')),
ADD EVENT sqlserver.log_blocks_uncache 
(WHERE (database_id = ' + CAST(DB_ID('AdventureWorks2008R2') AS varchar(3)) + ')),
ADD EVENT sqlserver.log_cache_buffer_refcounter_change 
(WHERE (database_id = ' + CAST(DB_ID('AdventureWorks2008R2') AS varchar(3)) + ')),
ADD EVENT sqlserver.log_consumer_act 
(WHERE (database_id = ' + CAST(DB_ID('AdventureWorks2008R2') AS varchar(3)) + ')),
ADD EVENT sqlserver.log_flush_complete 
(WHERE (database_id = ' + CAST(DB_ID('AdventureWorks2008R2') AS varchar(3)) + ')),
ADD EVENT sqlserver.log_flush_requested 
(WHERE (database_id = ' + CAST(DB_ID('AdventureWorks2008R2') AS varchar(3)) + ')),
ADD EVENT sqlserver.log_flush_start 
(WHERE (database_id = ' + CAST(DB_ID('AdventureWorks2008R2') AS varchar(3)) + ')),
ADD EVENT sqlserver.log_single_record 
(WHERE (database_id = ' + CAST(DB_ID('AdventureWorks2008R2') AS varchar(3)) + ')),
ADD EVENT sqlserver.new_log_interest_flip 
(WHERE (database_id = ' + CAST(DB_ID('AdventureWorks2008R2') AS varchar(3)) + ')),
ADD EVENT sqlserver.redo_single_record 
(WHERE (database_id = ' + CAST(DB_ID('AdventureWorks2008R2') AS varchar(3)) + ')),
ADD EVENT sqlserver.redo_target_set 
(WHERE (database_id = ' + CAST(DB_ID('AdventureWorks2008R2') AS varchar(3)) + ')),
ADD EVENT sqlserver.transaction_log 
(WHERE (database_id = ' + CAST(DB_ID('AdventureWorks2008R2') AS varchar(3)) + '))
ADD TARGET package0.asynchronous_file_target(
     SET filename=''C:\SQLBlog\MonitorStartupLogRecovery.xel'',
         metadatafile=''C:\SQLBlog\MonitorStartupLogRecovery.xem'')
WITH (MAX_MEMORY = 8192KB, EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS, STARTUP_STATE = ON)'
EXEC(@sqlcmd)
GO

With the Event Session created, we can make some changes that write to our test database to see what happens when the database is recovered at startup. We are going to make two changes to the database. First we’ll begin a transaction and create a table with 10 rows of data in it without committing the transaction.

USE AdventureWorks2008R2
GO
-- Begin a Transaction and leave it open
BEGIN TRANSACTION
-- Create the First Table
SELECT TOP 10 *
INTO TestTable
FROM Sales.SalesOrderDetail sod
GO

Now in a New Query Window, we’ll create a second table with 10 rows of data without opening a transaction, and then force a dirty shutdown of the Database Engine.

USE AdventureWorks2008R2
GO
-- Create a Second Table
SELECT TOP 10 *
INTO TestTable2
FROM Sales.SalesOrderDetail sod
GO
-- Flush changes to data file
CHECKPOINT
GO
-- Force Shutdown the Engine
SHUTDOWN

Once SHUTDOWN is issued, the process terminates, and the Database Engine will need to be restarted from the Services Snapin, the SQL Server Configuration Manager, or through SSMS. When the Engine starts up, the Event Session will become active, and the Events will be logged to the package0.asynchronous_file_target for analysis. Once recovery completes, we can drop the Event Session from the Server, so that the buffers flush, and we can then begin our analysis of the collected information.

USE tempdb
GO

-- Read the Raw Event data into a table
SELECT CAST(event_data AS XML) AS event_data
INTO TargetEvents
FROM sys.fn_xe_file_target_read_file('C:\SQLBlog\MonitorStartupLogRecovery*.xel', 'C:\SQLBlog\MonitorStartupLogRecovery*.xem', null, null)

-- Fetch the Event Data from the Raw Event Data into another table
SELECT 
    event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,
    DATEADD(hh, 
            DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), 
            event_data.value('(event/@timestamp)[1]', 'datetime2')) AS [timestamp],
    COALESCE(event_data.value('(event/data[@name="database_id"]/value)[1]', 'int'), 
             event_data.value('(event/action[@name="database_id"]/value)[1]', 'int')) AS database_id,
    event_data.value('(event/data[@name="count"]/value)[1]', 'bigint') AS [count],
    event_data.value('(event/data[@name="start_log_block_id"]/value)[1]', 'bigint') AS [start_log_block_id],
    event_data.value('(event/data[@name="is_read_ahead"]/value)[1]', 'nvarchar(4000)') AS [is_read_ahead],
    event_data.value('(event/data[@name="private_consumer_id"]/value)[1]', 'bigint') AS [private_consumer_id],
    event_data.value('(event/data[@name="mode"]/text)[1]', 'nvarchar(4000)') AS [mode],
    event_data.value('(event/data[@name="file_handle"]/value)[1]', 'nvarchar(4000)') AS [file_handle],
    event_data.value('(event/data[@name="offset"]/value)[1]', 'bigint') AS [offset],
    event_data.value('(event/data[@name="file_id"]/value)[1]', 'int') AS [file_id],
    event_data.value('(event/data[@name="filegroup_id"]/value)[1]', 'int') AS [filegroup_id],
    event_data.value('(event/data[@name="size"]/value)[1]', 'bigint') AS [size],
    event_data.value('(event/data[@name="path"]/value)[1]', 'nvarchar(4000)') AS [path],
    event_data.value('(event/data[@name="duration"]/value)[1]', 'bigint') AS [duration],
    event_data.value('(event/data[@name="io_data"]/value)[1]', 'nvarchar(4000)') AS [io_data],
    event_data.value('(event/data[@name="resource_type"]/text)[1]', 'nvarchar(4000)') AS [resource_type],
    event_data.value('(event/data[@name="owner_type"]/text)[1]', 'nvarchar(4000)') AS [owner_type],
    event_data.value('(event/data[@name="transaction_id"]/value)[1]', 'bigint') AS [transaction_id],
    event_data.value('(event/data[@name="lockspace_workspace_id"]/value)[1]', 'nvarchar(4000)') AS [lockspace_workspace_id],
    event_data.value('(event/data[@name="lockspace_sub_id"]/value)[1]', 'int') AS [lockspace_sub_id],
    event_data.value('(event/data[@name="lockspace_nest_id"]/value)[1]', 'int') AS [lockspace_nest_id],
    event_data.value('(event/data[@name="resource_0"]/value)[1]', 'int') AS [resource_0],
    event_data.value('(event/data[@name="resource_1"]/value)[1]', 'int') AS [resource_1],
    event_data.value('(event/data[@name="resource_2"]/value)[1]', 'int') AS [resource_2],
    event_data.value('(event/data[@name="object_id"]/value)[1]', 'int') AS [object_id],
    event_data.value('(event/data[@name="associated_object_id"]/value)[1]', 'bigint') AS [associated_object_id],
    event_data.value('(event/data[@name="resource_description"]/value)[1]', 'nvarchar(4000)') AS [resource_description],
    event_data.value('(event/data[@name="database_name"]/value)[1]', 'nvarchar(4000)') AS [database_name],
    event_data.value('(event/data[@name="log_block_id"]/value)[1]', 'bigint') AS [log_block_id],
    event_data.value('(event/data[@name="log_block_size"]/value)[1]', 'int') AS [log_block_size],
    event_data.value('(event/data[@name="from_disk"]/value)[1]', 'nvarchar(4000)') AS [from_disk],
    event_data.value('(event/data[@name="incomplete"]/value)[1]', 'nvarchar(4000)') AS [incomplete],
    event_data.value('(event/data[@name="cache_buffer_pointer"]/value)[1]', 'nvarchar(4000)') AS [cache_buffer_pointer],
    event_data.value('(event/data[@name="consumer_id"]/value)[1]', 'bigint') AS [consumer_id],
    event_data.value('(event/data[@name="old_weight"]/value)[1]', 'int') AS [old_weight],
    event_data.value('(event/data[@name="new_weight"]/value)[1]', 'int') AS [new_weight],
    event_data.value('(event/data[@name="new_position"]/value)[1]', 'int') AS [new_position],
    event_data.value('(event/data[@name="last_log_block_id"]/value)[1]', 'bigint') AS [last_log_block_id],
    event_data.value('(event/data[@name="weight"]/value)[1]', 'int') AS [weight],
    event_data.value('(event/data[@name="address"]/value)[1]', 'nvarchar(4000)') AS [address],
    event_data.value('(event/data[@name="type"]/text)[1]', 'nvarchar(4000)') AS [type],
    event_data.value('(event/data[@name="current_count"]/value)[1]', 'int') AS [current_count],
    event_data.value('(event/data[@name="change_type"]/value)[1]', 'int') AS [change_type],
    event_data.value('(event/data[@name="activity_id"]/value)[1]', 'int') AS [activity_id],
    event_data.value('(event/data[@name="write_size"]/value)[1]', 'int') AS [write_size],
    event_data.value('(event/data[@name="rows"]/value)[1]', 'int') AS [rows],
    event_data.value('(event/data[@name="pending_writes"]/value)[1]', 'int') AS [pending_writes],
    event_data.value('(event/data[@name="pending_bytes"]/value)[1]', 'int') AS [pending_bytes],
    event_data.value('(event/data[@name="reason"]/text)[1]', 'nvarchar(4000)') AS [reason],
    event_data.value('(event/data[@name="waiters"]/value)[1]', 'int') AS [waiters],
    event_data.value('(event/data[@name="error"]/value)[1]', 'int') AS [error],
    event_data.value('(event/data[@name="slot_id"]/value)[1]', 'int') AS [slot_id],
    event_data.value('(event/data[@name="used_size"]/value)[1]', 'int') AS [used_size],
    event_data.value('(event/data[@name="reservation_size"]/value)[1]', 'bigint') AS [reservation_size],
    event_data.value('(event/data[@name="log_op_id"]/value)[1]', 'int') AS [log_op_id],
    event_data.value('(event/data[@name="log_op_name"]/value)[1]', 'nvarchar(4000)') AS [log_op_name],
    event_data.value('(event/data[@name="interest"]/value)[1]', 'nvarchar(4000)') AS [interest],
    event_data.value('(event/data[@name="cache_type"]/value)[1]', 'int') AS [cache_type],
    event_data.value('(event/data[@name="keys"]/value)[1]', 'nvarchar(4000)') AS [keys],
    event_data.value('(event/data[@name="stop_mark"]/value)[1]', 'nvarchar(4000)') AS [stop_mark],
    event_data.value('(event/data[@name="operation"]/text)[1]', 'nvarchar(4000)') AS [operation],
    event_data.value('(event/data[@name="success"]/value)[1]', 'nvarchar(4000)') AS [success],
    event_data.value('(event/data[@name="index_id"]/value)[1]', 'int') AS [index_id],
    event_data.value('(event/data[@name="log_record_size"]/value)[1]', 'int') AS [log_record_size],
    event_data.value('(event/data[@name="context"]/text)[1]', 'nvarchar(4000)') AS [context],
    event_data.value('(event/data[@name="replication_command"]/value)[1]', 'int') AS [replication_command],
    event_data.value('(event/data[@name="transaction_start_time"]/value)[1]', 'nvarchar(4000)') AS [transaction_start_time]
INTO Results
FROM TargetEvents

Now we can begin to analyze the information that we collected by querying the Results table. Looking at the Results as a whole, we can see the database opened by reading the first page of the database and then the database boot page (page_id=9) and page 32 of the primary data file. Then the engine scans each of the VLF’s of the transaction log. We can tell that the log reads are scans of the VLF’s by looking at the DBCC LOGINFO information for the database and comparing the file_read offsets from the Event Session to the StartOffset of each of the VLF’s in the DBCC LOGINFO output.

DBCC LOGINFO

SELECT event_name, timestamp, database_id, file_id, mode, offset, 
    CASE WHEN file_id = 1 THEN offset/8192 ELSE NULL END AS page_id, size, 
    log_block_id, log_block_size, start_log_block_id, last_log_block_id, 
    from_disk, consumer_id, activity_id, log_op_id, log_op_name, change_type, 
    operation, object_id, index_id, log_record_size, slot_id, used_size, 
    reservation_size, write_size, rows, pending_writes, pending_bytes, 
    context, waiters
FROM Results

After the startup scans the VLF’s 120K of information is read from the log file, and the log buffers start to be consumed to determine the redo start point for recovery. We can filter our Event data to remove Events that while interesting are not necessary for our analysis at the moment, as well as to reduce the number of columns being returned from the data set.

SELECT 
    event_name, timestamp, file_id, mode, offset, size, log_block_id, 
    COALESCE(log_op_name, operation) as [operation], slot_id, 
    object_id, index_id, log_record_size, context, write_size, rows
FROM Results
WHERE event_name NOT IN ('log_consumer_act', 'log_single_record', 'log_cache_buffer_refcounter_change', 'file_read')

With the filtered results, we can see the log reads into cache and the setting of the redo target. If we scroll down further, we can get a better picture of what is happening.

The last active log blog was consumed, and the redo target was set at that log_block_id. Then the log is reread starting at offset 318976 and the blocks get cached and the redo operations begin against the database. Scrolling through the results further, we can see that the redo operations continue as the log blocks increase up to the Checkpoint operation that was executed immediately before the Shutdown of the instance occurred, at the log block that was set as the redo target originally.

At this point the data file begins to be read so that the undo operations can be performed before making the database available.

After the undo completes the database_started Event is raised and that database becomes available for use.

To validate that the changes we see occurring after the redo operations and before the database_started Event, we can set the database OFFLINE, recreate our Event Session, and then bring the database back ONLINE again, and then compare the logged Events when no changes have occurred to our original Events when known changes have occurred. I am not going to do that in this blog post, but will instead leave that up to the reader to investigate on their own.

An XEvent a Day (28 of 31) – Tracking Page Compression Operations

jmkehayias — Wed, 29 Dec 2010 02:00:00 GMT

The Database Compression feature in SQL Server 2008 Enterprise Edition can provide some significant reductions in storage requirements for SQL Server databases, and in the right implementations and scenarios performance improvements as well. There isn’t really a whole lot of information about the operations of database compression that is documented as being available in the DMV’s or SQL Trace. Paul Randal pointed out on Twitter today that sys.dm_db_index_operational_stats() provides the page_compression_attempt_count and page_compression_success_count available. Beyond that the only other documented information for monitoring Data Compression are the Page Compression Attempts/sec and Pages Compressed/sec Performance Counters of the SQL Server:Access Methods object in Perfmon (http://msdn.microsoft.com/en-us/library/cc280449.aspx).

There is one thing in common about the documented methods of monitoring Data Compression, and that is they all only deal with Page compression, and not Row compression, and in Extended Events we find the same commonality as there are no Row compression Events in Extended Events. There are two Page compression Events in Extended Events; sqlserver.page_compression_attempt_failed and sqlserver.page_compression_tracing. These two Events can be used to track Page compression operations at multiple levels, including database, object, index, and even down to the individual page. The sqlserver.page_compression_tracing Event provides Start and End tracing of Page compression operations inside of the Database Engine and returns the database_id, index_id, rowset_id, page_id, and duration of the compression operation. The sqlserver.page_compression_attempt_failed is really poorly named, and doesn’t provide information about failures in the sense that something broke, but provides information for why a page compression attempt did not actually change the compression of the data in the page. It also returns the database_id, index_id, rowset_id, and page_id for the compression attempt, and it also includes a failure_reason column which correlates to the page_compression_failure_reason Map Value.

-- Get the payload information for the Events 
SELECT 
    object_name, 
    column_id, 
    name, 
    type_name
FROM sys.dm_xe_object_columns
WHERE object_name IN ('page_compression_tracing', 
                      'page_compression_attempt_failed')
  AND column_type = 'data'

To demonstrate how these Events function, I am going to use the LineItem table from the TPC-H Benchmark that was created by Quest Benchmark Factory using Level 2 for the table sizing, which makes the table just at 1.8GB in size. All of the indexes on the table will be rebuilt using PAGE compression, and then 10,000 rows will be added to the table. To setup the environment, first load the TPC-H LineItem table with the appropriate seed of data, this can be done with the free trial version of Benchmark Factory. Then rebuild all of the indexes on the LineItem table using PAGE compression, and review the PAGE compression statistics from sys.dm_db_index_operational_stats for the database and object.

USE [TPCH]
GO
-- Rebuild the indexes with Page compression 
ALTER INDEX ALL ON dbo.H_Lineitem REBUILD WITH (DATA_COMPRESSION = PAGE)
GO
-- Look at the compression information in sys.dm_db_index_operational_stats
SELECT 
    database_id, 
    object_id, 
    index_id, 
    page_compression_attempt_count, 
    page_compression_success_count,
    (page_compression_attempt_count - page_compression_success_count) as page_compression_failure_count
FROM sys.dm_db_index_operational_stats(db_id('TPCH'), object_id('H_Lineitem'), null, null)
GO

Once the table and its indexes have been rebuilt using PAGE compression, we can then create our Event Session, start it, and add 10,000 rows to the LineItem table. After we add the rows, we can then check the page compression statistics in sys.dm_db_index_operational_stats, and drop our Event Session from the server.

-- Create an Event Session to Track the Failed attempts
CREATE EVENT SESSION PageCompressionTracing
ON SERVER
ADD EVENT sqlserver.page_compression_attempt_failed,
ADD EVENT sqlserver.page_compression_tracing
ADD TARGET package0.asynchronous_file_target(
     SET filename='C:\SQLBlog\PageCompressionTracing.xel',
         metadatafile='C:\SQLBlog\PageCompressionTracing.xem')
WITH (MAX_MEMORY = 8MB, EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS, MAX_DISPATCH_LATENCY=5SECONDS)
GO
-- Start the Event Session
ALTER EVENT SESSION PageCompressionTracing
ON SERVER
STATE=START
GO
-- Insert 10000 rows into the H_Lineitem table
INSERT INTO H_Lineitem
    (l_orderkey, l_partkey, l_suppkey, l_linenumber, l_quantity, 
     l_extendedprice, l_discount, l_tax, l_returnflag, l_linestatus, 
     l_shipdate, l_commitdate, l_receiptdate, l_shipinstruct, l_shipmode, 
     l_comment)
SELECT TOP 10000 
     l_orderkey, l_partkey, l_suppkey, l_linenumber, l_quantity, 
     l_extendedprice, l_discount, l_tax, l_returnflag, l_linestatus, 
     l_shipdate, l_commitdate, l_receiptdate, l_shipinstruct, l_shipmode, 
     l_comment
FROM H_Lineitem
GO
-- Look at the compression information in sys.dm_db_index_operational_stats
SELECT 
    database_id, 
    object_id, 
    index_id, 
    page_compression_attempt_count, 
    page_compression_success_count,
    (page_compression_attempt_count - page_compression_success_count) as page_compression_failure_count
FROM sys.dm_db_index_operational_stats(db_id('TPCH'), object_id('H_Lineitem'), null, null)
GO
-- Drop the Event Session
DROP EVENT SESSION PageCompressionTracing
ON SERVER
GO

Now we can parse the Events that were captured by our Event Session and compare the information presented by sys.dm_db_index_operational_stats() with what was collected by Extended Events.

-- Create our result Analysis database
CREATE DATABASE [PageCompTestResults]
GO
USE [PageCompTestResults]
GO
-- Create intermediate temp table for raw event data
CREATE TABLE RawEventData
(Rowid int identity primary key, event_data xml)
GO
-- Read the file data into intermediate temp table
INSERT INTO RawEventData (event_data)
SELECT
    CAST(event_data AS XML) AS event_data
FROM sys.fn_xe_file_target_read_file('C:\SQLBlog\PageCompressionTracing*.xel', 
                                     'C:\SQLBlog\PageCompressionTracing*.xem', 
                                     null, null)
GO
-- Fetch the Event Data from the Event Session Target
SELECT 
    RowID,
    event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,
    DATEADD(hh, 
            DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), 
            event_data.value('(event/@timestamp)[1]', 'datetime2')) AS [timestamp],
    COALESCE(event_data.value('(event/data[@name="database_id"]/value)[1]', 'int'), 
             event_data.value('(event/action[@name="database_id"]/value)[1]', 'int')) AS database_id,
    event_data.value('(event/data[@name="file_id"]/value)[1]', 'int') AS [file_id],
    event_data.value('(event/data[@name="page_id"]/value)[1]', 'int') AS [page_id],
    event_data.value('(event/data[@name="rowset_id"]/value)[1]', 'bigint') AS [rowset_id],
    event_data.value('(event/data[@name="failure_reason"]/text)[1]', 'nvarchar(150)') AS [failure_reason],
    event_data.value('(event/action[@name="system_thread_id"]/value)[1]', 'int') AS [system_thread_id],
    event_data.value('(event/action[@name="scheduler_id"]/value)[1]', 'int') AS [scheduler_id],
    event_data.value('(event/action[@name="cpu_id"]/value)[1]', 'int') AS [cpu_id]
INTO ParsedResults
FROM RawEventData
GO

After parsing out the data, we can begin to really leverage the information we’ve gathered. If we join the ParsedResults table to sys.partitions for our TPCH database by rowset_id = hobt_id, we can get the object_id and index_id and aggregate the failure reasons up to the object and index level.

SELECT 
    pr.database_id, 
    p.object_id, 
    p.index_id,
    failure_reason, 
    COUNT(*) as failure_count
FROM TPCH.sys.partitions p
JOIN ParsedResults pr
    ON pr.rowset_id = p.hobt_id
WHERE event_name = 'page_compression_attempt_failed'
GROUP BY     pr.database_id, 
    p.object_id, 
    p.index_id,
    failure_reason
GO
-- Look at the compression information in sys.dm_db_index_operational_stats
SELECT 
    database_id, 
    object_id, 
    index_id, 
    page_compression_attempt_count, 
    page_compression_success_count,
    (page_compression_attempt_count - page_compression_success_count) as page_compression_failure_count
FROM sys.dm_db_index_operational_stats(db_id('TPCH'), object_id('H_Lineitem'), null, null)
GO

With this we can se that the Extended Events sqlserver.page_compression_attempt_failed Event tracks failures and attempts that are not counted in sys.dm_db_index_operational_stats(). The PageModCountBelowThreshold failure isn’t really a failed attempt at compression. This reason shows that the page was evaluated for recalculation, and the modified counter for the page hadn’t passed the internal threshold for recalculation so the actual compression operation wasn’t performed. If we look at the sqlserver.page_compression_tracing Event information, we can see how the numbers begin to come together to match what is output by sys.dm_db_index_operational_stats().

SELECT 
    pr.database_id, 
    p.object_id, 
    p.index_id,
    COUNT(*) as attempt_count
FROM TPCH.sys.partitions p
JOIN ParsedResults pr
    ON pr.rowset_id = p.hobt_id
WHERE event_name = 'page_compression_tracing'
  AND opcode = 'Begin'
GROUP BY     pr.database_id, 
    p.object_id, 
    p.index_id
GO
-- Look at the compression information in sys.dm_db_index_operational_stats
SELECT 
    database_id, 
    object_id, 
    index_id, 
    page_compression_attempt_count, 
    page_compression_success_count,
    (page_compression_attempt_count - page_compression_success_count) as page_compression_failure_count
FROM sys.dm_db_index_operational_stats(db_id('TPCH'), object_id('H_Lineitem'), null, null)
GO

We have 193 attempts by this Event, and we have 72 PageModCountBelowThreshold failures, matching our actual attempts of 121 from the DMF. We can then subtract out the other failures and get the 93 successful operations matching the DMF as well.

An XEvent a Day (27 of 31) – The Future - Tracking Page Splits in SQL Server Denali CTP1

jmkehayias — Tue, 28 Dec 2010 02:00:00 GMT

Nearly two years ago Kalen Delaney blogged about Splitting a page into multiple pages, showing how page splits occur inside of SQL Server. Following her blog post, Michael Zilberstein wrote a post, Monitoring Page Splits with Extended Events, that showed how to see the sqlserver.page_split Events using Extended Events. Eladio Rincón also blogged about Using XEvents (Extended Events) in SQL Server 2008 to detect which queries are causing Page Splits, but not in relation to Kalen’s blog post. Both of these blog posts demonstrate how to get the sqlserver.page_split Events, but as discussed in the comments section of Michael Zilberstein’s blog post, the Event fires for all page splits and Adam Machanic and I talked after Eladio’s blog post and opened a connect item to have the sqlserver.page_split Event extended in the product so that you know what kind of split is actually occurring.

https://connect.microsoft.com/SQLServer/feedback/details/388482/sql-server-extended-events-page-split-event-additions

The CTP1 release of Denali has significant changes to the sqlserver.page_split Event, that makes it easier to find the splitting object as well the type of split that is occurring. Before we look at that, I am going to show the code required to get the object and index information from SQL Server 2008, which is based on Adam’s comments to use sys.dm_os_buffer_descriptors. For the examples in this blog post I am going use Kalen’s multipage split example from her blog post referenced above.

-- Create the table 
USE tempdb;
GO
SET NOCOUNT ON
GO
IF EXISTS (SELECT * FROM sys.tables
            WHERE name = 'split_page')
    DROP TABLE split_page;
GO
CREATE TABLE split_page 
(id INT IDENTITY(0,2) PRIMARY KEY,
id2 bigint DEFAULT 0,
data1 VARCHAR(33) NULL, 
data2 VARCHAR(8000) NULL);
GO

-- fill page until no more rows fit
INSERT INTO split_page DEFAULT VALUES;
GO 385

-- verify that there is only one data page 
DBCC IND(tempdb, split_page, -1);

-- Create MonitorPageSplits Extended Event Session 
IF (SELECT 1 FROM sys.server_event_sessions WHERE name = 'MonitorPageSplits') IS NOT NULL 
   DROP EVENT SESSION MonitorPageSplits ON SERVER 
GO 
CREATE EVENT SESSION MonitorPageSplits ON SERVER 
ADD EVENT sqlserver.page_split 
( 
    ACTION (sqlserver.database_id, sqlserver.sql_text)   
    WHERE sqlserver.database_id = 2 
) 
ADD TARGET package0.ring_buffer 
WITH(MAX_DISPATCH_LATENCY = 1 SECONDS)
GO 

-- Start the MonitorPageSplits Event Session 
ALTER EVENT SESSION MonitorPageSplits ON SERVER STATE = start; 
GO 

-- Now insert one more row, this time filling the VARCHARs to the maximum length. 
SET IDENTITY_INSERT split_page  ON;
GO
INSERT INTO split_page (id, id2, data1, data2)
      SELECT 111, 0, REPLICATE('a', 33), REPLICATE('b', 8000);
GO
SET IDENTITY_INSERT split_page  OFF;
GO 

ALTER EVENT SESSION MonitorPageSplits ON SERVER 
DROP EVENT sqlserver.page_split; 
GO 

-- Wait to allow dispatch to complete
WAITFOR DELAY '00:00:01.000' 
GO

SELECT oTab.*
  , p.OBJECT_ID
  , p.index_id
  , OBJECT_NAME(p.OBJECT_ID)
  , i.name

FROM
(
SELECT 
    XEvent            = XEvent.query('.') 
  , time              = XEvent.value('(@timestamp)[1]','datetime') 
  , FILE_ID           = XEvent.value('(data[@name=''file_id'']/value)[1]','int') 
  , page_id           = XEvent.value('(data[@name=''page_id'']/value)[1]','int') 
  , database_id       = XEvent.value('(action[@name=''database_id'']/value)[1]','int') 
  , sql_text          = XEvent.value('(action[@name=''sql_text'']/value)[1]','varchar(max)') 
FROM 
( 
   SELECT CAST(target_data AS XML) AS target_data 
   FROM sys.dm_xe_session_targets xst 
   JOIN sys.dm_xe_sessions xs ON xs.address = xst.event_session_address 
   WHERE xs.name = 'MonitorPageSplits' 
) AS tab (target_data) 
CROSS APPLY target_data.nodes('/RingBufferTarget/event') AS EventNodes(XEvent) 
) AS oTab
LEFT JOIN sys.dm_os_buffer_descriptors AS obd
   ON obd.database_id = oTab.database_id
       AND obd.FILE_ID = oTab.FILE_ID
       AND obd.page_id = oTab.page_id
LEFT JOIN sys.allocation_units au
   ON au.allocation_unit_id = obd.allocation_unit_id
LEFT JOIN sys.partitions p 
   ON p.partition_id = au.container_id  
LEFT JOIN sys.indexes i
   ON p.OBJECT_ID = i.OBJECT_ID
       AND p.index_id = i.index_id

-- verify that there is only one data page 
DBCC IND(tempdb, split_page, -1);

The above code creates a table in tempdb, loads one page of data in it exactly as in Kalen’s blog post, and then creates an Event Session for the sqlserver.page_split Event in tempdb, that also collects the sqlserver.database_id and sqlserver.sql_text actions when the Event fires. After triggering the page split, it drops the Event from the Event Session and then uses WAITFOR DELAY to allow the events to be buffered to the package0.ring_buffer Target. Then it shreds the XML and joins to the DMV’s to get the object and index names. The output of running the above script in SQL Server 2008 should be similar to the following, showing 10 split events and 10 additional pages in the database table.

Note that the only two columns returned by the sqlserver.page_split Event are the file_id and page_id. In SQL Server Denali CTP1, the sqlserver.page_split event now has a much larger Event payload associated with it. It now returns the file_id, page_id, database_id (as a part of the event, not requiring an action), rowset_id, splitOperation, new_page_file_id, and the new_page_page_id associated with the page_split Event. This makes the Event much more useful and allows it to be used without having to query the buffer descriptors to find the object association. The following demo is identical to the demo for SQL Server 2008 listed above with the exception of that the XQuery is slightly different (a requirement to pull the new information from the XML).

-- Create the table 
USE tempdb;
GO
SET NOCOUNT ON
GO
IF EXISTS (SELECT * FROM sys.tables
            WHERE name = 'split_page')
    DROP TABLE split_page;
GO
CREATE TABLE split_page 
(id INT IDENTITY(0,2) PRIMARY KEY,
id2 bigint DEFAULT 0,
data1 VARCHAR(33) NULL, 
data2 VARCHAR(8000) NULL);
GO

-- fill page until no more rows fit
INSERT INTO split_page DEFAULT VALUES;
GO 385

-- verify that there is only one data page 
DBCC IND(tempdb, split_page, -1);

-- Create MonitorPageSplits Extended Event Session 
IF (SELECT 1 FROM sys.server_event_sessions WHERE name = 'MonitorPageSplits') IS NOT NULL 
   DROP EVENT SESSION MonitorPageSplits ON SERVER 
GO 
CREATE EVENT SESSION MonitorPageSplits ON SERVER 
ADD EVENT sqlserver.page_split 
( 
    ACTION (sqlserver.database_id, sqlserver.sql_text)   
    WHERE sqlserver.database_id = 2 
) 
ADD TARGET package0.ring_buffer 
WITH (MAX_DISPATCH_LATENCY = 1 SECONDS)
GO 

-- Start the MonitorPageSplits Event Session 
ALTER EVENT SESSION MonitorPageSplits ON SERVER STATE = start; 
GO 

-- Now insert one more row, this time filling the VARCHARs to the maximum length. 
SET IDENTITY_INSERT split_page  ON;
GO
INSERT INTO split_page (id, id2, data1, data2)
      SELECT 111, 0, REPLICATE('a', 33), REPLICATE('b', 8000);
GO
SET IDENTITY_INSERT split_page  OFF;
GO 

ALTER EVENT SESSION MonitorPageSplits ON SERVER 
DROP EVENT sqlserver.page_split; 

GO

SELECT 
    event_time         = XEvent.value('(@timestamp)[1]','datetime') 
  , orig_file_id      = XEvent.value('(data[@name=''file_id'']/value)[1]','int') 
  , orig_page_id      = XEvent.value('(data[@name=''page_id'']/value)[1]','int') 
  , database_id           = XEvent.value('(data[@name=''database_id'']/value)[1]','int') 
  , OBJECT_ID         = p.OBJECT_ID
  , index_id          = p.index_id
  , OBJECT_NAME           = OBJECT_NAME(p.OBJECT_ID)
  , index_name            = i.name
  , rowset_id         = XEvent.value('(data[@name=''rowset_id'']/value)[1]','bigint') 
  , splitOperation        = XEvent.value('(data[@name=''splitOperation'']/text)[1]','varchar(255)') 
  , new_page_file_id  = XEvent.value('(data[@name=''new_page_file_id'']/value)[1]','int') 
  , new_page_page_id  = XEvent.value('(data[@name=''new_page_page_id'']/value)[1]','int') 
  , sql_text          = XEvent.value('(action[@name=''sql_text'']/value)[1]','varchar(max)') 
FROM 
( 
   SELECT CAST(target_data AS XML) AS target_data 
   FROM sys.dm_xe_session_targets xst 
   JOIN sys.dm_xe_sessions xs ON xs.address = xst.event_session_address 
   WHERE xs.name = 'MonitorPageSplits' 
) AS tab (target_data) 
CROSS APPLY target_data.nodes('/RingBufferTarget/event') AS EventNodes(XEvent) 
LEFT JOIN sys.allocation_units au
   ON au.container_id = XEvent.value('(data[@name=''rowset_id'']/value)[1]','bigint') 
LEFT JOIN sys.partitions p 
   ON p.partition_id = au.container_id  
LEFT JOIN sys.indexes i
   ON p.OBJECT_ID = i.OBJECT_ID
       AND p.index_id = i.index_id

-- View the Page allocations 
DBCC IND(tempdb, split_page, -1);

If you run the above demo the output should be similar to the below (if you click on the picture, it will open up larger). One thing that should become immediately obvious is that the same demo in Denali is doing 1/3rd of the page splits that occur in SQL Server 2008.

The old_page_id and new_page_id tell where the page originated and moved to, and the splitOperation tells the type of split. In this case only two of the type of splits are occurring; SPLIT_FOR_ROOT_NODE which occurs when the first page allocated is split into multiple pages, and SPLIT_FOR_INSERT which occurs as the inserts continue and the pages are split to accommodate the data. There are a number of additional split operations that exist in SQL Server Denali CTP1 including, SPLIT_FOR_DELETE, SPLIT_FOR_GHOST, SPLIT_FOR_INTERNAL_NODE, and SPLIT_FOR_UPDATE. I’ve tried to figure out how to correlate the output from DBCC IND with the data held in the Event Session for page splits to correlate the old_page_id and new_page_id to identify problematic splits, but haven’t finalized validation of my tests yet (hopefully I can finish this work and I’ll write an update to this blog post showing how to do this at some point in the near future). One item that I have noted in my testing is that mid-page splits generally generate multiple sqlserver.page_split Events in the same operation, similar to the demonstrations used in this example, where as end-page splits for identity and sequential GUID inserts do not. I am not certain that this is a valid conclusion to come to at this point and have further testing to do to investigate page splits more.

An XEvent a Day (26 of 31) – Configuring Session Options

jmkehayias — Mon, 27 Dec 2010 02:00:00 GMT

There are 7 Session level options that can be configured in Extended Events that affect the way an Event Session operates. These options can impact performance and should be considered when configuring an Event Session. I have made use of a few of these periodically throughout this months blog posts, and in today’s blog post I’ll cover each of the options separately, and provide further information about their usage. Mike Wachal from the Extended Events team at Microsoft, talked about the Session options on his blog post, Option Trading: Getting the most out of the event session options, and I’d recommend giving it a read for additional information as well.

EVENT_RETENTION_MODE

The EVENT_RETENTION_MODE option specifies how the Event Session handles Event loss when Events generate faster than they can be dispatched to the Targets. There are three possible values for this option; ALLOW_SINGLE_EVENT_LOSS, ALLOW_MULTIPLE_EVENT_LOSS, and NO_EVENT_LOSS. This option directly affects the possible impact that an Event Session may have on the performance of a system while the Event Session is active. A trade off occurs between performance impact and the guarantee whether all Events are captured or not.

ALLOW_SINGLE_EVENT_LOSS

The ALLOW_SINGLE_EVENT_LOSS value is the system default for all Event Sessions where the EVENT_RETENTION_MODE is not explicitly specified as a part of the Event Session definition. This value allows single events to be dropped and lost from the session when the memory buffers for the Event Session are full and dispatch to the Targets can not keep up with the Event generation.

ALLOW_MULTIPLE_EVENT_LOSS

The ALLOW_MULTIPLE_EVENT_LOSS value allows an entire memory buffer containing multiple events to be dropped and lost when the memory buffers are full and the Events are generating faster than the buffers can be dispatched to the Targets. This can minimize the performance impact on the server at the trade off that many Events could potentially be lost, with the number of Events lost depending on the size of the Events being generated, the configuration of the MAX_MEMORY session option, and the MEMORY_PARTITION_MODE session option.

NO_EVENT_LOSS

The NO_EVENT_LOSS value guarantees that all Events that fire are captured, but at the expense of possible system performance degradation when the Event Session is active. If the memory buffers are all full and an Event fires, the task firing the Event will wait until space is available in a memory buffer for the Event to be buffered. This option value is not recommended by the Extended Events team at Microsoft for most Event Sessions and should be used with extreme caution and only when it is absolutely necessary that every Event be captured, even at the expense of degraded performance of the system.

MAX_DISPATCH_LATENCY

The MAX_DISPATCH_LATENCY option specifies the time in seconds that Events are held in a memory buffer that is not full before being dispatched to the asynchronous session Targets. The default value if the MAX_DISPATCH_LATENCY is not explicitly defined in the Session definition is 30 seconds, and the option has a minimum value of 1 second. If a value of 0 or INFINITE is specified, the Events held in a memory buffer will not be dispatched until the memory buffer becomes full.

MAX_EVENT_SIZE

The MAX_EVENT_SIZE option specifies the maximum size in kilobytes or megabytes an individual Event can be. The default value for this option when it is not explicitly set in the Session definition is 0KB, allowing the maximum Event size to be the size of a single memory buffer in the Event Session. This option can be explicitly set to allow Events that are larger than a single memory buffer to be captured by the Event Session. The minimum value for this option is 64KB.

MAX_MEMORY

The MAX_MEMORY option specifies the amount of memory in kilobytes or megabytes that is allocated to the memory buffers for the Event Session. The value of this options is divided evenly amongst the memory buffers that are created for the Event Session based on the configuration of the MEMORY_PARTITION_MODE session option. The MAX_MEMORY option can be used to increase the memory available for buffering Events when a large number of Events are expected to fire, minimizing Event loss due to full memory buffers. The default value for this option is 4 megabytes (MB) or 4096 kilobytes (KB).

Mike Wachal blogged about this option on the Extended Events blog Take it to the MAX (and beyond), and again in response to a number of questions that I sent him early on in this blog series when I was working on a large NUMA based server, Session memory – who’s this guy named Max and what’s he doing with my memory?

MEMORY_PARTITION_MODE

The MEMORY_PARTITION_MODE option specifies how the memory buffers for the Event Session are created and/or partitioned. For servers with multiple processors and/or multiple NUMA nodes the memory buffers can become a bottleneck performance wise if multiple CPU’s are firing Events and have to wait on a memory buffer to buffer the Event information being collected. There are three values for this option; NONE, PER_NODE, and PER_CPU.

NONE

The NONE value specifies that a single set of memory buffers will be created for the Event Session. In this configuration, three memory buffers are created for the Event Session, and the memory for the Event Session is divided evenly, to the nearest 64KB boundary, amongst the three memory buffers. This is the default value for an Event Session if the MEMORY_PARTITION_MODE is not explicitly defined.

PER_NODE

The PER_NODE value specifies that a separate set of three memory buffers will be created. In this configuration, three memory buffers are created for each NUMA node that exists for the SQL Server Instance, and the memory is divided evenly, to the nearest 64KB boundary, amongst all of the memory buffers.

PER_CPU

The PER_CPU value specifies that a set of memory buffers is created for each CPUs/Scheduler that is assigned to the SQL Server Instance. In this configuration, the number of memory buffers is 2.5 times the number of CPUs/Schedulers available, and the memory is divided evenly, to the nearest 64KB boundary, amongst all of the memory buffers.

STARTUP_STATE

The STARTUP_STATE option specifies whether an Event Session automatically starts in an Active state when the SQL Server Instance starts up. There are two valid values for this option, ON and OFF, with OFF being the default.

TRACK_CAUSALITY

The TRACK_CAUSALITY option specifies whether causality tracking across multiple Events is turned ON or OFF. The default configuration for this option is OFF. When TRACK_CAUSALITY is turned on, an additional Action, package0.attach_activity_id, is added to each Event that fires in the Event Session. This Action is a combination GUID and sequence number that allows related Events to be tracked for cause and effect analysis of the Events that fired in the order in which they have fired.

I should make note of the fact that in many cases, the options specified in the blog posts, may not be appropriate for a production implementation, and may have been made based on the fact that I just didn’t want to wait over multiple test cycles for Events to dispatch to the Targets.

An XEvent a Day (25 of 31) – The Twelve Days of Christmas

jmkehayias — Sat, 25 Dec 2010 14:00:00 GMT

Correction: I mistakenly stated that Tim Mitchel had blogged the 12 days of SQL Christmas, and was informed that Tim Ford is who wrote that blog post. My sincerest apologies to Tim and Tim for the mix up. The post has been corrected below.

In the spirit of today’s holiday, a couple of people have been posting SQL related renditions of holiday songs. Tim Ford posted his 12 days of SQL Christmas, and Paul Randal and Kimberly Tripp went as far as to record themselves sing SQL Carols on their blog post Our Christmas Gift To You: Paul and Kimberly Singing! For today’s post on Extended Events I give you the 12 days of Christmas, Extended Events style (all of these are based on true facts about Extended Events in SQL Server).

On the first day of Christmas Extended Events gave to me: a chance to write a useful GUI.
On the second day of Christmas Extended Events gave to me: two sqlserver packages.
On the third day of Christmas Extended Events gave to me: three new DDL Commands.
On the fourth day of Christmas Extended Events gave to me: four ETW channels.
On the fifth day of Christmas Extended Events gave to me: five in-memory targets.
On the sixth day of Christmas Extended Events gave to me: six keyword maps.
On the seventh day of Christmas Extended Events gave to me: seven session options.
On the eighth day of Christmas Extended Events gave to me: eight file io events.
On the ninth day of Christmas Extended Events gave to me: nine database_log events.
On the tenth day of Christmas Extended Events gave to me: ten new DMV’s.
On the eleventh day of Christmas Extended Events gave to me: eleven Operational events.
On the twelfth day of Christmas Extended Events gave to me: twelve sqlos Actions.

An XEvent a Day (24 of 31) – What is the package0.callstack Action?

jmkehayias — Sat, 25 Dec 2010 02:00:00 GMT

One of the actions inside of Extended Events is the package0.callstack and the only description provided by sys.dm_xe_objects for the object is 16-frame call stack. If you look back at The system_health Session blog post, you’ll notice that the package0.callstack Action has been added to a number of the Events that the PSS team thought were of significance to include in the Event Session. We can trigger an event that will by logged by our system_health Event Session by raising an error of severity >=20 with the RAISERROR functionality in TSQL.

-- Generate a Severity 20 Error to trigger system_health
-- sqlserver.error_reported Event
RAISERROR(50001, 20, 1, 'This is an Error!') WITH LOG

After raising the error, we can query the system_health Event Session for the callstacks that have been collected by adding into our XQuery a filter for the action node with the @name attribute = “callstack”

SELECT n.query('.') AS callstack
FROM
(
    SELECT CAST(target_data as xml)
    FROM sys.dm_xe_sessions AS s 
    INNER JOIN sys.dm_xe_session_targets AS t
        ON s.address = t.event_session_address
    WHERE s.name = 'system_health'
      AND t.target_name = 'ring_buffer'
) AS src (target_data)
CROSS APPLY target_data.nodes('RingBufferTarget/event/action[@name="callstack"]') as q(n)

This will only return the action nodes for the callstack and the XML fragment will be similar to the following:

    <action name="callstack" package="package0">
      <type name="callstack" package="package0" />
      <value>0x0000000001CD4F55
0x000000000113A310
0x0000000000BEA7D0
0x0000000001A3A0CC
0x0000000002FA3EAE
0x0000000000BC9616
0x0000000000BCABBB
0x0000000000BCA4D9
0x0000000000BCD10B
0x0000000000BC7C9B
0x0000000000B6163B
0x0000000000B612FA
0x0000000000B60E35
0x00000000010E0E50
0x00000000010E09A0
0x00000000010F9AB0</value>
      <text />
    </action>

So what is it about this information that would make it important enough to collect? The callstack provides the most recent 16 frames inside of the sqlservr process. If you create a dump file of the sqlservr process using sqldumper.exe, you canopen the mdmp file up in windbg, load the public symbols for sql Server, and then walk the stack with the ln <stack address> command. For example the above callstack resolves in windbg as:

(00000000`01cd4f10)   sqlservr!GenericEvent::CallNextAction+0x45   | (00000000`01cd5000)   sqlservr!AutoSpinlockHolder<170,1,1>::~AutoSpinlockHolder<170,1,1>
(00000000`00b78be0)   sqlservr!_chkstk+0xf276c   | (00000000`00b78c30)   sqlservr!IsWorktableRowset
(00000000`00bea640)   sqlservr!ErrorReportedAutoPublish::Publish+0x190   | (00000000`00bea820)   sqlservr!CErrorReportingManager::CwchCallFormatMessage
(00000000`00b78be0)   sqlservr!_chkstk+0x1bd96d   | (00000000`00b78c30)   sqlservr!IsWorktableRowset
(00000000`02fa3800)   sqlservr!CXStmtError::XretExecute+0x6ae   | (00000000`02fa44b0)   sqlservr!CStmtDbcc::XretExecute
(00000000`00bc8f80)   sqlservr!CMsqlExecContext::ExecuteStmts<1,1>+0x55a   | (00000000`00bc9e30)   sqlservr!CSessionTaskProxy::AddRef
(00000000`00bca630)   sqlservr!CMsqlExecContext::FExecute+0x58b   | (00000000`00bcad60)   sqlservr!CExecParamTblHelperForExecParamTable::`vftable'
(00000000`00bca1c0)   sqlservr!CSQLSource::Execute+0x319   | (00000000`00bca630)   sqlservr!CMsqlExecContext::FExecute
(00000000`00bcd1a0)   sqlservr!process_request+0x370   | (00000000`00bcd6c0)   sqlservr!CAutoSetupCXCtxtS::~CAutoSetupCXCtxtS
(00000000`00bc7990)   sqlservr!process_commands+0x2b2   | (00000000`00bc7c10)   sqlservr!CConnection::PNetConn
(00000000`00b61520)   sqlservr!SOS_Task::Param::Execute+0x11b   | (00000000`00b616f0)   sqlservr!Worker::Reset
(00000000`00b61230)   sqlservr!SOS_Scheduler::RunTask+0xca   | (00000000`00b61520)   sqlservr!SOS_Task::Param::Execute
(00000000`00b60da0)   sqlservr!SOS_Scheduler::ProcessTasks+0x95   | (00000000`00b61090)   sqlservr!WorkDispatcher::DequeueTask
(00000000`010e0d40)   sqlservr!SchedulerManager::WorkerEntryPoint+0x110   | (00000000`010e0ea0)   sqlservr!SOSQueueCounted<Worker,0>::Dequeue
(00000000`010e0940)   sqlservr!SystemThread::RunWorker+0x60   | (00000000`010e0a10)   sqlservr!SchedulerManager::AcquireWorker
(00000000`010f9980)   sqlservr!SystemThreadDispatcher::ProcessWorker+0x12c   | (00000000`010f9b00)   sqlservr!SEList<SystemThread,112>::Head

This information isn’t really of much use unless you have access to or understand the SQL Server Source code. In the event that you have an issue, the PSS team can create a memory dump of the process, collect the output from the ring_buffer target, and walk the stack to see what lead to the Event firing.

It is possible to materialize the stack without having to actually perform a memory dump and without using windbg. In the SQLCAT team blog post Resolving DTC Related Waits and Tuning Scalability of DTC, Trace Flag 3656 is documented as materializing the callstack if the sqlservr.pdb symbols file exists in the same directory as sqlservr.exe.

NOTE: There is a reason that this functionality is not turned on by default in SQL Server. It is not recommended that you enable this Trace Flag on a production server unless directed to do so by PSS as a part of a support case. This Trace Flag can impact performance and should not be used lightly.

In SQL Server 2008, the symbols file is not included by default in the product. To get the symbols file, you can use windbg and a memory dump. For steps on how to do this, see http://blogs.msdn.com/b/askjay/archive/2009/12/29/basic-debugging-concepts-and-setup.aspx. Once you open the memory dump file for the first time, the symbols are downloaded from the public symbols server and placed in the .sympath specified, in the case of the blog post mentioned it will be C:\symbols\public\sq\sqlservr.pdb\1E7168D2F78B4FBA911F507689D7DE902. After copying the pdb to the Binn folder for the SQL instance, by default C:\Program Files\Microsoft SQL Server\MSSQL10.MSSQLSERVER\MSSQL\Binn, we can turn on the trace flag and requery our Event Session.

--Trace flag 3656 enables the call stacks to be resolved.  This requires that the 
--sqlservr.pdb file reside in the same directory as sqlservr.exe
DBCC TRACEON (3656, -1)  
GO
SELECT n.query('.') AS callstack
FROM
(
    SELECT CAST(target_data as xml)
    FROM sys.dm_xe_sessions AS s 
    INNER JOIN sys.dm_xe_session_targets AS t
        ON s.address = t.event_session_address
    WHERE s.name = 'system_health'
      AND t.target_name = 'ring_buffer'
) AS src (target_data)
CROSS APPLY target_data.nodes('RingBufferTarget/event/action[@name="callstack"]') as q(n)

The output of our callstack action is now:

<action name="callstack" package="package0">
  <type name="callstack" package="package0" />
  <value>GenericEvent::CallNextAction+45 [ @ 0+0x0
_chkstk+f276c [ @ 0+0x0
ErrorReportedAutoPublish::Publish+190 [ @ 0+0x0
_chkstk+1bd96d [ @ 0+0x0
CXStmtError::XretExecute+6ae [ @ 0+0x0
CMsqlExecContext::ExecuteStmts&lt;1,1&gt;+55a [ @ 0+0x0
CMsqlExecContext::FExecute+58b [ @ 0+0x0
CSQLSource::Execute+319 [ @ 0+0x0
process_request+370 [ @ 0+0x0
process_commands+2b2 [ @ 0+0x0
SOS_Task::Param::Execute+11b [ @ 0+0x0
SOS_Scheduler::RunTask+ca [ @ 0+0x0
SOS_Scheduler::ProcessTasks+95 [ @ 0+0x0
SchedulerManager::WorkerEntryPoint+110 [ @ 0+0x0
SystemThread::RunWorker+60 [ @ 0+0x0
SystemThreadDispatcher::ProcessWorker+12c [ @ 0+0x0</value>
  <text />
</action>

If you note, these match up to the stack output from windbg. If you are interested in trying to figure out the internal stack of SQL Server, the package0.callstack event can certainly be useful, but in general it is not something that you will get much use of in general troubleshooting with Extended Events.

An XEvent a Day (23 of 31) – How it Works – Multiple Transaction Log Files

jmkehayias — Thu, 23 Dec 2010 19:48:54 GMT

While working on yesterday’s blog post The Future – fn_dblog() No More? Tracking Transaction Log Activity in Denali I did a quick Google search to find a specific blog post by Paul Randal to use it as a reference, and in the results returned another blog post titled, Investigating Multiple Transaction Log Files in SQL Server caught my eye so I opened it in a new tab in IE and went about finishing the blog post. It probably wouldn’t have gotten my attention if it hadn’t been on the SqlServerPedia site. When I was finished I went back and read through the post, and I found that some of the information presented in it was incorrect, so I attempted to post a comment, and not surprisingly the blog had moderation controls turned on, I have it turned on here if you aren’t a SQLBlog member so I don’t have a problem with that necessarily, and the comment didn’t show up on the site.

Interestingly enough, yesterday SQL Server Central had an editorial by Tim Mitchell titled Calling Out Bad Advice that discussed the problem of bad information on the internet and how to go about calling people out for publishing bad advice. Lets face it, people are human, at least I am, and mistakes happen from time to time, either through our own misunderstandings of our personal experiences and what we perceived from the information we had, or by shear accident in some cases. This afternoon I got an email back from the blog post author and we traded a few emails about the post, and in the end the author made changes to the original post which have been syndicated to SQLServerPedia already, so to see the original you have do something like look at the Google Cached Copy. The author also posted a follow up blog post today on the subject.

So why this blog post? Well even with the corrections, some of the conclusions are still wrong.

I am not trying to knock this guy for what he saw or perceived from the information he collected, but 2, 3 and 4 are still incorrect. What’s great is we can prove this by using Extended Events in SQL Server 2008 and that is what the real purpose behind this blog post is. To set things up, we first need to create a database that roughly matches the available information shown in the pictures of the original blog post. The database will have a single database file, that I am sizing initially at 128MB and will have a fixed autogrowth value of 64MB. The database will have four log files that are initially sized at 1MB each, and the first log file will have a fixed autogrowth value of 32MB, with the last three transaction log files having fixed growth values of just 1MB. Don’t comment on this configuration, I understand completely that there is no reason to create multiple log files on the same disk array (half the purpose behind this post is to show that there is benefit to having multiple log files like this, which is also the intended purpose behind the original blog post as well), and I wouldn’t do this in production, but it works perfectly for the tests that we are about to run. Once the database is created, we’ll switch to that database, and dump out the transaction log VLF information using DBCC LOGINFO.

-- Create our Test database with
--        1 data file sized at 128MB with 64MB autogrowth
--        1 log file sized at 1MB with 32MB autogrowth
--        3 log files sized at 1MB with 1MB autogrowth
CREATE DATABASE [Test] ON  
PRIMARY 
    (    
        NAME = N'Test', 
        FILENAME = N'D:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\DATA\Test.mdf', 
        SIZE = 131072KB, 
        FILEGROWTH = 65536KB
    )
LOG ON 
    (    
        NAME = N'Test_log', 
        FILENAME = N'L:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\DATA\Test_log.ldf', 
        SIZE = 1024KB, 
        MAXSIZE = 131072KB, 
        FILEGROWTH = 32768KB
    ), 
    (    
        NAME = N'Test_log2',     
        FILENAME = N'L:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\DATA\Test_log2.ldf', 
        SIZE = 1024KB, 
        MAXSIZE = 131072KB, 
        FILEGROWTH = 1024KB 
    ), 
    ( 
        NAME = N'Test_log3', 
        FILENAME = N'L:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\DATA\Test_log3.ldf', 
        SIZE = 1024KB, 
        MAXSIZE = 131072KB, 
        FILEGROWTH = 1024KB 
    ), 
    ( 
        NAME = N'Test_log4', 
        FILENAME = N'L:\SQLData\MSSQL10.MSSQLSERVER\MSSQL\DATA\Test_log4.ldf', 
        SIZE = 1024KB, 
        MAXSIZE = 131072KB, 
        FILEGROWTH = 1024KB 
    )
GO
-- Switch to our Test database
USE [Test]
GO
-- Dump the VLF Usage information
DBCC LOGINFO
GO

Each of the log files VLF’s have been highlighted in a different color above to point out the separation of the four different files. Note that the active VLF is in the first log file, FileId=2, as shown by the Status=2. With our test database created, we can now set out to create the Extended Events Event Session that:

The transaction logs are written to sequentially starting with the first VLF in FileId=2 and then when the last VLF in FileId=2 is full, the log begins writing log records to the first VLF of FileId=3 and when the last VLF in FileId=3 is full, the log begins writing log records to the first VLF of FileId=4 and when the last VLF in FileId=4 is full, the log begins writing log records to the first VLF of FileId=5 and when the last VLF in FileId=5 is full, the log circles back to the first VLF of FileId=2 which will still be active because we are going to work within a single explicit transaction for the duration of the test. Since the file is full it has to be grown, and because it has a growth factor of 32MB it grows by 32MB and begins writing log records to the first VLF of the newly allocated space.
The writes to the log files do not happen at the same time, they occur sequentially as the engine writes log records into each file, filling the VLF’s and has to move to the next file, or circle back to the beginning of the log when it reaches the end of the last log file.
Whatever results were seen in the original thread by opening the log file with Apex tools were incorrect and misleading to the original poster, since log files were actually written to all of the files during the operation. I have a couple of theories as to what could have happened that made the Apex tool show no log records that I will discuss later in this thread.

What Events would we want to capture to look at what is happening in our transaction log files when running the same workload from the original post? Since we are going to be executing a number of statements, the sqlserver.sql_statement_starting and sqlserver.sql_statement_completed Events seem like a good starting point, and since we want to know what statement was executing, we’ll add the sql_text Action to these Events. Since we are dealing with the transaction log files, the sqlserver.databases_log_file_size_changed, sqlserver.databases_log_file_used_size_changed, sqlserver.databases_log_flush_wait, sqlserver.databases_log_flush, sqlserver.databases_log_growth, and sqlserver.databases_log_truncation Events should probably be included to so we can track what’s going on with our log specifically, and to ensure that these Events only fire for our test database, we’ll dynamically build in a Predicate on the sqlserver.database_id Predicate source using the output of DB_ID() inside the testing database.

Since the log is a file, we also will want to collect the file operation related events such as sqlserver.flush_file_buffers, sqlserver.file_read, sqlserver.file_written, sqlserver.file_read_completed, and sqlserver.file_write_completed, and we’ll dynamically set a database_id Predicate on these Events as well. If you recall back to Friday of last week, I talked about a number of trace flags that provide further information about Backup, Restore and file operations in my blog post A Look at Backup Internals and How to Track Backup and Restore Throughput (Part 1). One of those was Trace Flag 3004, which writes file zeroing information to the trace print output whenever a zeroing operation occurs. I previously used this trace flag in my blog post Does the tempdb Log file get Zero Initialized at Startup? Since the log files grew in the original tests, we can turn this trace flag on to track the file growths, and use the sqlserver.trace_print Event to capture the file operation messages, and to keep this Event focused to our tests only, we’ll dynamically set a Predicate for the current session_id using the sqlserver.session_id Predicate Source and the output of @@SPID. Finally since this is all happening inside of an explicit transaction, we’ll also capture the sqlserver.database_transaction_begin and sqlserver.database_transaction_end events for the current database_id.

We have quite a large list of Events associated with this Event Session, and to ensure that we can perform analysis over all of the Event data from our tests, we’ll use the package0.asynchronous_file_target to hold our Event information. We’ll also increase our buffer memory from the default 4MB to 8MB and set the Event Session up to ALLOW_SINGLE_EVENT_LOSS, which does exactly what it sounds like it does, and to correlate cause and effect we’ll also turn TRACK_CAUSALITY to ON for the session.

-- Create our Event Session dynamically
DECLARE @sqlcmd nvarchar(2000) = '
CREATE EVENT SESSION TransactionLogUsage
ON SERVER
--ADD EVENT sqlserver.sql_statement_starting
--( ACTION(sqlserver.sql_text)
--  WHERE (sqlserver.database_id = '+ cast(DB_ID() as varchar(3))+')),
--ADD EVENT sqlserver.sql_statement_completed
--( ACTION(sqlserver.sql_text)
--  WHERE (sqlserver.database_id = '+ cast(DB_ID() as varchar(3))+')),
ADD EVENT sqlserver.databases_log_file_size_changed
( WHERE (sqlserver.database_id = '+ cast(DB_ID() as varchar(3))+')),
ADD EVENT sqlserver.databases_log_file_used_size_changed
( WHERE (sqlserver.database_id = '+ cast(DB_ID() as varchar(3))+')),
ADD EVENT sqlserver.databases_log_flush_wait
( WHERE (sqlserver.database_id = '+ cast(DB_ID() as varchar(3))+')),
ADD EVENT sqlserver.databases_log_flush
( WHERE (sqlserver.database_id = '+ cast(DB_ID() as varchar(3))+')),
ADD EVENT sqlserver.databases_log_growth
( WHERE (sqlserver.database_id = '+ cast(DB_ID() as varchar(3))+')),
ADD EVENT sqlserver.databases_log_truncation
( WHERE (sqlserver.database_id = '+ cast(DB_ID() as varchar(3))+')),
ADD EVENT sqlserver.flush_file_buffers
( WHERE (sqlserver.database_id = '+ cast(DB_ID() as varchar(3))+')),
ADD EVENT sqlserver.file_read
( WHERE (sqlserver.database_id = '+ cast(DB_ID() as varchar(3))+')),
ADD EVENT sqlserver.file_written
( WHERE (sqlserver.database_id = '+ cast(DB_ID() as varchar(3))+')),
ADD EVENT sqlserver.file_read_completed
( WHERE (sqlserver.database_id = '+ cast(DB_ID() as varchar(3))+')),
ADD EVENT sqlserver.file_write_completed
( WHERE (sqlserver.database_id = '+ cast(DB_ID() as varchar(3))+')),
ADD EVENT sqlserver.trace_print
(   WHERE (sqlserver.session_id = '+ cast(@@SPID as varchar(4))+')),
ADD EVENT sqlserver.database_transaction_begin
( WHERE (sqlserver.database_id = '+ cast(DB_ID() as varchar(3))+')),
ADD EVENT sqlserver.database_transaction_end
( WHERE (sqlserver.database_id = '+ cast(DB_ID() as varchar(3))+'))
ADD TARGET package0.asynchronous_file_target(
     SET filename=''C:\SQLBlog\TransactionLogUsage.xel'',
         metadatafile=''C:\SQLBlog\TransactionLogUsage.xem'')
WITH (MAX_MEMORY = 8MB, EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS, TRACK_CAUSALITY = ON )'
EXEC (@sqlcmd)
GO

If you notice above, I have commented out the sqlserver.sql_statement_starting and sqlserver.sql_statement_completed Events in the Event Session. It turns out that these two events are not needed in the Event Session to prove the points being made in this blog post. Including these two events makes the time to process the 240K+ Events run in the 10-15 minute range on my 16 core test server, so its not likely something that you are going to do on a laptop VM, but they were included in my initial Event Session for this, and I wanted to show the thought process I followed to get from A to B and ultimately C.

With our Event Session created, we can finish setting up our environment to run the actual tests. To do this we’ll create a table named LogTable with two columns that are, as best as I can tell from the limited information provided about the test table, the same as the table used in the original post. We’ll then CHECKPOINT the database to cause log truncation to occur (you did create the database in SIMPLE recovery right?), turn on Trace Flag 3004 for our session, and then start the Event Session so that it collects the data from our Events during our test.

-- Create our Test Table
CREATE TABLE LogTable (RowID decimal(10,4), Data char(1024))
GO
-- Checkpoint the database to truncate and clear the log.
CHECKPOINT
GO
-- Turn on Trace Flag 3004 so we can see file zeroing ops.
DBCC TRACEON(3004)
GO
-- Start the Event Session
ALTER EVENT SESSION TransactionLogUsage
ON SERVER
STATE=START
GO

With the Event Session started and all our setup work completed we can now run the test script that was used in the original post to generate our test workload. When the tests complete, we’ll dump out our VLF information again with DBCC LOGINFO, then ROLLBACK the transaction, switch to master and DROP our test database and the Extended Events Session from the server since they are no longer needed.

-- Run our tests
SET NOCOUNT ON

DECLARE @cnt decimal(10,4)=0
DECLARE @rows int=0
BEGIN TRAN
WHILE 1=1
BEGIN
    INSERT INTO LogTable VALUES (ROUND((RAND()* 1000000),0), SPACE(1024))
    
    SELECT @rows+=1
        
    SELECT @cnt = (size * 1.0 * 8.0)/1024.0 
    FROM  Test.sys.database_files
    WHERE data_space_id = 0
    AND [FILE_ID]=5
    
    IF @cnt>1.0
            BREAK
END

SELECT @rows;
GO
-- Pull Log VLF usage again
DBCC LOGINFO
GO
-- Rollback our transaction
ROLLBACK
GO
USE master
GO
-- Kill any connection to Test database
ALTER DATABASE [Test] SET SINGLE_USER WITH ROLLBACK IMMEDIATE;
GO
-- Drop the Test database
DROP DATABASE [Test]
GO
-- Drop the Event Session
DROP EVENT SESSION TransactionLogUsage
ON SERVER
GO

There is a reason that I dump out the VLF information before performing the ROLLBACK of the transaction. As long as the transaction remains active, the VLF’s containing the active transaction can not be truncated and cleared. In order to see the allocated VLF’s, we need the transaction active still. Once again, I have highlighted each of the individual log files separately, and from the DBCC LOGINFO output we can look at the FileId and Status columns and see that our transaction log wrote information into all 4 of the files, filling them, and the wrapped back to the first file which had to be grown, and each of the subsequent log files were also grown by the database engine. However, if you look at the CreateLSN information for the growth portion of each log file, you will notice that each file has its own Create LSN value for the second set of VLF’s, meaning that they were grown separately and at different times. Still not convinced by DBCC LOGINFO? Well we have the data to validate this and prove it unequivocally, but before we can look at the data, we need to retrieve it from the asynchronous_file_target files and shred the XML using XQuery.

-- Create our Analysis Database
CREATE DATABASE TLogUsageTestResults
GO
-- Switch to our Analysis Database
USE [TLogUsageTestResults]
GO
-- Create intermediate temp table for raw event data
CREATE TABLE RawEventData
(Rowid int identity primary key, event_data xml)

-- Create final results table for parsed event data
CREATE TABLE TestResults
([Rowid] int primary key, [event_name] varchar(50), [package_name] varchar(50),
 [timestamp] datetime2, [count] bigint, [increment] bigint, [database_id] int, 
 [mode] nvarchar(4000), [file_handle] nvarchar(4000), [offset] bigint, 
 [file_id] int, [file_group_id] int, [path] nvarchar(4000), [duration] bigint, 
 [io_data] nvarchar(4000), [succeeded] nvarchar(4000), [sql_text] nvarchar(4000), 
 [trace_message] nvarchar(4000), [source_database_id] int, [object_id] int, 
 [object_type] int, [cpu] int, [reads] bigint, [writes] bigint, 
 [state] nvarchar(4000), [offset_end] int, [nest_level] int, 
 [activity_id] uniqueidentifier, [event_sequence] int )

-- Read the file data into intermediate temp table
INSERT INTO RawEventData (event_data)
SELECT
    CAST(event_data AS XML) AS event_data
FROM sys.fn_xe_file_target_read_file('C:\SQLBlog\TransactionLogUsage*.xel', 
                                     'C:\SQLBlog\TransactionLogUsage*.xem', 
                                     null, null)

-- Query the Event data from the Target.
INSERT INTO TestResults
([Rowid], [event_name], [timestamp], [database_id], [count], [increment], 
 [mode], [file_handle], [offset], [file_id], [file_group_id], [path], 
 [duration], [io_data], [succeeded], [sql_text], [trace_message], [source_database_id], 
 [object_id], [object_type], [cpu], [reads], [writes], [state], [offset_end], 
 [nest_level], [activity_id], [event_sequence])

-- Fetch the Event Data from the Event Session Target
SELECT 
    RowID,
    event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,
    DATEADD(hh, 
            DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), 
            event_data.value('(event/@timestamp)[1]', 'datetime2')) AS [timestamp],
    COALESCE(event_data.value('(event/data[@name="database_id"]/value)[1]', 'int'), 
             event_data.value('(event/action[@name="database_id"]/value)[1]', 'int')) AS database_id,
    event_data.value('(event/data[@name="count"]/value)[1]', 'bigint') AS [count],
    event_data.value('(event/data[@name="increment"]/value)[1]', 'bigint') AS [increment],
    event_data.value('(event/data[@name="mode"]/text)[1]', 'nvarchar(4000)') AS [mode],
    event_data.value('(event/data[@name="file_handle"]/value)[1]', 'nvarchar(4000)') AS [file_handle],
    event_data.value('(event/data[@name="offset"]/value)[1]', 'bigint') AS [offset],
    event_data.value('(event/data[@name="file_id"]/value)[1]', 'int') AS [file_id],
    event_data.value('(event/data[@name="file_group_id"]/value)[1]', 'int') AS [file_group_id],
    event_data.value('(event/data[@name="path"]/value)[1]', 'nvarchar(4000)') AS [path],
    event_data.value('(event/data[@name="duration"]/value)[1]', 'bigint') AS [duration],
    event_data.value('(event/data[@name="io_data"]/value)[1]', 'nvarchar(4000)') AS [io_data],
    event_data.value('(event/data[@name="succeeded"]/value)[1]', 'nvarchar(4000)') AS [succeeded],
    event_data.value('(event/action[@name="sql_text"]/value)[1]', 'nvarchar(4000)') AS [sql_text],
    event_data.value('(event/data[@name="message"]/value)[1]', 'nvarchar(4000)') AS [trace_message],
    event_data.value('(event/data[@name="source_database_id"]/value)[1]', 'int') AS [source_database_id],
    event_data.value('(event/data[@name="object_id"]/value)[1]', 'int') AS [object_id],
    event_data.value('(event/data[@name="object_type"]/value)[1]', 'int') AS [object_type],
    event_data.value('(event/data[@name="cpu"]/value)[1]', 'int') AS [cpu],
    event_data.value('(event/data[@name="reads"]/value)[1]', 'bigint') AS [reads],
    event_data.value('(event/data[@name="writes"]/value)[1]', 'bigint') AS [writes],
    event_data.value('(event/data[@name="state"]/text)[1]', 'nvarchar(4000)') AS [state],
    event_data.value('(event/data[@name="offset_end"]/value)[1]', 'int') AS [offset_end],
    event_data.value('(event/data[@name="nest_level"]/value)[1]', 'int') AS [nest_level],
    CAST(SUBSTRING(event_data.value('(event/action[@name="attach_activity_id"]/value)[1]', 'varchar(50)'), 1, 36) AS uniqueidentifier) as activity_id,
    CAST(SUBSTRING(event_data.value('(event/action[@name="attach_activity_id"]/value)[1]', 'varchar(50)'), 38, 10) AS int) as event_sequence
FROM RawEventData
ORDER BY Rowid
GO

-- Return our results
SELECT * 
FROM TestResults
WHERE event_name NOT IN ('sql_statement_starting' , 'sql_statement_completed')
ORDER BY RowID

If you scroll through the results you can see the writes occurring sequentially through each of the log files, and while FileId=4 is being written to, the Database Engine begins the growth of FileId=2 by 32MB. If we change our query to only focus on the file_write_completed, databases_log_growth, and trace_print Events, we can see this a little easier.

-- Return our results
SELECT 
    Rowid, 
    event_name, 
    [timestamp], 
    [count], 
    database_id, 
    mode, 
    offset, 
    file_id, 
    duration, 
    trace_message 
FROM TestResults
WHERE event_name  IN ('file_write_completed' , 'databases_log_growth', 'trace_print')
ORDER BY RowID


Log Rollover from Log1 to Log2		Log Rollover from Log2 to Log3


Autogrow of Log1		Log Rollover from Log3 to Log4


Log Rollover from Log4 back to Log1		Autogrow of Log2


Autogrow of Log3		Autogrow of Log4

We can see the first log file, FileID=2, grows before the log rollover from Log3, FileID=4, occurs to Log4, FileID=5, making space available in the first log file for the rollover when FileID=5 becomes full. Log records are written all four of the log files before the log wraps back around to the first log file, debunking point numbers two and four of the conclusion. The timestamps of the events shows that the additional log files are written to serially and not at the same time debunking point number three of the conclusion. The reason that only a fraction of the log records are written to the three additional log files is proportionate to the difference in the autogrowth settings between the first log file at 32MB and the three additional log files at 1MB. If the first log file was set to grow at 1MB, the majority of the log records would not be in the first log file.

Its been well documented that there is no performance benefit to having multiple log files in a database, and Paul Randal’s blog post, Importance of proper transaction log size management, was linked to in the original blog post that ultimately triggered this post. The behavior demonstrated in this post isn’t a mystery, its documented in the Books Online (Transaction Log Physical Architecture), but sometime empirical evidence like this helps solidify that fact.