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

  • Extended Events demos on Microsoft Virtual Academy

    I had an opportunity recently to contribute a presentation to the Microsoft Virtual Academy as part of the Mission Critical Confidence using SQL Server 2012 course offering. The MVA offers you a myriad of free training opportunities, so I encourage anyone who is interested in expanding your knowledge to take advantage of this offering.

    For those of you who don’t want to invest the time to go through the whole course, you can access my presentation here. I cover the following topics:

    • Integration of Extended Events into AlwaysOn troubleshooting.
    • Troubleshooting Login failures using client/server correlation.
    • Troubleshooting query performance issues using client/server correlation.

    I’m not sure how long content is made available on MVA, I got the impression that it would be removed as some point in the future, but should be there for at lease several months.

    - Mike

  • Issues with the system_health session in SQL Server 2012

    The ever alert Jonathan Kehayias (Blog | Twitter) sent me a question recently asking about the Extended Event UI used for showing predicates. In particular, he was wondering about the predicate for the wait_info event that is defined in the system_health session and was wondering what was going on.

    wait_info_pred

    It’s obvious what peaked Jonathan’s interest – all those error icons seem like there is a problem with the predicate. This post will explain what’s happening, why it’s happening and also document a problem that I discovered while investigating this and for which I will give you a solution.

    Bug or Artifact – You make the call

    I’d actually call this an artifact because the rows that have error icons are caused because of a change made somewhere else in SQL Server that result in the Filter UI not being able to resolve the integer value (map_key) we specify in the predicate to the name of an actual wait (map_value). The reason that the map_key cannot be resolved is because of changes made within SQL Server to the enumeration of our wait types. These changes don’t impact you directly, but it turns out they do mess with how our UI displays this filter. This is a little complex, but I’ll attempt to give you the short version…

    In order to save space we’ve created a special data type in extended events called a map, which allows us to use an integer to represent some known value. (OK, this probably isn’t really that complex for all you DBAs since you do it all the time with PK/FK relationships and lookup tables.) We store these mappings in dm_xe_map_values and the UI uses this DMV to resolve the map_value when it displays the filter. The wait_type field in the wait_info event is one of these map data types. Let’s take a simple example, we might write a filter for wait_info such as:

    wait_type = 120

    A quick check of dm_xe_map_values shows us that 120 is equivalent to the SOS_SCHEDULER_YIELD wait type, so the UI would display:

    wait_type | equal_uint64 | SOS_SCHEDULER_YIELD

    In the case of wait_type we get this mapping directly from within the SQL Server engine (this is true of many maps) so any changes to the list of wait_types are automatically represented in our map DMV. The reason you see blanks in the Value field in some cases is because the list of wait_types is not always contiguous; in other words, there are gaps in the map_key list because there are some numbers that have not been used yet. The change I referenced earlier, is that the unused regions used to be filled with place holder values (PADDING_##) but are now just missing in SQL Server 2012. You can convince yourself of this very easily by running the following query:

    SELECT TOP 50 * FROM sys.dm_xe_map_value
    .csharpcode, .csharpcode pre { font-size: small; color: black; font-family: consolas, "Courier New", courier, monospace; background-color: #ffffff; /*white-space: pre;*/ } .csharpcode pre { margin: 0em; } .csharpcode .rem { color: #008000; } .csharpcode .kwrd { color: #0000ff; } .csharpcode .str { color: #006080; } .csharpcode .op { color: #0000c0; } .csharpcode .preproc { color: #cc6633; } .csharpcode .asp { background-color: #ffff00; } .csharpcode .html { color: #800000; } .csharpcode .attr { color: #ff0000; } .csharpcode .alt { background-color: #f4f4f4; width: 100%; margin: 0em; } .csharpcode .lnum { color: #606060; }

    What you’ll see is the following:

    map_keys

    values

    0 UNKNOWN
    1-21 Lock waits
    22-31 Not used
    32-37 Latch waits
    38-47 Not used
    48-50 Pagelatch waits

    In the system_health session we specify a filter that selects for the waits that we want to collect, but but instead of specifying each wait independently we specify ranges. So for example, to collect all the PAGELATCH* waits, we’d use this predicate:

    (wait_type > 47 and wait_type < 54)
    .csharpcode, .csharpcode pre { font-size: small; color: black; font-family: consolas, "Courier New", courier, monospace; background-color: #ffffff; /*white-space: pre;*/ } .csharpcode pre { margin: 0em; } .csharpcode .rem { color: #008000; } .csharpcode .kwrd { color: #0000ff; } .csharpcode .str { color: #006080; } .csharpcode .op { color: #0000c0; } .csharpcode .preproc { color: #cc6633; } .csharpcode .asp { background-color: #ffff00; } .csharpcode .html { color: #800000; } .csharpcode .attr { color: #ff0000; } .csharpcode .alt { background-color: #f4f4f4; width: 100%; margin: 0em; } .csharpcode .lnum { color: #606060; }

    But from the table earlier in the post we know that wait_type 47 is not used, so when the UI looks up the value for 47, it comes back empty, which it perceives to be an error and marks it as such. Logically, this in not an error because 48 > 47 whether there happens to be a 47 in the list or not. The predicate still works, it’s just that the UI doesn’t know how to display it.

    You said there was an “issue”

    Yes I did, and thank you for reminding me.

    While I was investigating the UI artifact I noticed that there have been several additions to the wait_type list, and a few deletions, in SQL Server 2012 that has resulted in significant renumbering of the wait_types map. This has had the unfortunate result of changing the meaning of the filter that we specified for both wait_info and wait_info_external, to the point where system_health is not longer collecting the waits we consider important. This is definitely a bug, but one that we won’t be able to address until after RTM. Since we can’t get the fix in for RTM, I’m providing a script that will correct the system_health session here.

    This script will do the following:

    • If the system_health session exists, it will remove the wait_info & wait_info_external events and replace them with the corrected filter. Any modifications you’ve made to these events in your system_health session will be lost.
    • If the system_health session does not exist, it will created it.
    • If the system_health session is not running, it will be started.

    Download the fix for the system health session

  • Activity Tracking event session template is broken

    With the release of SQL Server 2012 RC0 you will notice that a number of new session templates have shown up in both the New Session Wizard and the New Session dialog. One template in particular, Activity Tracking, is unfortunately broken “out of the box.” We found this problem too late to be able to fix it before releases of the RTM product, but it’s pretty easy to fix.

    MVP Jonathan Kehayias has posted the steps to fix this problem along with a corrected copy of the Activity Tracking template – check it out.

    We are hoping to fix this in the first service pack of SQL Server 2012.

    - Mike

  • Introducing the Extended Events Reader

    Check out What's new for Extended Events in SQL Server Codenamed "Denali" CTP3 for an overview of all of the new functionality released in CTP3. This post covers the details of the “reader” API, which we call the XeReader, that you can use to programmatically access both XEL files and the near-live event stream from a running session. You can find information about the Extended Events object model in my earlier post: Introducing the Extended Events Object Model.

    Event stream defined

    An event stream is pretty much what it sounds like, a stream of events that comes out of a running session. You will not find an option to configure the event stream in the UI or Extended Events DDL, it is accessed using the API described in this post. All the session configuration is handled under the covers. There are a few things to understand about the event stream before I dive into some examples:

    • The event stream is asynchronous, not live, but to make the experience seem “more live” the event stream modifies the latency behavior of the source event session. When the event stream is hooked to an event session, the latency period specified by MAX_DISPATCH_LATENCY is changed to 3 seconds. When the event stream is disconnected, the latency is changed back to it’s original value. You may notice some odd behavior if you connect more than one XeReader to the same event session; the latency modification assumes only one connection so the first disconnect from the event session will revert the latency back to the original value (eg. no ref-counting).
    • The event stream aggressively follows the prime directive – if the application utilizing the event stream API gets far enough behind in processing events that it risks blocking the server, the application will be disconnected. This is to prevent a “client tracing” application from bringing down a server; a problem often documented with SQL Profiler. If the event rate from your event session is so high that it causes a disconnection, then the event file is a more appropriate target for you.

    Exploring the API

    From the point of view of the XeReader, there is no difference between an XEL file and an event stream aside from the mechanism used to obtain the data. The main object in the XeReader is the QueriableXEventData object, which returns an enumerable list of events.

    Using the XeReader API

    In order to code against the API you’ll need to add a reference to the following assembly:

    Microsoft.SqlServer.XEvent.Linq.dll

    You’ll also need to add the following namespaces to your classes.

    using Microsoft.SqlServer.XEvent.Linq;

    Note: By the time we release “Denali” you will also need to add a second namespace, Microsoft.SqlServer.Xevent, to your code. Just letting you know so it’s not a surprise.

    Reading an event file (XEL)

    The XeReader supports reading the legacy XEL/XEM from SQL Server 2008 & SQL Server 2008 R2 as well as the XEL file produced in SQL Server “Denali” CTP2 and above. There is no support for reading the files created in SQL Server “Denali” CTP1. There are three versions of the constructor that accept files:

    • A single string with a valid path.
    • A single string array containing a set of paths to XEL files.
    • Two string arrays containing sets of paths to XEL and XEM files respectively.

    The paths can be fully qualified files or any valid representation of a path using wildcards. Here are a couple examples:

    Read all XEL files from a specific location

    QueryableXEventData events = new QueryableXEventData(@"C:\Temp\myFile*.xel");

    Read a specified multiple of XEL files

    string[] fileList = new string[2];
    fileList[0] = @"C:\Temp\demo_trace_0_129418467298110000.xel";
    fileList[1] = @"C:\Temp\demo_trace_0_129391767647570000.xel";
    
    QueryableXEventData events = new QueryableXEventData(fileList);

    Provide both XEL and XEM files

    string[] xelFiles = new string[1];
    xelFiles[0] = @"C:\Temp\demo_trace_0_129418467298110000.xel";
    string[] xemFiles = new string[1];
    xemFiles[1] = @"C:\Temp\demo_trace_0_129418467298110000.xem";
    
    QueryableXEventData events = new QueryableXEventData(xelFiles, xemFiles);

    You get the idea.

    Reading an event stream

    You can read a stream from a running session by providing a connection string and event session name to the constructor along with a couple extra options.

    QueryableXEventData stream = new QueryableXEventData(
        @"Data Source = (local); Initial Catalog = master; Integrated Security = SSPI", 
    "alert_me", EventStreamSourceOptions.EventStream, EventStreamCacheOptions.DoNotCache);
    • EventStreamSourceOptions – EventStream is the only option that exists at this point. We’ll be adding one more option before we release but I’ll leave that for a later blog post when it’s relevant.
    • EventStreamCacheOptions – You can either choose to not cache any data (DoNotCache) or to cache the data (CacheToDisk). This option determines whether you can enumerate across the history of events that have come from the stream. The DoNotCache option will pull events from the server as fast as possible and keep them in memory as long as possible. It is possible for events to be ejected from memory before they are processed by the enumerator. The CacheToDisk option will store events to the disk until the disk is full.
    Working with the Events

    The constructors all return an enumerable collection of type PublishedEvent, so the code to work with the events is identical regardless of source. I’ll cover the basics here to get you started.

    You can loop through the collection of events just like you would expect for an enumerable object so you can imagine using a foreach to process each event. Additionally, each PublishedEvent object, contains collections for Fields and Actions that return the PublishedEventField and PublishedAction objects respectively. Taken together it’s a straight forward operation to list out all the events along with their fields and actions using code similar to this:

    foreach (PublishedEvent evt in events)
    {
          Console.WriteLine(evt.Name);
    
          foreach (PublishedEventField fld in evt.Fields)
            {
                Console.WriteLine("\tField: {0} = {1}", fld.Name, fld.Value);
            }
    
          foreach (PublishedAction act in evt.Actions)
            {
                Console.WriteLine("\tAction: {0} = {1}", act.Name, act.Value);
            } 
    }

    You can perform conditional expressions as you would expect, say if you wanted to perform an action based on a specific value being returned from a field:

    if (evt.Fields["field_name"].Value == "foo")

    or

    if (fld.Value == "foo")

    It is worth pointing out some “weirdness” associated with map fields if you want to evaluate using the friendly text that you would find in dm_xe_map_values rather than the integer map_key. You have to explicitly cast the field to a MapValue:

    if (((MapValue)evt.Fields["field_name"].Value).Value == "foo" )

    Again, you get the idea. This is really the core of the XeReader and the part I expect you’ll be working with the most. To make your life a little easier, I’ve attached a files that contains all this code in a runnable format, just add a reference to the assembly and you should be ready to start experimenting.

    Download the Extended Event Reader sample code

    Happy Eventing

    - Mike

  • Introducing the Extended Events User Interface

    Check out What's new for Extended Events in SQL Server Codenamed "Denali" CTP3 for an overview of all of the new functionality released in CTP3. This post details the new user interface. In my overview post I mentioned that the user interface is built directly into management studio (SSMS) and that there are four parts:

    1. The session list in Object Explorer.
    2. A Create Session wizard.
    3. A Create Session dialog.
    4. A display grid.

    This post focuses on the mechanisms for creating event sessions and displaying event session data.

    Creating and modifying event sessions

    The New Session Wizard and dialog share many common UI elements, so I’ll just cover the dialog. If a notable difference exists for the wizard, I’ll call it out at the appropriate place. A picture is worth a thousand words, so here is the pictorial tour of the new user interface.

    General page

     

    The General page collects the basic information about the session:

    · Name – You can figure this one out.

    · Template – We’ve carried over the idea of templates similar to SQL Profiler. You can export any session you’ve created to a template (Expand the context menu of your event session and click Export Session…). If you save the template to the default location, it will show up in this dropdown under the User Templates category.

    · Schedule – You can choose to make this an Autostart event session, start the session immediately after you complete the dialog and even choose to start up the event stream viewer. (More on that later.)

    · Causality Tracking – Turn on the correlation ids in your trace.

    Wizard differences: These options are spread across three different wizard steps.

    Event page - Library
    The Event page has a couple parts. The Event Library allows you to select which events you want to add to your event session. The library supports Excel-like filtering using dropdown lists for Category and Channel. You can also search for specific events by just typing in the search text box. You choose an event by double-clicking or by selecting it and clicking the right arrow to move it to the Selected events list. We support Shift+Click and Ctrl+Click for choosing multiple events at once.
    Event page – Configure

    In Extended Events, each event can be extended to include additional data or cause a specific action, only fire under defined conditions and to enable optional fields. Clicking on the Configure button takes you to the advanced event configuration options. You configure an event by selecting it in the Selected events list and then setting the configuration options on one of the tabs. When you select multiple events, the configuration options will apply to all selected events.

    The Global Fields (Actions) tab allows you select the list of Actions that you want to append to the event(s).

    The Filter (Predicate) tab is used to define the conditions under which the event will be collected.

    The Event Fields table allows you to enable or disable the collection of optional fields. (Fields without a checkbox are always collected.) You can also see the description and data type of each field on this tab.

    Wizard differences: Global Fields and Predicates apply to all selected events. You cannot configure the events individually.

    Data Storage page

    You determine how the event session data is stored on this page by specifying the target for the session. You can specify more than one target for any session, but you can only use each target once. Each target will present a set of configuration options on the bottom of the page.

    Wizard differences: The wizard supports only the event file and ring buffer targets.

    Advanced page

    Configure the options for the entire event session here. We use the same defaults you would get with the DDL syntax.

    Wizard differences: You cannot configure the event session options in the wizard, the defaults are used.

    Other stuff

    You may have noticed from the screen shots that you can script out your configured event session from the user interface using the button at the top of the page. The button becomes enabled as soon as you have enough of the event session configured such that the DDL would execute without error.

    You can change the configuration of an event session by right-clicking the session name in Object Explorer and clicking Properties. The same user interface will be presented showing all your configured settings. Most settings can be changed on a running session, but you’ll need to stop the session to change the Advanced options. You cannot change the target configuration (Data Storage page) on an existing target, you’ll need to delete the target and re-add it to change that. You will also find that the Script button is not enabled in the Properties dialog, you can still script your event session to DDL, but you’ll need to do it from Object Explorer by right-clicking the session name and choosing one of the Script Session as… commands.

    Wizard differences: The wizard is not re-entrant. Sessions created in the wizard can be modified using the Property dialog just like any other session.

    Viewing event session data

    SSMS includes an event session data viewer for all of the supported targets with the exception of the ETW file target. (There are many other tools for working with ETL files.) There are basically two different types of event session data display.

    In-memory targets

    The in-memory targets include: ring buffer, event counter, histogram and event pairing. The data from these targets is displayed in a simple grid format.

    By default you see a “point in time” view of the data when you opened the display. You can either manually refresh the data or have it refresh on a schedule from the context menu. The ring buffer is a bit special in that the display shows you a single row containing the XML output of the ring buffer. You can double-click the row to open an XML document, but there is no event by event grid view for the ring buffer, sorry.

    Event stream and event file

    You can open a “live view” of a running session by right-clicking on the session name and choosing the Watch Live Data menu item. This will open a page in SSMS that provides you with a scrolling display of the events as they come from the event session. This is similar to the behavior that exists in SQL Profiler with the major difference being that Extended Events does not cause the performance degradation that you might be used to with SQL Profiler. Extended Events will never block the server waiting for the client event stream view; we’re so serious about this that the event stream is disconnected if the client becomes too slow that it will block the server workload. (Remember the prime directive – this is one of those tradeoffs.) If you have a very busy server (eg. lots of events) the file target will be a more appropriate target.

    The event file target uses the XEL extension by default, and that extension is associated with SSMS so that you can open an event file by double-clicking or simply dragging it onto the SSMS window. You can also open event files in two different ways from the File menu:

    File | Open | File – Pick an XEL file and click Open

    File | Open | Merge Extended Event files – Use the dialog to collect multiple files to be merged

    Both the event steam and event files are displayed in the same user interface:

    The picture is a bit small, but you get the idea. Open up an XEL file in SSMS to get the full experience.

    The first thing you won’t notice, but now you will because I’m telling you, is that there is a custom toolbar for Extended Events; there is also a menu added. You can control all the functionality of the display UI using these. The first thing you will notice is that the default view has only two columns, name and timestamp, all the other columns for an event are shown in the Details pane when you select a specific row in the grid. There is a bunch of functionality in this UI, almost too much to fit into a summary such as this, so I’ll hit the high points and let you explore.

    · You can add additional columns to the grid by either right-clicking the in the Details pane and choosing Show Column in Table or by clicking the Choose Columns button to open the Choose Columns dialog.

    · You can Find event records using the typical SSMS find behavior.

    · You can Bookmark records of interest and move between bookmarked records.

    · You can apply a filter to the results using a flexible criteria builder. (This is worth a picture; so much better than SQL Profiler!)

    · You can use the Grouping and Aggregation commands to do some basic analysis of your data directly in the display UI.

    · You can save the configuration of the display table (columns, filter, sorting and group/aggregation) using the View Settings button. (Note: This button name may change before RTM.)

    · You can export the list of events to a SQL Server table, CSV or XEL using the Export to menu item. (Note: This is only on the menu, not the command bar.)

    · You can Start and Stop the collection of the data and control the scrolling of the data in the window for the event stream.

    That about wraps up the pictorial tour of the new Extended Events user interface. Take it out for a spin and let us know what you think. If you find any problems, or have suggestions for future versions, please post them to Microsoft Connect.  If you have questions, post them to the SQL Server Database Engine forum.

    Happy Eventing!

    - Mike

  • What’s New for Extended Events in SQL Server Codenamed “Denali” CTP3

    CTP3 is finally here and the crowd goes wild! Since I’m sure everyone has been anticipating the CTP3 updates to Extended Events (because, let’s face it, Extended Events is the most important part of the product, right?) let’s get to it.

    Introduction

    I’m going to cover the new features at a high level in this post and then drill into a couple specific features in more detail in posts dedicated to that topic. Before I get into the “meat” of this post I wanted to spend a few sentence writing about the design philosophy we’ve followed as we’ve created Extended Events. Every feature gets to a point where a trade-off has to be made and the design philosophy guides us in making those trade-offs.

    Foremost is our prime directive (not that I’m a Star Trek™ fan):

    The most important workload on the server is the customer workload; diagnostic systems should not prevent the customer workload from running.

    This doesn’t mean that a diagnostic workload won’t impact server performance, it will. It means that in cases where we have to make a choice between the activity of the customer workload and the diagnostic workload, the customer workload wins, period. This has been the prime directive of the Extended Events team since the beginning and it didn’t change in “Denali.”

    The goal for “Denali” has been twofold:

    1. Provide a diagnostic tracing facility, built on Extended Events, that will not just replace the existing SQL Trace/SQL Profiler based system, but exceed it.
    2. Drastically improve the usability of Extended Events.

    A significant part of meeting our first goal was accomplished in CTP1 by providing data parity with SQL Trace event classes. I’ve already discussed migration from SQL Trace to Extended Events in the blog, so I won’t go into details about that work here. With that preamble, let’s take a look and how we accomplished the second goal.

    Extended Events User Interface

    Get more details: Introducing the Extended Events User Interface

    This won’t be a surprise to many of you, but we’ve created a user interface for Extended Events and you’ll find it in CTP3. Having a user interface was the most common user request, by far, and we listened. SQL Profiler is too important to not have equivalent functionality. Making it much easier to configure and read event sessions is the primary way we delivered on our usability goal. The Extended Events user interface is built directly into SSMS and there are four primary pieces:

    • Session list – You will find a list of sessions within the Object Explorer under the node Management | Extended Events | Sessions.
    • New Session Wizard – A wizard (duh) that provides a simplified experience for creating an event session. Only the most common options and functionality is exposed with everything else being configured automatically. Expand the context menu of the Sessions node and click New Session Wizard.
    • New Session dialog – The complete set of Extended Events configuration in handy dialog format. Expand the context menu of the Sessions node and click New Session…. The same dialog is used for creating new sessions and for modifying existing sessions (click Properties on the context menu).
    • Extended Events display – A collection of SSMS pages (tabs like the Query window) that display Extended Events trace data.

    The user interface you designed…really

    We didn’t just listen to the feedback that we needed a user interface, we also listened to the feedback we got throughout the design and development process. This UI represents more than just the work of the Microsoft development team, but also the feedback of many SQL Server MVPs, usability study participants and anyone who would talk to us at the various conferences where we presented the UI. We took something useful away from every customer interaction and made significant changes based on that feedback. Thanks to everyone who took the time to provide your feedback. (And keep it coming – as you explore CTP3 send us your feedback using Microsoft Connect.)

    You might want to sit down for this next section

    It’s an unpopular word, but I have to say it … Deprecation.

    Yeah, I said it; we are announcing deprecation of SQL Trace in Denali. Before everyone goes off the deep end, remember, this is only the announce phase which means that nothing actually changes in Denali, we’re just letting you know that we’re phasing it out in favor of the new system over the next few releases so now is a good time to start investigating how to migrate. (See the link in the Introduction for more details.)

    Programming Extended Events

    Get more details: Introducing the Extended Events Reader

    Another important aspect of creating a usable diagnostic system is a programmatic interface. (Not everyone loves DDL as much as we do apparently.) We’ve covered this in two pieces:

    • A “management” API that lets you create and modify event sessions as well as explore the Extended Events metadata on a server. This API was release in CTP1 and I’ve already provided examples in my post Introducing the Extended Events Object Model.
    • A “reader” API that provides functionality for reading event files (XEL) and event streams coming from a running event session.

    The UI is built on top of these APIs so you have all the capabilities you need to write your own customized tools for working with Extended Events.

    The “other” stuff

    There are always a host of little things that we add, change or fix when we’re improving a feature. I don’t want to deprive anyone of the “Joy of Discovery” that comes with finding these little bits and pieces, so stop reading now if you want to hunt them down on your own. For the rest of you, here is the list of bits and pieces that we hope will make the Extended Events world a little better for you.

    Some (target) names have been changed to protect the innocent

    We’ve changed the names of some of the targets to be friendlier:

    Old Target Name

    New Target Name

    asynchronous_file_target

    event_file

    synchronous_event_counter

    event_counter

    asynchronous_bucketizer

    histogram

    synchronous_bucketizer

    histogram (I’ll explain below)

    To make this change easier we’ve done some work under the covers:

    • ADD TARGET with the old target names will still work. We do name fixup inside SQL Server when we execute the DDL.
    • DROP TARGET with the old target names will not work. We fixed up the names so there are no records in the catalog with the old names.
    • The target_name field of dm_xe_session_targets will be fixed up to have the new target names for any running sessions during Upgrade.
    • The name field of server_event_session_targets will be fixed up to have the new target names for any configured session during Upgrade.

    Note on histogram target – There is not strong evidence to support that people are using both the synchronous and asynchronous bucketizer together in a single session so we used the renaming event to also eliminate this duplication. We have a single histogram target now that is asynchronous.

    There can be only one – file that is

    We’ve eliminated the metadata file all together. That’s right, no more XEM file, it just didn’t make sense and it’s kind of a pain to have to worry about dragging the extra file around if you’re sending logs to other folks. Both the server reader function, fn_xe_file_target_read_file and the new Reader API are fully backwards compatible with the SQL Server 2008 and SQL Server 2008 R2 “dual file” format.

    Note: We do not support the XEL/XEM files created in SQL Server Codenamed “Denali” CTP1.

    The single file model has some downstream implications for event_file target and the fn_xe_file_target_read_file function.

    event_file – You no longer need to set the metadatafile attribute but it is still available (but optional) so as not to break your DDL scripts. If you do provide a value for metadatafile it will be ignored for valid paths and it will throw an error for invalid paths.

    fn_xe_file_target_read_file – The mdpath attribute is optional and ignored (but will throw if you provide an invalid path) when the filename path represents “Denali” XEL version files. You should just pass ‘NULL’ for mdpath as you would for all other optional attributes.

    New options available for some targets

    We’ve added a few new options to make some of the targets a bit more flexible.

    pair_matching – In order to help prevent the pair_matching target from running amok in cases where you have an excessive number of orphaned records we’ve added the max_orphans option to the target with a default of 10000. As you might surmise, this option controls the number of orphaned records that will be maintained in the pair_matching target.

    ring_buffer – We’ve introduce the max_events_limit for the ring_buffer to provide a deterministic way to control the number of events in the target. The default value is 1000 and we’ve changed the default for max_memory to be unlimited, meaning that the ring_buffer will use as much memory as required to store 1000 events by default. You can set one or both of these. When both are set we’ll honor the one that is hit first.

    Wrapping up

    Now that you have the overview go ahead and take Extended Events out for a spin. Dig into the detailed posts for more information about the UI and the programmatic APIs. If you find any issues or have suggestions for future advancements please post an item into Microsoft Connect so that others can vote on it. If you have questions, post them to the SQL Server Database Engine forum.

    Happy Eventing!

    - Mike

  • Sampling SQL server batch activity

    Recently I was troubleshooting a performance issue on an internal tracking workload and needed to collect some very low level events over a period of 3-4 hours.  During analysis of the data I found that a common pattern I was using was to find a batch with a duration that was longer than average and follow all the events it produced. 

    This pattern got me thinking that I was discarding a substantial amount of event data that had been collected, and that it would be great to be able to reduce the collection overhead on the server if I could still get all activity from some batches.

    In the past I’ve used a sampling technique based on the counter predicate to build a baseline of overall activity (see Mikes post here).  This isn’t exactly what I want though as there would certainly be events from a particular batch that wouldn’t pass the predicate.  What I need is a way to identify streams of work and select say one in ten of them to watch, and sql server provides just such a mechanism: session_id.  Session_id is a server assigned integer that is bound to a connection at login and lasts until logout.  So by combining the session_id predicate source and the divides_by_uint64 predicate comparator we can limit collection, and still get all the events in batches for investigation.

    CREATE EVENT SESSION session_10_percent ON SERVER

    ADD EVENT sqlserver.sql_statement_starting(

        WHERE (package0.divides_by_uint64(sqlserver.session_id,10))),

    ADD EVENT sqlos.wait_info (

           WHERE (package0.divides_by_uint64(sqlserver.session_id,10))),

    ADD EVENT sqlos.wait_info_external (

           WHERE (package0.divides_by_uint64(sqlserver.session_id,10))),

    ADD EVENT sqlserver.sql_statement_completed(

        WHERE (package0.divides_by_uint64(sqlserver.session_id,10)))

    ADD TARGET ring_buffer

    WITH (MAX_DISPATCH_LATENCY=30 SECONDS,TRACK_CAUSALITY=ON)

    GO

     

    There we go; event collection is reduced while still providing enough information to find the root of the problem. 

    By the way the performance issue turned out to be an IO issue, and the session definition above was more than enough to show long waits on PAGEIOLATCH*.

     

     

     

     

  • Introducing the Extended Events Object Model

    The primary focus we’ve had for Extended Events in SQL Server codenamed “Denali” is to offer a better user experience by providing options for working with the system beyond DDL. One of those options is the availability of a managed code object model. In this post I’ll describe the object model and it’s usage as well as provide sample code that shows how various objects are used.

    In the graphic below you can see that there are two “sides” of the object model:

    Metadata: Describes the set of events, actions, targets, etc. that are available on the system. All access to the metadata objects has to go through the Package object.

    Runtime: Describes the event sessions that are configured and various aspects of their runtime state. All access to the runtime objects has to go through the Session object.

    image

    The top level object is named XEStore; you get to the XEStore by connecting to the program that uses Extended Events. At the current time the object model supports the SQL Server database engine, <teaser> but in the future there will likely be others.</teaser> <bummer>(Sorry, I can’t discuss when or what at this point.)</bummer> The object model is based on the SFC Framework which isn’t particularly important for most of the XE objects, but the XEStore is a type of SfcConnection so I thought it worth mentioning. Since we’re specifically after the XEStore in SQL Server, I’m using a SqlStoreConnection, which inherits SfcConnection, and I need to pass in a normal SqlConnection to get to my server.

    private static XEStore ConnectToXEStore()
    {
        Microsoft.SqlServer.Management.Sdk.Sfc.SqlStoreConnection server;
        SqlConnectionStringBuilder conBuild = new SqlConnectionStringBuilder();
        conBuild.DataSource = "(local)";
        conBuild.InitialCatalog = "master";
        conBuild.IntegratedSecurity = true;
    
        // Create the actual SqlStoreConnection...
        server = new Microsoft.SqlServer.Management.Sdk.Sfc.SqlStoreConnection
    (new SqlConnection(conBuild.ConnectionString.ToString())); // ...and then create the XEStore to return to the calling function. return new XEStore(server); }

    In this case I’m using the SqlConnectonStringBuilder for clarity, but you can see how I could have just passed a connection string directly into the SqlStoreConnection constructor. The connection to the XEStore is the part that changes if I connect to a different program that uses Extended Events. Everything else will be identical.

    In the interest of keeping this post short and helping you avoid a boat-load of Copy/Paste activities, I’ve just put all the sample code into a .cs file with comments throughout to help explain the various objects and tie them back to the Extended Event DMVs and Catalog that you’re already familiar with. I tested this code on the current, public CTP, so things should be working, but let me know if you run into any problems.

    - Mike

    Download sample code: XeObjectModel.cs

  • Migrating from SQL Trace to Extended Events

    In SQL Server codenamed “Denali” we are moving our diagnostic tracing capabilities forward by building a system on top of Extended Events. With every new system you face the specter of migration which is always a bit of a hassle. I’m obviously motivated to see everyone move their diagnostic tracing systems over to the new extended events based system, so I wanted to make sure we lowered the bar for the migration process to help ease your trials.

    In my initial post on Denali CTP 1 I described a couple tables that we created that will help map the existing SQL Trace Event Classes to the equivalent Extended Events events. In this post I’ll describe the tables in a bit more details, explain the relationship between the SQL Trace objects (Event Class & Column) and Extended Event objects (Events & Actions) and at the end provide some sample code for a managed stored procedure that will take an existing SQL Trace session (eg. a trace that you can see in sys.Traces) and converts it into event session DDL.

    Can you relate?

    In some ways, SQL Trace and Extended Events is kind of like the Standard and Metric measuring systems in the United States. If you spend too much time trying to figure out how to convert between the two it will probably make your head hurt. It’s often better to just use the new system without trying to translate between the two. That said, people like to relate new things to the things they’re comfortable with, so, with some trepidation, I will now explain how these two systems are related to each other. First, some terms…

    SQL Trace is made up of Event Classes and Columns. The Event Class occurs as the result of some activity in the database engine, for example, SQL:Batch Completed fires when a batch has completed executing on the server. Each Event Class can have any number of Columns associated with it and those Columns contain the data that is interesting about the Event Class, such as the duration or database name.

    In Extended Events we have objects named Events, EventData field and Actions. The Event (some people call this an xEvent but I’ll stick with Event) is equivalent to the Event Class in SQL Trace since it is the thing that occurs as the result of some activity taking place in the server. An  EventData field (from now on I’ll just refer to these as fields) is a piece of information that is highly correlated with the event and is always included as part of the schema of an Event. An Action is something that can be associated with any Event and it will cause some additional “action” to occur when ever the parent Event occurs. Actions can do a number of different things for example, there are Actions that collect additional data and, take memory dumps.

    When mapping SQL Trace onto Extended Events, Columns are covered by a combination of both fields and Actions. Knowing exactly where a Column is covered by a field and where it is covered by an Action is a bit of an art, so we created the mapping tables to make you an Artist without the years of practice.

    Let me draw you a map.

    Event Mapping

    The table dbo.trace_xe_event_map exists in the master database with the following structure:

    Column_name

    Type

    trace_event_id

    smallint

    package_name

    nvarchar

    xe_event_name

    nvarchar

    By joining this table sys.trace_events using trace_event_id and to the sys.dm_xe_objects using xe_event_name you can get a fair amount of information about how Event Classes are related to Events. The most basic query this lends itself to is to match an Event Class with the corresponding Event.

    SELECT
        t.trace_event_id,
        t.name [event_class],
        e.package_name,
        e.xe_event_name
    FROM sys.trace_events t INNER JOIN dbo.trace_xe_event_map e
        ON t.trace_event_id = e.trace_event_id

    There are a couple things you’ll notice as you peruse the output of this query:

    • For the most part, the names of Events are fairly close to the original Event Class; eg. SP:CacheMiss == sp_cache_miss, and so on.
    • We’ve mostly stuck to a one to one mapping between Event Classes and Events, but there are a few cases where we have combined when it made sense. For example, Data File Auto Grow, Log File Auto Grow, Data File Auto Shrink & Log File Auto Shrink are now all covered by a single event named database_file_size_change. This just seemed like a “smarter” implementation for this type of event, you can get all the same information from this single event (grow/shrink, Data/Log, Auto/Manual growth) without having multiple different events. You can use Predicates if you want to limit the output to just one of the original Event Class measures.
    • There are some Event Classes that did not make the cut and were not migrated. These fall into two categories; there were a few Event Classes that had been deprecated, or that just did not make sense, so we didn’t migrate them. (You won’t find an Event related to mounting a tape – sorry.) The second class is bigger; with rare exception, we did not migrate any of the Event Classes that were related to Security Auditing using SQL Trace. We introduced the SQL Audit feature in SQL Server 2008 and that will be the compliance and auditing feature going forward. Doing this is a very deliberate decision to support separation of duties for DBAs. There are separate permissions required for SQL Audit and Extended Events tracing so you can assign these tasks to different people if you choose. (If you’re wondering, the permission for Extended Events is ALTER ANY EVENT SESSION, which is covered by CONTROL SERVER.)

    Action Mapping

    The table dbo.trace_xe_action_map exists in the master database with the following structure:

    Column_name

    Type

    trace_column_id

    smallint

    package_name

    nvarchar

    xe_action_name

    nvarchar

    You can find more details by joining this to sys.trace_columns on the trace_column_id field.

    SELECT
        c.trace_column_id,
        c.name [column_name],
        a.package_name,
        a.xe_action_name
    FROM sys.trace_columns c INNER JOIN    dbo.trace_xe_action_map a
        ON c.trace_column_id = a.trace_column_id

    If you examine this list, you’ll notice that there are relatively few Actions that map to SQL Trace Columns given the number of Columns that exist. This is not because we forgot to migrate all the Columns, but because much of the data for individual Event Classes is included as part of the EventData fields of the equivalent Events so there is no need to specify them as Actions.

    Putting it all together

    If you’ve spent a bunch of time figuring out the inner workings of SQL Trace, and who hasn’t, then you probably know that the typically set of Columns you find associated with any given Event Class in SQL Profiler is not fix, but is determine by the contents of the table sys.trace_event_bindings. We’ve used this table along with the mapping tables to produce a list of Event + Action combinations that duplicate the SQL Profiler Event Class definitions using the following query, which you can also find in the Books Online topic How To: View the Extended Events Equivalents to SQL Trace Event Classes.

    USE MASTER;
    GO
    SELECT DISTINCT
       tb.trace_event_id,
       te.name AS 'Event Class',
       em.package_name AS 'Package',
       em.xe_event_name AS 'XEvent Name',
       tb.trace_column_id,
       tc.name AS 'SQL Trace Column',
       am.xe_action_name as 'Extended Events action'
    FROM (sys.trace_events te LEFT OUTER JOIN dbo.trace_xe_event_map em
       ON te.trace_event_id = em.trace_event_id) LEFT OUTER JOIN sys.trace_event_bindings tb
       ON em.trace_event_id = tb.trace_event_id LEFT OUTER JOIN sys.trace_columns tc
       ON tb.trace_column_id = tc.trace_column_id LEFT OUTER JOIN dbo.trace_xe_action_map am
       ON tc.trace_column_id = am.trace_column_id
    ORDER BY te.name, tc.name

    As you might imagine, it’s also possible to map an existing trace definition to the equivalent event session by judicious use of fn_trace_geteventinfo joined with the two mapping tables. This query extracts the list of Events and Actions equivalent to the trace with ID = 1, which is most likely the Default Trace. You can find this query, along with a set of other queries and steps required to migrate your existing traces over to Extended Events in the Books Online topic How to: Convert an Existing SQL Trace Script to an Extended Events Session.

    USE MASTER;
    GO
    DECLARE @trace_id int
    SET @trace_id = 1
    SELECT DISTINCT el.eventid, em.package_name, em.xe_event_name AS 'event'
       , el.columnid, ec.xe_action_name AS 'action'
    FROM (sys.fn_trace_geteventinfo(@trace_id) AS el
       LEFT OUTER JOIN dbo.trace_xe_event_map AS em
          ON el.eventid = em.trace_event_id)
    LEFT OUTER JOIN dbo.trace_xe_action_map AS ec
       ON el.columnid = ec.trace_column_id
    WHERE em.xe_event_name IS NOT NULL AND ec.xe_action_name IS NOT NULL

    You’ll notice in the output that the list doesn’t include any of the security audit Event Classes, as I wrote earlier, those were not migrated.

    But wait…there’s more!

    If this were an infomercial there’d by some obnoxious guy next to me blogging “Well Mike…that’s pretty neat, but I’m sure you can do more. Can’t you make it even easier to migrate from SQL Trace?”  Needless to say, I’d blog back, in an overly excited way, “You bet I can' obnoxious blogger side-kick!” What I’ve got for you here is a Extended Events Team Blog only special – this tool will not be sold in any store; it’s a special offer for those of you reading the blog.

    I’ve wrapped all the logic of pulling the configuration information out of an existing trace and and building the Extended Events DDL statement into a handy, dandy CLR stored procedure. Once you load the assembly and register the procedure you just supply the trace id (from sys.traces) and provide a name for the event session. Run the procedure and out pops the DDL required to create an equivalent session. Any aspects of the trace that could not be duplicated are included in comments within the DDL output.

    This procedure does not actually create the event session – you need to copy the DDL out of the message tab and put it into a new query window to do that. It also requires an existing trace (but it doesn’t have to be running) to evaluate; there is no functionality to parse t-sql scripts. I’m not going to spend a bunch of time explaining the code here – the code is pretty well commented and hopefully easy to follow. If not, you can always post comments or hit the feedback button to send us some mail.

     

    Installing the procedure

    Just in case you’re not familiar with installing CLR procedures…once you’ve compile the assembly you can load it using a script like this:

    -- Context to master
    USE master
    GO

    -- Create the assembly from a shared location.
    CREATE ASSEMBLY TraceToXESessionConverter
    FROM 'C:\Temp\TraceToXEventSessionConverter.dll'
    WITH PERMISSION_SET = SAFE
    GO

    -- Create a stored procedure from the assembly.
    CREATE PROCEDURE CreateEventSessionFromTrace
    @trace_id int,
    @session_name nvarchar(max)
    AS
    EXTERNAL NAME TraceToXESessionConverter.StoredProcedures.ConvertTraceToExtendedEvent
    GO

    Enjoy!

    -Mike

  • Session memory – who’s this guy named Max and what’s he doing with my memory?

    SQL Server MVP Jonathan Kehayias (blog) emailed me a question last week when he noticed that the total memory used by the buffers for an event session was larger than the value he specified for the MAX_MEMORY option in the CREATE EVENT SESSION DDL. The answer here seems like an excellent subject for me to kick-off my new “401 – Internals” tag that identifies posts where I pull back the curtains a bit and let you peek into what’s going on inside the extended events engine.

    In a previous post (Option Trading: Getting the most out of the event session options) I explained that we use a set of buffers to store the event data before  we write the event data to asynchronous targets. The MAX_MEMORY along with the MEMORY_PARTITION_MODE defines how big each buffer will be. Theoretically, that means that I can predict the size of each buffer using the following formula:

    max memory / # of buffers = buffer size

    If it was that simple I wouldn’t be writing this post.

    I’ll take “boundary” for 64K Alex

    For a number of reasons that are beyond the scope of this blog, we create event buffers in 64K chunks. The result of this is that the buffer size indicated by the formula above is rounded up to the next 64K boundary and that is the size used to create the buffers. If you think visually, this means that the graph of your max_memory option compared to the actual buffer size that results will look like a set of stairs rather than a smooth line. You can see this behavior by looking at the output of dm_xe_sessions, specifically the fields related to the buffer sizes, over a range of different memory inputs:

    Note: This test was run on a 2 core machine using per_cpu partitioning which results in 5 buffers. (Seem my previous post referenced above for the math behind buffer count.)

    input_memory_kb

    total_regular_buffers

    regular_buffer_size

    total_buffer_size

    637

    5

    130867

    654335

    638

    5

    130867

    654335

    639

    5

    130867

    654335

    640

    5

    196403

    982015

    641

    5

    196403

    982015

    642

    5

    196403

    982015

    This is just a segment of the results that shows one of the “jumps” between the buffer boundary at 639 KB and 640 KB. You can verify the size boundary by doing the math on the regular_buffer_size field, which is returned in bytes:

    196403 – 130867 = 65536 bytes

    65536 / 1024 = 64 KB

    The relationship between the input for max_memory and when the regular_buffer_size is going to jump from one 64K boundary to the next is going to change based on the number of buffers being created. The number of buffers is dependent on the partition mode you choose. If you choose any partition mode other than NONE, the number of buffers will depend on your hardware configuration. (Again, see the earlier post referenced above.) With the default partition mode of none, you always get three buffers, regardless of machine configuration, so I generated a “range table” for max_memory settings between 1 KB and 4096 KB as an example.

    start_memory_range_kb

    end_memory_range_kb

    total_regular_buffers

    regular_buffer_size

    total_buffer_size

    1

    191

    NULL

    NULL

    NULL

    192

    383

    3

    130867

    392601

    384

    575

    3

    196403

    589209

    576

    767

    3

    261939

    785817

    768

    959

    3

    327475

    982425

    960

    1151

    3

    393011

    1179033

    1152

    1343

    3

    458547

    1375641

    1344

    1535

    3

    524083

    1572249

    1536

    1727

    3

    589619

    1768857

    1728

    1919

    3

    655155

    1965465

    1920

    2111

    3

    720691

    2162073

    2112

    2303

    3

    786227

    2358681

    2304

    2495

    3

    851763

    2555289

    2496

    2687

    3

    917299

    2751897

    2688

    2879

    3

    982835

    2948505

    2880

    3071

    3

    1048371

    3145113

    3072

    3263

    3

    1113907

    3341721

    3264

    3455

    3

    1179443

    3538329

    3456

    3647

    3

    1244979

    3734937

    3648

    3839

    3

    1310515

    3931545

    3840

    4031

    3

    1376051

    4128153

    4032

    4096

    3

    1441587

    4324761

    As you can see, there are 21 “steps” within this range and max_memory values below 192 KB fall below the 64K per buffer limit so they generate an error when you attempt to specify them.

    Clarification: I got another question about this topic last week, this time from a student in one of Jonathan Kehayias' classes. Someone noticed that if you take the size of the buffer (regular_buffer_size) and divide that by 64 KB you don't get the nice even boundary that I am claiming above and that someone is wondering "What gives?". A reasonable question.

    What gives is that regular_buffer_size is reporting the usable buffer space, or the space left after we subtract a small amount of memory for the overhead of managing the buffers. You'll notice that if you take any regular_buffer_size and divide it by 64 KB you'll have the same fraction left over every time: 0.99687194824219, that's the overhead.

    Max approximates True as memory approaches 64K

    The upshot of this is that the max_memory option does not imply a contract for the maximum memory that will be used for the session buffers (Those of you who read Take it to the Max (and beyond) know that max_memory is really only referring to the event session buffer memory.) but is more of an estimate of total buffer size to the nearest higher multiple of 64K times the number of buffers you have. The maximum delta between your initial max_memory setting and the true total buffer size occurs right after you break through a 64K boundary, for example if you set max_memory = 576 KB (see the green line in the table), your actual buffer size will be closer to 767 KB in a non-partitioned event session. You get “stepped up” for every 191 KB block of initial max_memory which isn’t likely to cause a problem for most machines.

    Things get more interesting when you consider a partitioned event session on a computer that has a large number of logical CPUs or NUMA nodes. Since each buffer gets “stepped up” when you break a boundary, the delta can get much larger because it’s multiplied by the number of buffers. For example, a machine with 64 logical CPUs will have 160 buffers using per_cpu partitioning or if you have 8 NUMA nodes configured on that machine you would have 24 buffers when using per_node. If you’ve just broken through a 64K boundary and get “stepped up” to the next buffer size you’ll end up with total buffer size approximately 10240 KB and 1536 KB respectively (64K * # of buffers) larger than max_memory value you might think you’re getting. Using per_cpu partitioning on large machine has the most impact because of the large number of buffers created. If the amount of memory being used by your system within these ranges is important to you then this is something worth paying attention to and considering when you configure your event sessions.

    The DMV dm_xe_sessions is the tool to use to identify the exact buffer size for your sessions. In addition to the regular buffers (read: event session buffers) you’ll also see the details for large buffers if you have configured MAX_EVENT_SIZE. The “buffer steps” for any given hardware configuration should be static within each partition mode so if you want to have a handy reference available when you configure your event sessions you can use the following code to generate a range table similar to the one above that is applicable for your specific machine and chosen partition mode.

    DECLARE @buf_size_output table (input_memory_kb bigint, total_regular_buffers bigint, regular_buffer_size bigint, total_buffer_size bigint)
    DECLARE @buf_size int, @part_mode varchar(8)
    SET @buf_size = 1 -- Set to the begining of your max_memory range (KB)
    SET @part_mode = 'per_cpu' -- Set to the partition mode for the table you want to generate

    WHILE @buf_size <= 4096 -- Set to the end of your max_memory range (KB)
    BEGIN
        BEGIN TRY

            IF EXISTS (SELECT * from sys.server_event_sessions WHERE name = 'buffer_size_test')
                DROP EVENT SESSION buffer_size_test ON SERVER
            DECLARE @session nvarchar(max)
            SET @session = 'create event session buffer_size_test on server
                            add event sql_statement_completed
                            add target ring_buffer
                            with (max_memory = ' + CAST(@buf_size as nvarchar(4)) + ' KB, memory_partition_mode = ' + @part_mode + ')'

            EXEC sp_executesql @session

            SET @session = 'alter event session buffer_size_test on server
                            state = start'

            EXEC sp_executesql @session

            INSERT @buf_size_output (input_memory_kb, total_regular_buffers, regular_buffer_size, total_buffer_size)
                SELECT @buf_size, total_regular_buffers, regular_buffer_size, total_buffer_size FROM sys.dm_xe_sessions WHERE name = 'buffer_size_test'
        END TRY
        BEGIN CATCH
            INSERT @buf_size_output (input_memory_kb)
                SELECT @buf_size
        END CATCH
        SET @buf_size = @buf_size + 1
    END

    DROP EVENT SESSION buffer_size_test ON SERVER

    SELECT MIN(input_memory_kb) start_memory_range_kb, MAX(input_memory_kb) end_memory_range_kb, total_regular_buffers, regular_buffer_size, total_buffer_size from @buf_size_output group by total_regular_buffers, regular_buffer_size, total_buffer_size

    Thanks to Jonathan for an interesting question and a chance to explore some of the details of Extended Event internals.

    - Mike

  • Be sure to read Jonathan Kehayias’ 31 day series on extended events

    If you have not seen it already, Jonathan Kehayias is writing a 31 day series on extended events in celebration of the public release of Denali CTP1. You can start at the master post to find links to each days efforts. As of this writing he is on day 3 and this is well worth the read.

    Enjoy!

    -Mike

  • What’s new for Extended Events in SQL Server code-named “Denali” CTP1

    I’ve been generally lax about posting new stuff to the blog for the last several months, and I’m particularly behind in posting an update about what you’ll see in Denali CTP1 that is new for Extended Events. My only excuse is that we’ve been hard at work on the advancements that will be in the next CTP after this and that’s been a full time job. But enough about the future, let’s get onto what you can see today.

    (For those of you who haven’t seen yet, we announced SQL Server code-named “Denali” as the 2010 PASS Summit. You can get information about it, and download it, at http://www.microsoft.com/sqlserver/en/us/product-info/future-editions.aspx.)

    Extended Events in SQL Server 2008 offered the ability to collect some very detailed information about what is going on inside the database engine but it was lacking some of the based information that you were used to seeing in SQL Trace. One of the goals for the team in Denali was to make up that difference, and we have in CTP1.

    From SQL Trace to Tracing with Extended Events

    We’ve ported the complete set of diagnostic events that are available in SQL Trace over to Extended Events and rounded out our set of Actions to ensure that you can produce the same data from an event session that you can using SQL Trace. We stayed pretty close to doing a one for one port, even keeping the same event names in most cases, but we did make a few tweeks in terms of name changes and combining a few events in places where it made sense.

    [What’s with the underline? SQL Trace really has two primary usage scenarios, one is diagnostics, the other is security auditing. We’re making a move to separate those two features; security auditing is covered by SQL Server Audit (introduced in 2008) and diagnostic tracing will be handled by Extended Events. This means the bulk of the audit related Event Classes have not been migrated.]

    We didn’t want to leave folks stranded trying to figure out the event equivalencies, so we created a couple mapping tables to guide you along. The tables are located in master and are: dbo.trace_xe_event_map and dbo.trace_xe_action_map with the rather obvious purposes. There are a couple BOL topics to help you utilize these tables:

    How To: View the Extended Events Equivalents to SQL Trace Event Classes
    How to: Convert an Existing SQL Trace Script to an Extended Events Session

    These should get you started examining how to create equivalent event sessions for SQL Trace sessions you’re already using. In a future post I’ll discuss this in more detail and describe how event fields and action are related to SQL Trace columns.

    image Exposing ourselves to Object Explorer

    Observant users of CTP1 will have likely noticed a new node in the SSMS Object Explorer. (Actually you’ve probably noticed several, but I’m only interested in Extended Events, so you’ve only noticed one, OK?) Yes, that’s right citizens, Extended Events has the first indications of a user interface!

    We’re going to live under the Management node in our very own Extended Events folder. You get a list of event sessions that exist on the server and you can see if they’re running or not. For CTP1 you have a limited set of commands that are accessed from the context menu:

    • Sessions | Import Session – Allows you to import an XML based definition of an event session.
    • <Event session name> |
      • Start / Stop Session – Does what it sounds like.
      • Import Session – Allows you to import an XML based definition of an event session.
      • Export Session – Allows you to export the selected session to an XML based defintion.
      • Script Session – The standard T-SQL script options that produce Extended Events DDL.

    The other menu options are self-explanatory or standard SSMS menu commands.

    Beyond the DDL

    We love our DDL but we’ve heard that some people like to use languages other than T-SQL. (Horrors!) We’ll we’ve got something for you weirdoes too. We’ve introduced a managed API for Extended Events that gives you access to the “inventory” of the system (eg. lists of events, actions, etc.) as well as the ability to create, modify and delete sessions using your favorite managed language. You can dig into this API by exploring the Microsoft.sqlserver.management.xevent namespace on MSDN. I’ll be posting some code samples to this blog in the future.

    We’ve also exposed this API through PowerShell, so if you’re one of the new elite scripting, we’ve got you covered. You can find some details of the PS provider in the BOL topic Using the PowerShell Provider for Extended Events.

    image 

    So that’s the run down of Extended Events in CTP1. I’ll follow-up with some posts that go into specifics for these areas and there is more to come in the next CTP so stay tuned.

    - Mike

  • Introducing your Data Collector to Extended Events

    One of the things I haven’t gotten around to blogging about yet is how to utilize Data Collector to capture data from event sessions. Raoul Illyes (blog) has relieved me of that duty by posting an article demonstrating how to use Data Collector to pull data out of the system_health event session.

    You can find Raoul’s post here. Thanks Raoul!

  • Take it to the MAX (and beyond)

    I got an interesting question from our Support team today and thought I’d blog the answer since it identified an area that can easily cause some confusion. In the BOL documentation for CREATE EVENT SESSION the description for the MAX_MEMORY session option states the following:

    “Specifies the maximum amount of memory to allocate to the session for event buffering. The default is 4 MB. size is a whole number and can be a kilobyte (kb) or a megabyte (MB) value.” [Underline is mine.]

    An observant Extended Events user noticed that their event session appeared to be using more than the specified value of for MAX_MEMORY and and that the amount over MAX_MEMORY could be quite large. So what’s up with that?

    Buffer memory versus session memory

    You’ve probably already guessed that I underscored the words “event buffering” in the BOL description because it was important. To better understand the importance, you need a crash course in how the asynchronous targets in Extended Events work. This is the real short version…

    When an event that is being track by an event session that includes asynchronous targets, the event data is written to an in memory event buffer. The event data sits in that event buffer until it is processed to the targets. The event buffer is processed based on two options, MAX_MEMORY and MAX_DISPATCH_LATENCY. I’ve discussed these options in more detail in a previous post.

    So the MAX_MEMORY option of the session is really only specifying the amount of memory to allocate for the event buffer, not for the entire event session. The amount of memory above MAX_MEMORY required for an event session is primarily related to the asynchronous in-memory targets. (eg. ring buffer, pairing, etc.) Most times it is fairly obvious how these targets will contribute to memory allocation, for example the ring buffer has its own MAX_MEMORY option to define the size of the memory allocated for use by the ring buffer. This is separate from the memory used for the event buffer.

    So what’s the catch?

    The most interesting in-memory target in terms of giving you “unexpected” behavior (but I’m telling you about it now, so it won’t be unexpected anymore) is the pairing target. The pairing target handles memory like this:

    1. The event buffer is processed to the pairing target.
    2. The target finds all the “pairs” and throws them out.
    3. The target allocates memory for the “orphans” and stores them.
    4. The event buffer is free to collect more event data.
    5. Lather, Rinse, Repeat.
    6. The next time around the target will attempt to match any orphans that it has stored with the new data from the event buffer (and throw out the pairs) and then allocate memory to store the new orphans along with any remaining orphans.

    If you happen to have a large number of orphans being generated you’ll find that the pairing target increases in size each time the event buffer is processed. If you’ve picked events that don’t pair well, then the pairing target can start eating up a lot of memory. The pairing target does have an option to RESPOND_TO_MEMORY_PRESSURE that will force it to stop collecting orphan events when under memory pressure, but if you have plenty of memory the target will happily use it.

    What not to do

    The canonical example of events that people would like to pair but that “don’t pair well” is the lock_acquired / lock_released events. These events are just begging to be paired, but it’s common for the SQL engine to release multiple, related locks as a single event. This results in a situation where multiple lock_acquired events are fired, but only a single lock_released event is fired and you end up with an increasing number of lock_acquired events being tracked in the pairing target that don’t represent legitimate lock orphans.

    The typical reason for wanting to do this type of pairing is to identify blocking but it is better to use the dm_tran_locks DMV to track blocking in this case.

    Hopefully this clarifies the MAX_MEMORY option and what it is actually controlling.

    -Mike

  • Today’s Subject: Predicates

    Don’t worry, I haven’t suddenly switched the topic of this blog to English grammar, but if you want to learn more about Predicates as they apply to sentence constriction you can start with this article on WikipediA. Rather, today’s topic is about predicates in Extended Events. You can find a brief description of predicates in Using SQL Server 2008 Extended Events (by Jonathan Kehayias) so I’ll try to extend your knowledge a bit beyond what that says.

    Pre versus Post processing

    There is usually more than one way to accomplish almost everything so it’s worth taking a moment to consider two different ways to process and event log. Post-processing describes the case where you allow the tracing system to collect every event and then you worry about reducing your data set after you’ve collected the data. Support for this doesn’t really depend on the diagnostic system you use since you can post-process any log that you can get into a tool that supports filtering, for example Excel. Some diagnostic systems have built in tools to do this as well. Pre-processing is when the filtering of events happens as part of the event generation code and therefore can “short-circuit” the event from firing. Extended Events support this type of pre-processing and that is what a Predicate if for.

    Pre-processing has some cost associated with evaluating the predicate which is why some diagnostic systems choose not to offer this functionality, ETW is an example of a diagnostic system that does not support pre-processing of events.

    Aside: Some ETW gurus (I don’t claim to be one) may argue that ETW does support pre-processing because you have the ability to define which events are collected based on Channel, Keyword and Level. For our purposes I’m defining pre-processing as requiring a finer level of control than that; you can decide if this is a semantic point or not.

    The obvious question is: why would you want to use predicates if there is a potential cost? There are a couple of reasons for using a predicate, and as always, whether it is worth it for you to use is going to depend on your situation. The first common reason you might want to use predicates is when the performance hit of collection is higher than the performance hit of evaluating the predicate. Extended Events supports the ability to collect additional data such as call stacks or memory dumps and these can be expensive operations. In order to reduce the performance impact of these expensive operations you can use a predicate to increase the specificity of your event collection. Another common reason to use a predicate is to reduce the volume of events being collected. Many events can occur at extremely high volume, particularly those in the Analytic and Debug channels, and result in “log flooding”, or the behavior of putting many thousands (hundreds of thousands?) of events into the log that are not related to the problem you’re actually troubleshooting. All this extra data makes it hard to analyze the real issue and can cause the log files to be large enough to cause a disk space problem. Again, the solution is to increase the specificity of your event collection which will reduce the number of events you are looking at. Here are a few ways that you might use a predicate to increase specificity of your event collection:

    • Only collect events that occur within a specific database or session_id.
    • Only collect a sampling of events from your system. (I’ve described sampling in this post.)

    So, how much do I save?

    So now you’re wondering what you’re getting for your trouble and for that we need to take a look at what is actually going on inside Extended Events when an event is fired. For our purposes you can think of firing an event as requiring five steps as shown below.

     1. Check if Enabled, 2. Collect EventData, 3. Analyze Predicate, 4. Collect Action Data, 5. Publish to Targets

    The predicate evaluation happens at step three, but don’t let the fact that this is the “middle step” fool you, the amount of work required to generate an event is not equally distributed across these steps. Take the earlier example of collecting a memory dump, this is an expensive operation that happens in step 4 and when combined with publishing the event to a target is easily more costly than collecting the event data itself. The ability to evaluate a predicate right after the minimum amount of event data is collected can significantly reduce the cost of event collection in the cases where you are looking for a specific set of data.

    Aside: SQL Trace/SQL Profiler also support pre-processing through the use of a filter (sp_trace_setfilter) but the filter is not applied until the entire Event Class and associated data has been collected resulting in relatively little performance savings.

     

    OK, so how do predicates work

    We’re finally to the actual topic of this post – thanks for sticking with me through all the preliminary stuff…

    Predicates in Extended Events are very similar to the WHERE clauses that you’ve probably used in T-SQL; they’re Boolean expressions that can be evaluated against two types of data:

    • Local event data (Now you understand why we need to collect EventData first.)
    • Global state

    Local event data is any of the fields that are automatically collect when an event fires. You can examine the list of local data fields for any given event by running a query against one of the DMVs for Extended Events; for example this query shows the fields for the wait_info event.







    SELECT name, type_name
    FROM sys.dm_xe_object_columns
    WHERE object_name = 'wait_info' and column_type = 'data'

    Field Name

    Type

    wait_type

    wait_types

    opcode

    event_opcode

    duration

    uint64

    max_duration

    uint64

    total_duration

    uint64

    signal_duration

    uint64

    completed_count

    uint64

    Global state represents data that is available in thread local storage (TLS) at all points in time in the SQL Server instances, or at least at most points in time. Examples of global state are things such as the session ID or the name of the client application. We call these predicate sources (pred_source for short) and you can query the list of predicate sources using a DMV.

    SELECT name, description,
        (SELECT name FROM sys.dm_xe_packages WHERE guid = o.package_guid) package
    FROM sys.dm_xe_objects o
    WHERE object_type = 'pred_source'
    ORDER BY name

    If you’re familiar with Extended Events you’ll notice that there is a strong correlation between predicate sources and actions. This correlation is on purpose so that you can write predicates against the same set of global data that you can collect using actions. But don’t let the similarities in names trick you into believing these are the same thing; the difference is the timing. Think back to the steps involved in firing an event – the point where the predicate is analyzed is where we collect the pred_source if there is a predicate that uses it. It’s not until after a predicate has evaluated as True that the system collects action data. This is the kind of technical detail that will make you sound cool at conferences when you overhear someone say “I used a predicate on the session_id action.” and you can explain that the predicate does not, in fact, use the session_id action, but rather the session_id predicate source. You would then further explain how the predicate sources allow for the creation of predicates over global data that is similar to that in actions, but that it can be done without having to collect the actions, therefore improving performance by short circuiting the action collection on events that are not of interest.

    Now that we have an understanding of where the data comes from, lets look at a few predicates; we’ll use the wait_info event described above:

    Only collect the event if the duration is more than 500 milliseconds. ADD EVENT wait_info (WHERE duration > 500)
    Only collect the event for session 52. ADD EVENT wait_info (WHERE sqlserver.session_id = 52)
    Only collect the event for NETWORK_IO waits. ADD EVENT wait_info (WHERE wait_type = 99)

    You can infer a couple rules from this list which I’ll state explicitly:

    1. You only need to use the field name when building a predicate on local event data. (duration > 500)
    2. You need to use the package name when using a predicate source. (sqlserver.session_id = 52)
    3. You need to pay Mike to learn the secret translation of specific wait types to the number that represents them.
    The secret translation of wait types into numbers (Maps): OK, so I’m not going to make much money from this secret, oh well. In order to make collection of some data a bit more efficient we created something called maps which simply map an integer to a more friendly string value. You can recognize map fields as those with data types that don’t seem to match with any type you’ve seen before, for example “wait_types”. You can look up the integer to friendly name comparison in the dm_xe_map_values DMV and matching the field’s type to the name column in the DMV. So to get a list of the numeric representation of the various waits, use the following query:

    SELECT *
    FROM sys.dm_xe_map_values
    WHERE name = 'wait_types'

    The final twist

    Another long post but there is just one more thing to discuss before I bring it to a close and that is predicate comparators(pred_compare for short). As you’ve probably guessed from the name, predicate comparators are the operators in the Extended Events predicate system. We’ve done the work to map the standard mathematical operators (=, <, >, !=, <=, etc.) to the appropriate predicate comparators so that you don’t have to see the gory details. Under normal circumstances you probably won’t need to go beyond using these mapped operators and your predicates will look very similar to what you’d expect if you have a working knowledge of the WHERE clause in T-SQL. There may be an occasional need to walk on the wild side and do something out of the ordinary. For these times you have a whole list of interesting pred_comps to play with. You can see the list by querying a DMV:

    SELECT name, description,
        (SELECT name FROM sys.dm_xe_packages WHERE guid = o.package_guid) package
    FROM sys.dm_xe_objects o
    WHERE object_type = 'pred_compare'
    ORDER BY name

    As you scan down the list you’ll see that most pred_compare operators have obvious mappings to a mathematical operator for a specific data type, for example, greater_than_int64 is mapped to > for 64 bit integers. If you look closely you will find a small number that don’t have an obvious mathematical equivalent, such as greater_than_max_int64 or less_than_min_int64. These pred_compare operators are special in that they do more than a simple comparison, in fact, in the case of the two mentioned, they actually maintain state within the predicate and use that stat for the comparison. Let’s consider greater_than_max_int64: this pred_compare will maintain the maximum value of the field passed to it and only fire when it encounters a value that is greater than the current maximum, at which point it sets a new max value and waits until the next time it is exceeded. You might find this useful if you have a statement that is degrading over time and you only want to capture the event data at the points that a degradation actually happens in order to examine what else is happening at those times. Sure, you could capture all the query events and draw a graph to find the points of degradation, but this pred_compare does it for you automatically.

    Calling a pred_compare directly follows this syntax:

    package_name.pred_compare(field/pred_source, value)

    Lets look at the duration predicate described before, but this time collect only when the duration exceeds 500 and is larger than the last maximum duration:

    ADD EVENT wait_info (WHERE package0.greater_than_max_int64(duration, 500)

    Wrapping it all up

    Despite my single criteria example, you can actually build a predicate statement with multiple criteria using the common AND/OR syntax. Order is important and you should put your most specific criteria first because the the event will short circuit as soon as it hits the first part of the predicate that makes it false. So lets pull the entire post together with a predicate that will only return events for the NETWORK_IO wait type when it occurs on sessions with an ID of 52 and only when the duration is larger than the max duration but never less than 500 milliseconds. (I bet you knew that would be the example.)

    ADD EVENT wait_info
    (WHERE wait_type = 99 AND sqlserver.session_id = 52 AND
    package0.greater_than_max_int64(duration, 500))

    Whew! Hopefully that gives you an idea how Predicates can help you create very specific event sessions and even do some interesting analysis directly in the session. Let me know if there is a topic you’d like to see covered in this blog and we’ll add your request to the topic list.

    - Mike

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