THE SQL Server Blog Spot on the Web

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

The Rambling DBA: Jonathan Kehayias

The random ramblings and rantings of frazzled SQL Server DBA

  • Times they are a changing…

    If you follow me on twitter (@SQLSarg), you already know that this has been a week of big announcements for me. Wednesday afternoon Paul Randal (Blog|Twitter) announced that I joined SQLskills.com as a full time employee, and Thursday afternoon, Joe Sack (Blog|Twitter) announced that I passed the Microsoft Certified Masters for SQL Server 2008. As a part of my transition to working for SQLskills.com full time, I will be changing blogs over to the SQLskills.com site. You can read about my experience taking the MCM Exams on my first blog post Reflecting on the MCM Exam Experience.

    It has been a ton of fun blogging on SQLBlog the last few years, and I have asked Adam to leave the content I published here available to the community. I look forward to what the future holds and to all the fun I’m going to have working with SQLskills.com.

    If you haven’t already, make sure to update your RSS Reader to include my new feed.

    -- See you on the playground!

  • TSQL Tuesday #15 – Maintaining Your Sanity While Managing Large Environments

    This month’s TSQL Tuesday event is being hosted by Pat Wright (Blog | Twitter) and  the topic this month is Automation!

    I figured that since many of you out there set a goal this year to blog more and to learn Powershell then this Topic should help in both of those goals.    So the topic I have chosen for this month is Automation!   It can be Automation with T-SQL or with Powershell or a mix of both.  Give us your best tips/tricks and ideas for making our lives easier through Automation.”

     

    Automation is a topic that is very near and dear to my heart.  The only reason I survive day to day in my environment is because of Automation.  Recently on the forums someone asked how you manage an environment with 100+ SQL Servers and thousands of user databases.  A lot of the responses said to purchase a third party monitoring tool, but as someone that manages an environment of this size I know first hand the significant cost associated with purchasing tools for this large of an environment, and getting approval for that kind of expense isn’t something that happens overnight.  For this reason, I didn’t consider this type of response to be an answer to the specific problem that the person was asking about.  Below is the response that I posted to the question and what I would suggest to anyone that has a large environment that they are just taking over.

    My Response:


    Hopefully you at least have a list of all the SQL Server Instances in your environment.  If you don't have a complete list of all the instances, that is the first thing you are going to have to get.  There are a couple of ways to go about doing this.  The Microsoft Assessment and Planning Toolkit is a free tool from Microsoft that a Domain Administrator can run in the environment to scan all of the systems for SQL Server.  You can also use the Quest® Discovery Wizard for SQL Server which is free and does a good job as well.  I found servers with the MAP toolkit that weren't discovered by the Discovery Wizard from Quest and vice versa, so you will probably want to run them both and match the results for a fill picture.

    Once you have a list of servers and instances, go to any SQL Server 2008 instance in your environment and setup the Central Management Server and add all of the SQL Servers into it.  From there, you can use the CMS to accomplish a lot of tasks.  I'd recommend that you download the Enterprise Policy Management Framework from Codeplex and set it up on the CMS.  This can be used to automate a lot of things with Policy Based Management, even against 2000 and 2005.

    As someone that manages a very large environment that is exactly what you describe I can tell you that the best thing I did when I took over the environment was learn to use Powershell.  With your master list of instances in a text file, you can find and fix a lot of problems by leveraging SMO with Powershell.  I'd recommend that you download PowerGUI, a free script editor for Powershell, also by Quest Software.  PowerGui gives you AutoComplete and the ability to create complex scripts with debugging.  You can find some examples of how you can leverage powershell to push changes to your entire environment on my blog posts:

    Configuring SQL Server Audit Logging with Powershell
    Setting SQL Server ErrorLog Retention and Rollover with Powershell
    Working with the SQL Server Powershell Provider and Central Management Servers from Powershell

    Others have recommended third party tools and I am not saying that you shouldn't do that, but I would be very careful about what tool I allowed in my environment.  Some of the monitoring tools recommended on this post have a significant impact to the environment being monitored, so make sure you don't just jump out and buy a tool without a lot of research and due dilligence.  Install any tool you are considering in a test environment, and then monitor its impact to the environment.  Fire up a SQL Trace and watch the activity the tool generates against SQL Server.  Look at the impact the tool has to the information captured and contained in the Default Trace, and most importantly, see if the tool hides its own activity from its reports because some vendors hide the activity being generated by their tool from you.  Make sure you check out all the vendors and not just the big names:

    http://sqlsentry.com/
    http://www.quest.com/sql-server/
    http://www.red-gate.com/
    http://idera.com/
    http://www.confio.com/English/Products/Ignite_for_SQL_Server.php

    Even if you could get immediate approval for the cost that the licenses for 100+ servers will cost, it takes time to get any monitoring software installed and configured so it doesn't drive you completely nuts.  I switched from a third party SQL specific tool to Operations Manager because the it was the lowest cost solution for managing an environment that large, and I had experience from the past working with it.  That said, it is also the most annoying monitoring system out there unless you have the time to configure it and set the necessary overrides and thresholds for the monitors so that it fits your environment.  All of the tools I've ever tested tend to be noisy out of the gate, and you have to tune and set thresholds to get it to where its telling you what you want to know about only.  Any of the vendors, Microsoft included can provide a resource during an implementation to customize the monitoring thresholds and teach you enough to be able to configure the tool long term.

    You can also roll your own monitoring using things freely available online.  Even with Operations Manager installed in my shop, I have a sqladmin database on every server that holds administrative objects.  Those objects do all kinds of tasks, and write data to tables in the sqladmin database that have reports on top of them.  I have a single SQL Script that deploys this database, setups up the Agent Jobs to do data collection for the monitoring, and configures Database Mail so that the jobs can send me notifications when things aren't right.  You can find a lot of this stuff in the Automated DBA series of articles I wrote a few years back:

    http://code.msdn.microsoft.com/SQLExamples/Wiki/View.aspx?title=AutomatedDBA

    Hope that helps.  Its a lot I know, but when I took over my current position there were 200+ SQL Servers in the environment, none of them best practice configurations, all of them full of problems, and I can feel your pain.  A year later I have been able to consolidate down to 132 SQL Servers and fix a lot of problems.  Powershell and automation are your friend here.  You don't have time to look at every server once a month, you need them to tell you when somethings not right.  The other thing I'd tell you is be willing to tell your employer you need help.  I was hired into a single DBA position and over a year built a team of three with a fourth position open.  Look at places where you could save money for your employer by having additional resources, and time is money.  Feel free to contact me if you have any questions.


    While I use Operations Manager for a lot of basic monitoring tasks, I rely more heavily on my own automation scripts in the day to day management of my environment.  Managing a very large SQL Server environment is nearly impossible to do if you don’t take steps to automate your processes and operations.  For a number of the tasks that can be automated, a lot of good code exists online already, minimizing the amount of work that you would have to do to automate most common tasks.

  • Making Use of Plan Explorer in my own Environment

    Back in October 2010, I briefly blogged about the SQL Sentry Plan Explorer in my blog post wrap up for SQL Bits 7 and how impressed I was with what I saw from a Alpha demo standpoint from Greg Gonzalez (Blog|Twitter) while I was at SQLBits 7 in York.  To be 100% honest and transparent, Greg gave me early access to this tool after discussing it at SQLBits 7, and I had the opportunity to test a number of pre-Beta releases where I was able to offer significant feedback and submit bugs in the tool to Greg and the primary developer of the tool with SQL Sentry before Greg ever announced the public beta of the tool on his blog. 

    Today I had the opportunity to work with a vendor of mine on a performance problem and during the investigation of the problems, I identified a query that if rewritten a different way, without any index changes impact to the SQL Server was significantly lower.  To show this to the vendor I got on a WebEx session and shared my desktop with the vendors developers and executed their original query and my rewritten version of the query to show that my version output the same result and had significantly less impact to the server than their original one did.  They could see this in the execution times of the two queries, but to really drive the point home I did a copy/paste of the Actual Execution Plan XML from the SQL Batch that contained both statements in it to the SQL Plan Explorer for the vendor.  The output from SQL Plan Explorer is shown below.

    image

    The highlighted statement above shows the impact of the vendors original statement, while the one below it shows the impact of the query rewrite that I did while tuning this statement.  The rewrite that I did reduced the query execution time from 24 seconds to 4 seconds with the exact same output.  After doing some indexing analysis and adding two indexes to the database for this regularly executed query, the execution time was under 300ms, and the vendor is looking at making changes to their database to accommodate these changes.  However, the real win here was that the tool provided me with a way to show the two queries to the vendor to show their impact directly to the SQL Server.  Funny enough, the vendor developers had never actually heard of this tool, and downloaded it while we were on a conference call today to give it a whirl.

    So how exactly did I do this?  It is really much easier than you might think.  To do this kind of side by side analysis, all you have to do is open a new query window in SQL Server Management Studio and paste both of the queries into the window.  Then turn on the Include Actual Execution Plan from the toolbar button as shown below:

    image

    When you execute the Batch, both of the plans will be output in the Execution Plan, and then you can click on the Execution Plan tab to view the Execution Plans together in SQL Server Management Studio.  To capture this and bring it into the SQL Sentry Plan Explorer, you can right click on the execution plan in SQL Server Management Studio and select the option to Show Execution Plan XML, which will open the Execution Plan in XML format in Management Studio.

    image 

    One of the best features of the SQL Sentry Plan Explorer is that you can paste the Execution Plan XML into the tool to get a different perspective of the information contained in the XML from SQL Server Management Studio.  In the interests of protecting this vendor and their application, primarily because I value my job and I actually have a lot of respect for this vendor because they have been really amicable to work with over the last six months, I am going to mask any identifying information the example screenshots provided in the remainder of this blog post.  The following is what SQL Server Management Studio presents for the Actual Execution Plans of the two queries:

    image

    and here is the SQL Sentry Plan Explorer display for the two queries:

    image

    Note that the graphical execution plan only shows one of the statements from the batch, the selected statement in the upper part of the window.  Also note that the upper window shows the difference between the two statements that exist in the batch.  Now previously I stated that I showed the vendor the output from the Actual Execution Plan, but if you note in the above, the output only shows the Estimated Execution Plan information.  Unfortunately, at the point that I wrote this blog post, I didn’t have the Actual Execution Plan information available, and I couldn’t subject my production systems to the execution of these statements to write this blog post so I have had to use Estimated Plans that were edited to write this post.

    In this post I have shown just one of the many benefits that is offered by the SQL Sentry Plan Explorer to production support DBA’s.  In my next few posts I will highlight a number of the other features of this free tool that a production support DBA will find useful in their regular work.

  • Parsing the sqlserver.sql_text Action in Extended Events by Offsets

    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'

    image

    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'

    image

    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.

    image

    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

    image

    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)
    

    image

    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

    image

    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'
    

    image

    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'
    

    image

    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
    
    image 

    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.

  • Using Substring() in XML FLOWR Queries

    Tonight I was monitoring the #sqlhelp hashtag on Twitter for a response to a question I asked when Randy Knight (Twitter) asked a question about using SUBSTRING in FLOWR statements with XML.

    #sqlhelp Is there a way to do a SQL Type "LIKE" or "SUBSTRING" in the where clause of FLWOR statement? Need to evaluate just first n chars.

    By the time I posted a response, Randy had figured out how to use the contains() function to solve his problem, but I am going to blog this because I am sure that I will need this at some point in the future, and it makes for a good blog post anyway.

    Using an example from the Books Online topic for FLOWR, I mocked up the following example showing how to use substring() in the where clause of a FLOWR statement.

    declare @x xml
    set @x='<ManuInstructions ProductModelID="1" ProductModelName="SomeBike" >
    <Location LocationID="L1" >
      <Step>Manu step 1 at Loc 1</Step>
      <Step>Manu step 2 at Loc 1</Step>
      <Step>Manu step 3 at Loc 1</Step>
    </Location>
    <Location LocationID="L2" >
      <Step>Manu step 1 at Loc 2</Step>
      <Step>Manu step 2 at Loc 2</Step>
      <Step>Manu step 3 at Loc 2</Step>
    </Location>
    </ManuInstructions>'
    SELECT @x.query('
       for $step in /ManuInstructions/Location[1]/Step
       where substring(string($step), 11, 1) = "2"
       return string($step)
    ')
    

    This outputs only a single node value where the substring() function evaluation matches the string value of 2.

  • Did the Community Lose It’s Focus, or Did I?

    Late Thursday night, ok it was actually very early Friday morning, I wrote a blog post that stirred a bit of a controversy in the community.  While the outcome of the discussion that was sparked by that post in the community has been good, it is definitely a case where the end isn’t justified by the means.   Hindsight is always 20/20, and while I stand by the point I was trying to make with that post, there are a number of ways I could have gone about making that point without risking my friendship and reputation with Tom LaRock (Blog|Twitter). While Tom has no hard feelings about that post, we’ve traded a number of emails about this, I’d like to take a few minutes and reflect on how that situation could have been handled differently.

    Tom made one suggestion in his blog response to my post, I could have emailed him directly with my problem rather than making it a public blog post, or at a bare minimum I could have emailed him that I was blogging it so he wasn’t blindsided in the morning. I can’t argue with Tom on that point, well I could try but it would only make me look like a bigger ass. (<= This is supposed to be funny but I’ll get to that in a minute) I personally think that the issue being addressed is a bigger community problem that needed addressed openly, but I don’t think it necessitated as Tom put it, a public smack down, and that honestly wasn’t exactly my intent. I absolutely intended to call Tom out on this as a community leader, but I didn’t consider it to be a smack down when I wrote the post, though to be perfectly honest, I would likely have been equally annoyed as Tom was if the reverse had been done to me.

    Paul Randal (Blog|Twitter) wrote a blog post today that provided some guidelines about blogging and one of his Don’t items was:

    If you're correcting some misinformation that you've seen on the Internet, don't link back directly to the post you're correcting. That makes it personal.

    I’m really bad about this, and it’s something that I am going to be cognizant about going forward with blogging. While the issue here wasn’t misinformation, linking to and naming Tom in the manner I did was just as personal and turned out to be the biggest part of the controversy. I have my own domains where I could have setup WordPress to use tynt.com to produce an example showing how annoying it is to have an uncommented message appended to any copy/paste operation. It would be interesting to know whether that approach would have had the same effect that being controversial did. I personally doubt that it would have had the same effect since the personal nature of that post is a big part of what drove the response from the community, but that is up for debate.

    It’s really rare for a blog post to affect the community in a positive and negative way. If you read the comments on my original blog post and on Tom’s response blog post, things are somewhat split in the community between those that think the tynt.com addition mattered or not, and there is a split between those that think I am an ass or not. Admittedly, I am, but I can also admit when I am wrong, and I should have handled this differently. To Tom, my sincerest apology for the embarrassment, I hope you know I don’t intend you any ill will. To the community, let this serve as a lesson on multiple levels.

    First; think before you post. I have a strict rule at work about email and controversial subjects and it basically is never respond to an email that could be controversial immediately, take a walk, change tasks and come back, or pick up the phone and call someone, before writing anything down. The reason for this is that I am very easily misread in written form, primarily because voice inflections and other cues that exist in speech don’t come across in written form.

    Second; don’t use sarcasm in written form unless you are good enough to pull it off. I pointed out a spelling error in Tom’s tynt.com message and that became a big deal in the community because I am one of the worst spellers out there, and my grammar is even worse at times. What I wrote about the misspelled word was entirely sarcastic and if you heard me say it in person you’d take different meaning from it than you would reading it in text form. Unless you are really good, sarcasm just doesn’t work in written form, and the only person I know that can nail sarcasm in text for is Buck Woody (Blog|Twitter), but we never take him serious anyway. (I apparently didn’t learn my lesson that was sarcasm! You know I love you Buck, not that you read my blog posts. <= Yet again!)

    Third; the general consensus is that plagiarism sucks, but using something like tynt.com isn’t likely to stop it. I actually like the fact that something like tynt.com can be used to append a source message to a blog post believe it or not. I mention in some of my presentations that I have a whole slew of code in my script archive that I have no idea where it came from. Three years ago when I started blogging, I realized I couldn’t tell what scripts in my code library were my own or something I had found online and I began adding a comment at the top of anything I found online noting the link address where I found things so that if I used it in the future I could provide credit where credit is due. Anything I had prior to this was moved into a separate folder so I knew that I couldn’t account for where it originated. Something like tynt.com, if used appropriately, could solve this problem.

  • Has the SQL Community Lost its Focus?

    Yesterday, Thomas LaRock’s blog post, WMI Code Creator, was brought to my attention by a member of the SQL Community.  I subscribe to Tom’s blog in my blog reader so eventually I’d like to think that his post would have come to my attention, but to be perfectly honest, I have been to busy with other obligations lately that have made reading blog posts almost impossible.  When I looked at Tom’s post, I was kind of put off when I did a copy paste of the Code from it and got the following:

    DECLARE @WmiServiceLocator INT ,
     @WmiService INT ,
     @CounterObject INT ,
     @AvgDiskReadPerSec BIGINT,
     @AvgDiskReadPerSec_Base BIGINT 
    
    EXEC sp_OACreate 'WbemScripting.SWbemLocator', @WmiServiceLocator OUTPUT, 5
    EXEC sp_OAMethod @WmiServiceLocator, 'ConnectServer', @WmiService OUTPUT, '.', 'root\cimv2' 
    
    IF ISNULL(@WmiService, -1) <= 0
     BEGIN
     EXEC sp_OADestroy @WmiServiceLocator          
     RAISERROR('Could not access WMI service.', 16, 1)
     RETURN
     END 
    
    EXEC sp_OAMethod @WmiService, 'Get', @CounterObject OUTPUT, 'Win32_PerfRawData_PerfDisk_PhysicalDisk="_Total"'
    EXEC sp_OAGetProperty @CounterObject, 'AvgDiskSecPerRead', @AvgDiskReadPerSec OUTPUT
    EXEC sp_OAGetProperty @CounterObject, 'AvgDiskSecPerRead_Base', @AvgDiskReadPerSec_Base OUTPUT 
    
    SELECT @AvgDiskReadPerSec, @AvgDiskReadPerSec_Base
    
    Read more: http://thomaslarock.com/2011/01/wmi-code-creator/#ixzz1AKN2Swcm 
    If you are not at thomaslarock.com, this material has been plagerized by someone who steals content from others. 

    Now I am all for protecting your content, but if you are going to blog code it should be reusable without an abusive message like this.  Beyond that, if you force me to have to delete this kind of message when posting code into SSMS from your blog, the word plagiarized should be spelled correctly at a minimum.

    As Since Tom is a member of the Board of Directors for PASS I would expect a lot more in the way of being a better role model for the community.  Personally, my own take on this is that if the WordPress Addin that appends this text to the copied code can’t handle code blocks separately for this kind of thing, then it shouldn’t be used.  There are certainly better ways to identify plagiarism than this, though they may require some additional work.

  • Using Extended Events in SQL Server Denali CTP1 to Map out the TransactionLog SQL Trace Event EventSubClass Values

    John Sansom (Blog|Twitter) asked on the MSDN Forums about the meaning/description for the numeric values returned by the EventSubClass column of the TransactionLog SQL Trace Event.  John pointed out that this information is not available for this Event like it is for the other events in the Books Online Topic (TransactionLog Event Class), or in the sys.trace_subclass_values DMV.  John wanted to know if there was a way to determine this information.  I did some looking and found an old SQL Server 2000 BOL topic, Transactions Data Columns gave more information about what the EventSubClass means and defined the column as:

    Type of transaction log event, such as BEGINXACT(null).

    After seeing this, I knew it would be possible to map this out using the new sqlserver.transaction_log Event in Extended Events, which I blogged about last month in my blog post, An XEvent a Day (22 of 31) – The Future – fn_dblog() No More? Tracking Transaction Log Activity in Denali.  To start with I created a database with database_id = 5 on my VM that I would run a number of test workloads against.  Then I created a filtered Extended Events Session for the sqlserver.transaction_log Event in Extended Events in a SQL Server Denali CTP1 VM on my laptop for the sqlserver.transaction_log Event with a Predicate on database_id = 5 for the Event. 

    CREATE EVENT SESSION tranlog
    ON SERVER
    ADD EVENT sqlserver.transaction_log
    (    ACTION (sqlserver.event_sequence)
        WHERE database_id = 5)
    ADD target package0.ring_buffer
    WITH (MAX_DISPATCH_LATENCY = 5SECONDS, EVENT_RETENTION_MODE=NO_EVENT_LOSS)
    GO
    ALTER EVENT SESSION tranlog
    ON SERVER
    STATE=START
    GO

    I then created a SQL Trace in Profiler that also captured the TransactionLog Event with all of the available columns into a Trace Table named TranLogTrace in the master database that also had a filter on DatabaseID = 5.  Then I ran a couple of workload samples against the demo database (Note: These tests do not necessarily represent a complete workload.)

    CREATE TABLE Test (rowid INT IDENTITY PRIMARY KEY)
    GO
    BEGIN TRANSACTION
    GO
    INSERT INTO Test DEFAULT VALUES;
    GO 100
    ROLLBACK
    GO
    BEGIN TRANSACTION
    GO
    INSERT INTO Test DEFAULT VALUES;
    GO 100
    COMMIT
    GO

    Based on this admittedly, overly simplistic test, the following mappings to of the EventSubClass of the SQL Trace TransactionLog using the following the parsing of the Extended Event Session Data as a comparison against the SQL Trace TransactionLog Event Data can be made:

    EventSubClass operation context
    257 LOP_FORMAT_PAGE HEAP
    266 LOP_FORMAT_PAGE IAM
    514 LOP_INSERT_ROWS CLUSTERED
    515 LOP_INSERT_ROWS INDEX_LEAF
    787 LOP_DELETE_ROWS MARK_AS_GHOST
    1026 LOP_MODIFY_ROW CLUSTERED
    1034 LOP_MODIFY_ROW IAM
    1035 LOP_MODIFY_ROW PFS
    1044 LOP_MODIFY_ROW BOOT_PAGE
    4866 LOP_ROOT_CHANGE CLUSTERED
    32768 LOP_BEGIN_XACT NULL
    33024 LOP_COMMIT_XACT NULL
    33280 LOP_ABORT_XACT NULL
    35072 LOP_HOBT_DDL NULL
    35840 LOP_HOBT_DELTA NULL
    36096 LOP_LOCK_XACT NULL
    45056 LOP_CREATE_ALLOCCHAIN NULL
    56576 LOP_INVALIDATE_CACHE NULL

    This is no way a complete mapping of the to entire subset of EventSubClass value’s of the SQL Trace Event, but it shows that there is a mechanism available through Extended Events that can map this kind of information out. 

    While I was playing with this, I did some testing along the lines of the original question of the MSDN Forums post, and there is nothing in the TransactionLog Event that you could key on to know the log truncated.  No Transaction Log record is generated that specifically says the log truncated, it opens a transaction, writes to the boot_page, and closes the transaction all in different log records.  Keep in mind that the boot page gets written to by a number of other operations in SQL Server, so keying on it is not the answer.  For example, if the log is failing to truncate because there is an open transaction and it has to grow, the growth would trigger a write to the boot page.  Attempting to key in on TransactionLog Events in SQL Trace that write to the Boot Page alone would be short sighted, and incorrect in this type of analysis alone.

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

    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%'
    

    image

    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'
    
    

    image

    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

    image

    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

    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%'

    image

    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

    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
    

    image

    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
    

    image 

    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') 
    

    image

     

    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.

    image

    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.

    image

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

    image

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

    image

    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.

  • Learn Who Started that Trace with the Default Trace

    This is not Extended Event related but it came from a question on Twitter about how to tell who and from what machine a server side trace was created, and there is no way to explain this in 140 characters so here’s a blog post.  This information is tracked in the Default Trace and can be found by querying for EventClass 175 which is the Audit Server Alter Trace Event trace_event_id from sys.trace_events.

    select 
        trace_event_id, 
        name
    from sys.trace_events
    where name like '%trace%'

    image

    To query the default trace for this information we can do the following:

    DECLARE @FileName VARCHAR(MAX)  
    
    SELECT @FileName = SUBSTRING(path, 0, LEN(path)-CHARINDEX('\', REVERSE(path))+1) + '\Log.trc'  
    FROM sys.traces   
    WHERE is_default = 1;  
    
    SELECT 
        LoginName, 
        HostName, 
        ApplicationName, 
        StartTime, 
        TextData
    FROM sys.fn_trace_gettable( @FileName, DEFAULT ) AS gt  
    WHERE EventClass = 175
  • An XEvent a Day (28 of 31) – Tracking Page Compression Operations

    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'

    image

    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

    image

    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

    image

    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

    image

    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

    image

    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

    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.

     image

    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. 

    image

    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

    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.

More Posts Next page »

This Blog

Syndication

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