THE SQL Server Blog Spot on the Web

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

Extended Events

  • Try a sample: Using the counter predicate for event sampling

    Extended Events offers a rich filtering mechanism, called predicates, that allows you to reduce the number of events you collect by specifying criteria that will be applied during event collection. (You can find more information about predicates in Using SQL Server 2008 Extended Events (by Jonathan Kehayias)) By evaluating predicates early in the event firing sequence we can reduce the performance impact of collecting events by stopping event collection when the criteria are not met. You can specify predicates on both event fields and on a special object called a predicate source. Predicate sources are similar to action in that they typically are related to some type of global information available from the server. You will find that many of the actions available in Extended Events have equivalent predicate sources, but actions and predicates sources are not the same thing.

    Applying predicates, whether on a field or predicate source, is very similar to what you are used to in T-SQL in terms of how they work; you pick some field/source and compare it to a value, for example, session_id = 52. There is one predicate source that merits special attention though, not just for its special use, but for how the order of predicate evaluation impacts the behavior you see. I’m referring to the counter predicate source. The counter predicate source gives you a way to sample a subset of events that otherwise meet the criteria of the predicate; for example you could collect every other event, or only every tenth event.

    Simple Counting
    The counter predicate source works by creating an in memory counter that increments every time the predicate statement is evaluated. Here is a simple example with my favorite event, sql_statement_completed, that only collects the second statement that is run. (OK, that’s not much of a sample, but this is for demonstration purposes. Here is the session definition:

    CREATE EVENT SESSION counter_test ON SERVER
    ADD EVENT sqlserver.sql_statement_completed
        (ACTION (sqlserver.sql_text)
        WHERE package0.counter = 2)
    ADD TARGET package0.ring_buffer
    WITH (MAX_DISPATCH_LATENCY = 1 SECONDS)

    You can find general information about the session DDL syntax in BOL and from Pedro’s post Introduction to Extended Events. The important part here is the WHERE statement that defines that I only what the event where package0.count = 2; in other words, only the second instance of the event. Notice that I need to provide the package name along with the predicate source. You don’t need to provide the package name if you’re using event fields, only for predicate sources. Let’s say I run the following test queries:

    -- Run three statements to test the session
    SELECT 'This is the first statement'
    GO
    SELECT 'This is the second statement'
    GO
    SELECT 'This is the third statement';
    GO

    Once you return the event data from the ring buffer and parse the XML (see my earlier post on reading event data) you should see something like this:

    event_name sql_text
    sql_statement_completed SELECT ‘This is the second statement’

    You can see that only the second statement from the test was actually collected. (Feel free to try this yourself. Check out what happens if you remove the WHERE statement from your session. Go ahead, I’ll wait.)

    Percentage Sampling

    OK, so that wasn’t particularly interesting, but you can probably see that this could be interesting, for example, lets say I need a 25% sample of the statements executed on my server for some type of QA analysis, that might be more interesting than just the second statement. All comparisons of predicates are handled using an object called a predicate comparator; the simple comparisons such as equals, greater than, etc. are mapped to the common mathematical symbols you know and love (eg. = and >), but to do the less common comparisons you will need to use the predicate comparators directly. You would probably look to the MOD operation to do this type sampling; we would too, but we don’t call it MOD, we call it divides_by_uint64. This comparator evaluates whether one number is divisible by another with no remainder. The general syntax for using a predicate comparator is pred_comp(field, value), field is always first and value is always second. So lets take a look at how the session changes to answer our new question of 25% sampling:

    CREATE EVENT SESSION counter_test_25 ON SERVER
    ADD EVENT sqlserver.sql_statement_completed
        (ACTION (sqlserver.sql_text)
        WHERE package0.divides_by_uint64(package0.counter,4))
    ADD TARGET package0.ring_buffer
    WITH (MAX_DISPATCH_LATENCY = 1 SECONDS)
    GO

    Here I’ve replaced the simple equivalency check with the divides_by_uint64 comparator to check if the counter is evenly divisible by 4, which gives us back every fourth record. I’ll leave it as an exercise for the reader to test this session.

    Why order matters

    I indicated at the start of this post that order matters when it comes to the counter predicate – it does. Like most other predicate systems, Extended Events evaluates the predicate statement from left to right; as soon as the predicate statement is proven false we abandon evaluation of the remainder of the statement. The counter predicate source is only incremented when it is evaluated so whether or not the counter is incremented will depend on where it is in the predicate statement and whether a previous criteria made the predicate false or not. Here is a generic example:

    Pred1: (WHERE statement_1 AND package0.counter = 2)
    Pred2: (WHERE package0.counter = 2 AND statement_1)

    Let’s say I cause a number of events as follows and examine what happens to the counter predicate source.

    Iteration Statement Pred1 Counter Pred2 Counter
    A

    Not statement_1

    0

    1

    B statement_1 1 2
    C Not statement_1 1 3
    D statement_1 2 4

    As you can see, in the case of Pred1, statement_1 is evaluated first, when it fails (A & C) predicate evaluation is stopped and the counter is not incremented. With Pred2 the counter is evaluated first, so it is incremented on every iteration of the event and the remaining parts of the predicate are then evaluated. In this example, Pred1 would return an event for D while Pred2 would return an event for B. But wait, there is an interesting side-effect here; consider Pred2 if I had run my statements in the following order:

    1. Not statement_1
    2. Not statement_1
    3. statement_1
    4. statement_1

    In this case I would never get an event back from Pred2 because the point at which counter=2, the rest of the predicate evaluates as false so the event is not returned. If you’re using the counter target for sampling and you’re not getting the expected events, or any events, check the order of the predicate criteria. As a general rule I’d suggest that the counter criteria should be the last element of your predicate statement since that will assure that your sampling rate will apply to the set of event records defined by the rest of your predicate.

    Aside: I’m interested in hearing about uses for putting the counter predicate criteria earlier in the predicate statement. If you have one, post it in a comment to share with the class.

    - Mike

  • Making a Statement: How to retrieve the T-SQL statement that caused an event

    If you’ve done any troubleshooting of T-SQL, you know that sooner or later, probably sooner, you’re going to want to take a look at the actual statements you’re dealing with. In extended events we offer an action (See the BOL topic that covers Extended Events Objects for a description of actions) named sql_text that seems like it is just the ticket. Well…not always – sounds like a good reason for a blog post.

    When is a statement not THE statement?

    The sql_text action returns the same information that is returned from DBCC INPUTBUFFER, which may or may not be what you want. For example, if you execute a stored procedure, the sql_text action will return something along the lines of “EXEC sp_notwhatiwanted” assuming that is the statement you sent from the client. Often times folks would like something more specific, like the actual statements that are being run from within the stored procedure or batch.

    Enter the stack

    Extended events offers another action, this one with the descriptive name of tsql_stack, that includes the sql_handle and offset information about the statements being run when an event occurs. With the sql_handle and offset values you can retrieve the specific statement you seek using the DMV dm_exec_sql_text. The BOL topic for dm_exec_sql_text provides an example for how to extract this information, so I’ll cover the gymnastics required to get the sql_handle and offset values out of the tsql_stack data collected by the action.

    I’m the first to admit that this isn’t pretty, but this is what we have in SQL Server 2008 and 2008 R2. We will be making it easier to get statement level information in the next major release of SQL Server.

    The sample code

    For this example I have a stored procedure that includes multiple statements and I have a need to differentiate between those two statements in my tracing. I’m going to track two events: module_end tracks the completion of the stored procedure execution and sp_statement_completed tracks the execution of each statement within a stored procedure. I’m adding the tsql_stack events (since that’s the topic of this post) and the sql_text action for comparison sake. (If you have questions about creating event sessions, check out Pedro’s post Introduction to Extended Events.)

    USE AdventureWorks2008
    GO

    -- Test SP
    CREATE PROCEDURE sp_multiple_statements
    AS
    SELECT 'This is the first statement'
    SELECT 'this is the second statement'
    GO

    -- Create a session to look at the sp
    CREATE EVENT SESSION track_sprocs ON SERVER
    ADD EVENT sqlserver.module_end (ACTION (sqlserver.tsql_stack, sqlserver.sql_text)),
    ADD EVENT sqlserver.sp_statement_completed (ACTION (sqlserver.tsql_stack, sqlserver.sql_text))
    ADD TARGET package0.ring_buffer
    WITH (MAX_DISPATCH_LATENCY = 1 SECONDS)
    GO

    -- Start the session
    ALTER EVENT SESSION track_sprocs ON SERVER
    STATE = START
    GO

    -- Run the test procedure
    EXEC sp_multiple_statements
    GO

    -- Stop collection of events but maintain ring buffer
    ALTER EVENT SESSION track_sprocs ON SERVER
    DROP EVENT sqlserver.module_end,
    DROP EVENT sqlserver.sp_statement_completed
    GO

    Aside: Altering the session to drop the events is a neat little trick that allows me to stop collection of events while keeping in-memory targets such as the ring buffer available for use. If you stop the session the in-memory target data is lost.

    Now that we’ve collected some events related to running the stored procedure, we need to do some processing of the data. I’m going to do this in multiple steps using temporary tables so you can see what’s going on; kind of like having to “show your work” on a math test. The first step is to just cast the target data into XML so I can work with it. After that you can pull out the interesting columns, for our purposes I’m going to limit the output to just the event name, object name, stack and sql text. You can see that I’ve don a second CAST, this time of the tsql_stack column, so that I can further process this data.

    -- Store the XML data to a temp table
    SELECT CAST( t.target_data AS XML) xml_data
    INTO #xml_event_data
    FROM sys.dm_xe_sessions s INNER JOIN sys.dm_xe_session_targets t
        ON s.address = t.event_session_address
    WHERE s.name = 'track_sprocs'

    SELECT * FROM #xml_event_data

    -- Parse the column data out of the XML block
    SELECT
        event_xml.value('(./@name)', 'varchar(100)') as [event_name],
        event_xml.value('(./data[@name="object_name"]/value)[1]', 'varchar(255)') as [object_name],
        CAST(event_xml.value('(./action[@name="tsql_stack"]/value)[1]','varchar(MAX)') as XML) as [stack_xml],
        event_xml.value('(./action[@name="sql_text"]/value)[1]', 'varchar(max)') as [sql_text]
    INTO #event_data
    FROM #xml_event_data
        CROSS APPLY xml_data.nodes('//event') n (event_xml)

    SELECT * FROM #event_data

    event_name

    object_name

    stack_xml

    sql_text

    sp_statement_completed

    NULL

    <frame level="1" handle="0x03000500D0057C1403B79600669D00000100000000000000" line="4" offsetStart="94" offsetEnd="172" /><frame level="2" handle="0x01000500CF3F0331B05EC084000000000000000000000000" line="1" offsetStart="0" offsetEnd="-1" />

    EXEC sp_multiple_statements

    sp_statement_completed

    NULL

    <frame level="1" handle="0x03000500D0057C1403B79600669D00000100000000000000" line="6" offsetStart="174" offsetEnd="-1" /><frame level="2" handle="0x01000500CF3F0331B05EC084000000000000000000000000" line="1" offsetStart="0" offsetEnd="-1" />

    EXEC sp_multiple_statements

    module_end

    sp_multiple_statements

    <frame level="1" handle="0x03000500D0057C1403B79600669D00000100000000000000" line="0" offsetStart="0" offsetEnd="0" /><frame level="2" handle="0x01000500CF3F0331B05EC084000000000000000000000000" line="1" offsetStart="0" offsetEnd="-1" />

    EXEC sp_multiple_statements

    After parsing the columns it’s easier to see what is recorded. You can see that I got back two sp_statement_completed events, which makes sense given the test procedure I’m running, and I got back a single module_end for the entire statement. As described, the sql_text isn’t telling me what I really want to know for the first two events so a little extra effort is required.

    -- Parse the tsql stack information into columns
    SELECT
        event_name,
        object_name,
        frame_xml.value('(./@level)', 'int') as [frame_level],
        frame_xml.value('(./@handle)', 'varchar(MAX)') as [sql_handle],
        frame_xml.value('(./@offsetStart)', 'int') as [offset_start],
        frame_xml.value('(./@offsetEnd)', 'int') as [offset_end]
    INTO #stack_data   
    FROM #event_data   
        CROSS APPLY    stack_xml.nodes('//frame') n (frame_xml)   

    SELECT * from #stack_data

    event_name

    object_name

    frame_level

    sql_handle

    offset_start

    offset_end

    sp_statement_completed

    NULL

    1

    0x03000500D0057C1403B79600669D00000100000000000000

    94

    172

    sp_statement_completed

    NULL

    2

    0x01000500CF3F0331B05EC084000000000000000000000000

    0

    -1

    sp_statement_completed

    NULL

    1

    0x03000500D0057C1403B79600669D00000100000000000000

    174

    -1

    sp_statement_completed

    NULL

    2

    0x01000500CF3F0331B05EC084000000000000000000000000

    0

    -1

    module_end

    sp_multiple_statements

    1

    0x03000500D0057C1403B79600669D00000100000000000000

    0

    0

    module_end

    sp_multiple_statements

    2

    0x01000500CF3F0331B05EC084000000000000000000000000

    0

    -1

    Parsing out the stack information doubles the fun and I get two rows for each event. If you examine the stack from the previous table, you can see that each stack has two frames and my query is parsing each event into frames, so this is expected. There is nothing magic about the two frames, that’s just how many I get for this example, it could be fewer or more depending on your statements. The key point here is that I now have a sql_handle and the offset values for those handles, so I can use dm_exec_sql_text to get the actual statement. Just a reminder, this DMV can only return what is in the cache – if you have old data it’s possible your statements have been ejected from the cache. “Old” is a relative term when talking about caches and can be impacted by server load and how often your statement is actually used. As with most things in life, your mileage may vary.

    SELECT
        qs.*,
        SUBSTRING(st.text, (qs.offset_start/2)+1,
            ((CASE qs.offset_end
              WHEN -1 THEN DATALENGTH(st.text)
             ELSE qs.offset_end
             END - qs.offset_start)/2) + 1) AS statement_text
    FROM #stack_data AS qs
    CROSS APPLY sys.dm_exec_sql_text(CONVERT(varbinary(max),sql_handle,1)) AS st

    event_name

    object_name

    frame_level

    sql_handle

    offset_start

    offset_end

    statement_text

    sp_statement_completed

    NULL

    1

    0x03000500D0057C1403B79600669D00000100000000000000

    94

    172

    SELECT 'This is the first statement'

    sp_statement_completed

    NULL

    1

    0x03000500D0057C1403B79600669D00000100000000000000

    174

    -1

    SELECT 'this is the second statement'

    module_end

    sp_multiple_statements

    1

    0x03000500D0057C1403B79600669D00000100000000000000

    0

    0

    C

    Now that looks more like what we were after, the statement_text field is showing the actual statement being run when the sp_statement_completed event occurs. You’ll notice that it’s back down to one row per event, what happened to frame 2? The short answer is, “I don’t know.” In SQL Server 2008 nothing is returned from dm_exec_sql_text for the second frame and I believe this to be a bug; this behavior has changed in the next major release and I see the actual statement run from the client in frame 2. (In other words I see the same statement that is returned by the sql_text action  or DBCC INPUTBUFFER) There is also something odd going on with frame 1 returned from the module_end event; you can see that the offset values are both 0 and only the first letter of the statement is returned. It seems like the offset_end should actually be –1 in this case and I’m not sure why it’s not returning this correctly. This behavior is being investigated and will hopefully be corrected in the next major version. You can workaround this final oddity by ignoring the offsets and just returning the entire cached statement.

    SELECT
        event_name,
        sql_handle,
        ts.text
    FROM #stack_data
        CROSS APPLY sys.dm_exec_sql_text(CONVERT(varbinary(max),sql_handle,1)) as ts

    event_name

    sql_handle

    text

    sp_statement_completed

    0x0300070025999F11776BAF006F9D00000100000000000000

    CREATE PROCEDURE sp_multiple_statements AS SELECT 'This is the first statement' SELECT 'this is the second statement'

    sp_statement_completed

    0x0300070025999F11776BAF006F9D00000100000000000000

    CREATE PROCEDURE sp_multiple_statements AS SELECT 'This is the first statement' SELECT 'this is the second statement'

    module_end

    0x0300070025999F11776BAF006F9D00000100000000000000

    CREATE PROCEDURE sp_multiple_statements AS SELECT 'This is the first statement' SELECT 'this is the second statement'

    Obviously this gives more than you want for the sp_statement_completed events, but it’s the right information for module_end. I leave it to you to determine when this information is needed and use the workaround when appropriate.

    Aside: You might think it’s odd that I’m showing apparent bugs with my samples, but you’re going to see this behavior if you use this method, so you need to know about it.

    I’m all about transparency.

    Happy Eventing
    - Mike

  • Introduction to Extended Events

    For those fighting with all the Extended Event terminology, let's step back and have a small overall Introduction to Extended Events.

    This post will give you a simplified end to end view through some of the elements in Extended Events. Before we start, let’s review the first Extented Events that we are going to use:

    -          Events: The SQL Server code is populated with event calls that, by default, are disabled. Adding events to a session enables those event calls. Once enabled, they will execute the set of functionality defined by the session.

    -          Target: This is an Extended Event Object that can be used to log event information.

    Also it is important to understand the following Extended Event concept:

    -          Session: Server Object created by the user that defines functionality to be executed every time a set of events happen.  

    It’s time to write a small “Hello World” using Extended Events. This will help understand the above terms. We will use:

    -          Event sqlserver. error_reported: This event gets fired every time that an error happens in the server.

    -          Target package0.asynchronous_file_target: This target stores the event data in disk.

    -          Session: We will create a session that sends all the error_reported events to the ring buffer.

    Before we get started, a quick note: Don’t run this script in a production environment. Even though, we are going just going to be raise very low severity user errors, we don't want to introduce noise in our servers.

    -- TRIES TO ELIMINATE PREVIOUS SESSIONS

    BEGIN TRY

          DROP EVENT SESSION test_session ON SERVER

    END TRY BEGIN CATCH END CATCH

    GO

     

    -- CREATES THE SESSION

    CREATE EVENT SESSION test_session ON SERVER

    ADD EVENT sqlserver.error_reported

    ADD TARGET package0.asynchronous_file_target

    -- CONFIGURES THE FILE TARGET

    (set filename = 'c:\temp\data1.xel' , metadatafile = 'c:\temp\data1.xem')

    GO

     

    -- STARTS THE SESSION

    ALTER EVENT SESSION test_session ON SERVER STATE = START

    GO

     

    -- GENERATES AN ERROR

    RAISERROR (N'HELLO WORLD', -- Message text.

               1, -- Severity,

               1, 7, 3, N'abcde'); -- Other parameters

    GO

     

    -- STOPS LISTENING FOR THE EVENT

    ALTER EVENT SESSION test_session ON SERVER

    STATE = STOP

    GO

     

    -- REMOVES THE EVENT SESSION FROM THE SERVER

    DROP EVENT SESSION test_session ON SERVER

    GO

    -- REMOVES THE EVENT SESSION FROM THE SERVER

    select CAST(event_data as XML) as event_data

    from sys.fn_xe_file_target_read_file

    ('c:\temp\data1*.xel','c:\temp\data1*.xem', null, null)

    This query will output the event data with our first hello world in the Extended Event format:

    <event name="error_reported" package="sqlserver" id="100" version="1" timestamp="2010-02-27T03:08:04.210Z">
    <data name="error"><value>50000</value><text /></data>
    <data name="severity"><value>1</value><text /></data>
    <data name="state"><value>1</value><text /></data>
    <data name="user_defined"><value>true</value><text />
    </data><data name="message"><value>HELLO WORLD</value><text /></data></event>

    More on parsing event data in this post: Reading event data 101

    Now let's move that lets move on to the other three Extended Event objects:

    -          Actions. This Extended Objects actions get executed before events are published (stored in buffers to be transferred to the targets). Currently they are used additional data (like the TSQL Statement related to an event, the session, the user) or generate a mini dump.

     

    -          Predicates: Predicates express are logical expressions that specify what predicates to fire (E.g. only listen to errors with a severity greater than 16). This are composed of two Extended Objects:

    o   Predicate comparators: Defines an operator for a pair of values. Examples:

    §  Severity > 16

    §  error_message = ‘Hello World!!’

    o   Predicate sources: These are values that can be also used by the predicates. They are generic data that isn’t usually provided in the event (similar to the actions).

    §  Sqlserver.username = ‘Tintin’

    As logical expressions they can be combined using logical operators (and, or, not).  Note: This pair always has to be first an event field or predicate source and then a value

           

    Let’s do another small Example. We will trigger errors but we will use the ones that have severity >= 10 and the error message != ‘filter’. To verify this we will use the action sql_text that will attach the sql statement to the event data:

    -- TRIES TO ELIMINATE PREVIOUS SESSIONS

    BEGIN TRY

          DROP EVENT SESSION test_session ON SERVER

    END TRY BEGIN CATCH END CATCH

    GO

     

    -- CREATES THE SESSION

    CREATE EVENT SESSION test_session ON SERVER

    ADD EVENT sqlserver.error_reported

          (ACTION (sqlserver.sql_text) WHERE severity = 2 and (not (message = 'filter')))

    ADD TARGET package0.asynchronous_file_target

    -- CONFIGURES THE FILE TARGET

    (set filename = 'c:\temp\data2.xel' , metadatafile = 'c:\temp\data2.xem')

    GO

     

    -- STARTS THE SESSION

    ALTER EVENT SESSION test_session ON SERVER STATE = START

    GO

     

    -- THIS EVENT WILL BE FILTERED BECAUSE SEVERITY != 2

    RAISERROR (N'PUBLISH', 1, 1, 7, 3, N'abcde');

    GO

    -- THIS EVENT WILL BE FILTERED BECAUSE MESSAGE = 'FILTER'

    RAISERROR (N'FILTER', 2, 1, 7, 3, N'abcde');

    GO

    -- THIS ERROR WILL BE PUBLISHED

    RAISERROR (N'PUBLISH', 2, 1, 7, 3, N'abcde');

    GO

     

    -- STOPS LISTENING FOR THE EVENT

    ALTER EVENT SESSION test_session ON SERVER

    STATE = STOP

    GO

     

    -- REMOVES THE EVENT SESSION FROM THE SERVER

    DROP EVENT SESSION test_session ON SERVER

    GO

    -- REMOVES THE EVENT SESSION FROM THE SERVER

    select CAST(event_data as XML) as event_data

    from sys.fn_xe_file_target_read_file

    ('c:\temp\data2*.xel','c:\temp\data2*.xem', null, null)

     

    This last statement will output one event with the following data:

    <event name="error_reported" package="sqlserver" id="100" version="1" timestamp="2010-03-05T23:15:05.481Z">

      <data name="error">

        <value>50000</value>

        <text />

      </data>

      <data name="severity">

        <value>2</value>

        <text />

      </data>

      <data name="state">

        <value>1</value>

        <text />

      </data>

      <data name="user_defined">

        <value>true</value>

        <text />

      </data>

      <data name="message">

        <value>PUBLISH</value>

        <text />

      </data>

      <action name="sql_text" package="sqlserver">

        <value>-- THIS ERROR WILL BE PUBLISHED

    RAISERROR (N'PUBLISH', 2, 1, 7, 3, N'abcde');

    </value>

        <text />

      </action>

    </event>

    If you see more events, check if you have deleted previous event files. If so, please run

     

    -- Deletes previous event files

    EXEC SP_CONFIGURE

    GO

    EXEC SP_CONFIGURE 'xp_cmdshell', 1

    GO

    RECONFIGURE

    GO

    XP_CMDSHELL 'del c:\temp\data*.xe*'

    GO

     

    or delete them manually.

     

    More Info on Events: Extended Event Events

    More Info on Targets: Extended Event Targets

    More Info on Sessions: Extended Event Sessions

    More Info on Actions: Extended Event Actions

    More Info on Predicates: Extended Event Predicates

  • Option Trading: Getting the most out of the event session options

    You can control different aspects of how an event session behaves by setting the event session options as part of the CREATE EVENT SESSION DDL. The default settings for the event session options are designed to handle most of the common event collection situations so I generally recommend that you just use the defaults. Like everything in the real world though, there are going to be a handful of “special cases” that require something different. This post focuses on identifying the special cases and the correct use of the options to accommodate those cases.

    There is a reason it’s called Default

    The default session options specify a total event buffer size of 4 MB with a 30 second latency. Translating this into human terms; this means that our default behavior is that the system will start processing events from the event buffer when we reach about 1.3 MB of events or after 30 seconds, which ever comes first.

    Aside: What’s up with the 1.3 MB, I thought you said the buffer was 4 MB?

    The Extended Events engine takes the total buffer size specified by MAX_MEMORY (4MB by default) and divides it into 3 equally sized buffers. This is done so that a session can be publishing events to one buffer while other buffers are being processed. There are always at least three buffers; how to get more than three is covered later.

    Using this configuration, the Extended Events engine can “keep up” with most event sessions on standard workloads. Why is this? The fact is that most events are small, really small; on the order of a couple hundred bytes. Even when you start considering events that carry dynamically sized data (eg. binary, text, etc.) or adding actions that collect additional data, the total size of the event is still likely to be pretty small. This means that each buffer can likely hold thousands of events before it has to be processed. When the event buffers are finally processed there is an economy of scale achieved since most targets support bulk processing of the events so they are processed at the buffer level rather than the individual event level. When all this is working together it’s more likely that a full buffer will be processed and put back into the ready queue before the remaining buffers (remember, there are at least three) are full.

    I know what you’re going to say: “My server is exceptional! My workload is so massive it defies categorization!” OK, maybe you weren’t going to say that exactly, but you were probably thinking it. The point is that there are situations that won’t be covered by the Default, but that’s a good place to start and this post assumes you’ve started there so that you have something to look at in order to determine if you do have a special case that needs different settings. So let’s get to the special cases…

    What event just fired?! How about now?! Now?!

    If you believe the commercial adage from Heinz Ketchup (Heinz Slow Good Ketchup ad on You Tube), some things are worth the wait. This is not a belief held by most DBAs, particularly DBAs who are looking for an answer to a troubleshooting question fast. If you’re one of these anxious DBAs, or maybe just a Program Manager doing a demo, then 30 seconds might be longer than you’re comfortable waiting. If you find yourself in this situation then consider changing the MAX_DISPATCH_LATENCY option for your event session. This option will force the event buffers to be processed based on your time schedule. This option only makes sense for the asynchronous targets since those are the ones where we allow events to build up in the event buffer – if you’re using one of the synchronous targets this option isn’t relevant.

    Avoid forgotten events by increasing your memory

    Have you ever had one of those days where you keep forgetting things? That can happen in Extended Events too; we call it dropped events. In order to optimizes for server performance and help ensure that the Extended Events doesn’t block the server if to drop events that can’t be published to a buffer because the buffer is full. You can determine if events are being dropped from a session by querying the dm_xe_sessions DMV and looking at the dropped_event_count field.

    Aside: Should you care if you’re dropping events?

    Maybe not – think about why you’re collecting data in the first place and whether you’re really going to miss a few dropped events. For example, if you’re collecting query duration stats over thousands of executions of a query it won’t make a huge difference to miss a couple executions. Use your best judgment.

    If you find that your session is dropping events it means that the event buffer is not large enough to handle the volume of events that are being published. There are two ways to address this problem. First, you could collect fewer events – examine you session to see if you are over collecting. Do you need all the actions you’ve specified? Could you apply a predicate to be more specific about when you fire the event? Assuming the session is defined correctly, the next option is to change the MAX_MEMORY option to a larger number. Picking the right event buffer size might take some trial and error, but a good place to start is with the number of dropped events compared to the number you’ve collected.

    Aside: There are three different behaviors for dropping events that you specify using the EVENT_RETENTION_MODE option. The default is to allow single event loss and you should stick with this setting since it is the best choice for keeping the impact on server performance low.

    You’ll be tempted to use the setting to not lose any events (NO_EVENT_LOSS) – resist this urge since it can result in blocking on the server. If you’re worried that you’re losing events you should be increasing your event buffer memory as described in this section.

    Some events are too big to fail

    A less common reason for dropping an event is when an event is so large that it can’t fit into the event buffer. Even though most events are going to be small, you might find a condition that occasionally generates a very large event. You can determine if your session is dropping large events by looking at the dm_xe_sessions DMV once again, this time check the largest_event_dropped_size. If this value is larger than the size of your event buffer [remember, the size of your event buffer, by default, is max_memory / 3] then you need a large event buffer.

    To specify a large event buffer you set the MAX_EVENT_SIZE option to a value large enough to fit the largest event dropped based on data from the DMV. When you set this option the Extended Events engine will create two buffers of this size to accommodate these large events. As an added bonus (no extra charge) the large event buffer will also be used to store normal events in the cases where the normal event buffers are all full and waiting to be processed. (Note: This is just a side-effect, not the intended use. If you’re dropping many normal events then you should increase your normal event buffer size.)

    Partitioning: moving your events to a sub-division

    Earlier I alluded to the fact that you can configure your event session to use more than the standard three event buffers – this is called partitioning and is controlled by the MEMORY_PARTITION_MODE option. The result of setting this option is fairly easy to explain, but knowing when to use it is a bit more art than science. First the science…

    You can configure partitioning in three ways: None, Per NUMA Node & Per CPU. This specifies the location where sets of event buffers are created with fairly obvious implication. There are rules we follow for sub-dividing the total memory (specified by MAX_MEMORY) between all the event buffers that are specific to the mode used:

    None: 3 buffers (fixed)
    Node: 3 * number_of_nodes
    CPU: 2.5 * number_of_cpus

    Here are some examples of what this means for different Node/CPU counts:

    Configuration

    None

    Node

    CPU

    2 CPUs, 1 Node

    3 buffers

    3 buffers

    5 buffers

    6 CPUs, 2 Node

    3 buffers

    6 buffers

    15 buffers

    40 CPUs, 5 Nodes

    3 buffers

    15 buffers

    100 buffers

     

    Aside: Buffer size on multi-processor computers

    As the number of Nodes or CPUs increases, the size of the event buffer gets smaller because the total memory is sub-divided into more pieces. The defaults will hold up to this for a while since each buffer set is holding events only from the Node or CPU that it is associated with, but at some point the buffers will get too small and you’ll either see events being dropped or you’ll get an error when you create your session because you’re below the minimum buffer size. Increase the MAX_MEMORY setting to an appropriate number for the configuration.

    The most likely reason to start partitioning is going to be related to performance. If you notice that running an event session is impacting the performance of your server beyond a reasonably expected level [Yes, there is a reasonably expected level of work required to collect events.] then partitioning might be an answer. Before you partition you might want to check a few other things:

    • Is your event retention set to NO_EVENT_LOSS and causing blocking? (I told you not to do this.) Consider changing your event loss mode or increasing memory.
    • Are you over collecting and causing more work than necessary? Consider adding predicates to events or removing unnecessary events and actions from your session.
    • Are you writing the file target to the same slow disk that you use for TempDB and your other high activity databases? <kidding> <not really> It’s always worth considering the end to end picture – if you’re writing events to a file you can be impacted by I/O, network; all the usual stuff.

    Assuming you’ve ruled out the obvious (and not so obvious) issues, there are performance conditions that will be addressed by partitioning. For example, it’s possible to have a successful event session (eg. no dropped events) but still see a performance impact because you have many CPUs all attempting to write to the same free buffer and having to wait in line to finish their work. This is a case where partitioning would relieve the contention between the different CPUs and likely reduce the performance impact cause by the event session.

    There is no DMV you can check to find these conditions – sorry – that’s where the art comes in. This is  largely a matter of experimentation. On the bright side you probably won’t need to to worry about this level of detail all that often. The performance impact of Extended Events is significantly lower than what you may be used to with SQL Trace. You will likely only care about the impact if you are trying to set up a long running event session that will be part of your everyday workload – sessions used for short term troubleshooting will likely fall into the “reasonably expected impact” category.

    Hey buddy – I think you forgot something

    OK, there are two options I didn’t cover: STARTUP_STATE & TRACK_CAUSALITY. If you want your event sessions to start automatically when the server starts, set the STARTUP_STATE option to ON. (Now there is only one option I didn’t cover.) I’m going to leave causality for another post since it’s not really related to session behavior, it’s more about event analysis.

    - Mike

  • Extended Blogs – Now cross posting to Sqlblog.com

    Thanks to some help from SQL MVP Adam Mechanic, the Extended Events blog is now being cross posted on SQLblog.com. Except for the first two posts (welcome message & Reading event data 101), these blogs will be identical so read whichever site you prefer, either the SQLblog version, or the original MSDN blog.

    - Mike

More Posts « Previous page
Powered by Community Server (Commercial Edition), by Telligent Systems
  Privacy Statement