I started digging into using Extended Events to trace Analysis Services recently for a client. They wanted to do some tracing of their SSAS instances, and with the deprecation of SQL Profiler, Extended Events was the best long term solution.
I have to admit, when I first started looking at this topic, I was overwhelmed. Other than a few blog posts, which I will list out below, there was very little to go on. I believe, on the whole, SQL Server Books Online (msdn, technet, etc) have pretty solid content. But for using Extended Events on Analysis Services, I have to agree with Chris Webb (Blog|Twitter) that BOL provides little value. Note: Although the examples I have seen in the wild, as well as my example below, have used SSAS Multidimensional, I implemented this for SSAS Tabular at my client. So, it works for both.
I will not be advising you on what events to trace for different purposes. I am afraid that is beyond the scope of this post and not something I have deep knowledge about at this point.
In researching this topic, I used the following blog posts:
Chris Webb (Blog|Twitter) – Using XEvents In SSAS 2012
Bill Anton (Blog|Twitter) – Extended Events For Analysis Services
Andreas Wolter (Blog|Twitter) – Tracing Analysis Services (SSAS) with Extended Events – Yes it works and this is how
Francesco De Chirico (Blog|Twitter) – Identify Storage Engine and Formula Engine bottlenecks with new SSAS XEvents
These posts were all helpful in one way or another. In some cases, I used a post as the source upon which I based the queries I used. When that is the case, I will make it clear where my base code came from. I do this because I am a vehement supporter of giving credit where it is due.
Extended Events for Analysis Services, unlike that for the database engine, lacks a graphical user interface. You have to work in code. Not only that, but the code happens to be XMLA. Yikes. I know there are people who are good with XMLA, but I am not among them. That was part of what gave me trepidation as I started down the path of working with Extended Events for SSAS.
For the CREATE script for my Extended Events trace, I turned to Bill Anton’s blog post listed above. That script not only includes the base syntax, but he also includes every event (I think it is all of them anyway) commented out. This allowed me to just uncomment the events I wanted to trace, but leave the others intact for easy use later. For this script, make sure you are connected to an SSAS instance in Management Studio, not Database Engine. Also, you will ideally be in an XMLA query window; I was able to run this code in an MDX window as well, but my examples below will assume an XMLA window.
Note: In XMLA, lines beginning with <!– and ending with –> are comments.
1: <!-- This script supplied by Bill Anton http://byobi.com/blog/2013/06/extended-events-for-analysis-services/ -->
2:
3: <Create
4: xmlns="http://schemas.microsoft.com/analysisservices/2003/engine"
5: xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
6: xmlns:ddl2="http://schemas.microsoft.com/analysisservices/2003/engine/2"
7: xmlns:ddl2_2="http://schemas.microsoft.com/analysisservices/2003/engine/2/2"
8: xmlns:ddl100_100="http://schemas.microsoft.com/analysisservices/2008/engine/100/100"
9: xmlns:ddl200_200="http://schemas.microsoft.com/analysisservices/2010/engine/200/200"
10: xmlns:ddl300_300="http://schemas.microsoft.com/analysisservices/2011/engine/300/300">
11: <ObjectDefinition>
12: <Trace>
13: <ID>MyTrace</ID>
14: <!--Example: <ID>QueryTuning_20130624</ID>-->
15: <Name>MyTrace</Name>
16: <!--Example: <Name>QueryTuning_20130624</Name>-->
17: <ddl300_300:XEvent>
18: <event_session name="xeas"
19: dispatchLatency="1"
20: maxEventSize="4"
21: maxMemory="4"
22: memoryPartitionMode="none"
23: eventRetentionMode="allowSingleEventLoss"
24: trackCausality="true">
25:
26: <!-- ### COMMAND EVENTS ### -->
27: <!--<event package="AS" name="CommandBegin" />-->
28: <!--<event package="AS" name="CommandEnd" />-->
29:
30: <!-- ### DISCOVER EVENTS ### -->
31: <!--<event package="AS" name="DiscoverBegin" />-->
32: <!--<event package="AS" name="DiscoverEnd" />-->
33:
34: <!-- ### DISCOVER SERVER STATE EVENTS ### -->
35: <!--<event package="AS" name="ServerStateDiscoverBegin" />-->
36: <!--<event package="AS" name="ServerStateDiscoverEnd" />-->
37:
38: <!-- ### ERRORS AND WARNING ### -->
39: <!--<event package="AS" name="Error" />-->
40:
41: <!-- ### FILE LOAD AND SAVE ### -->
42: <!--<event package="AS" name="FileLoadBegin" />-->
43: <!--<event package="AS" name="FileLoadEnd" />-->
44: <!--<event package="AS" name="FileSaveBegin" />-->
45: <!--<event package="AS" name="FileSaveEnd" />-->
46: <!--<event package="AS" name="PageInBegin" />-->
47: <!--<event package="AS" name="PageInEnd" />-->
48: <!--<event package="AS" name="PageOutBegin" />-->
49: <!--<event package="AS" name="PageOutEnd" />-->
50:
51: <!-- ### LOCKS ### -->
52: <!--<event package="AS" name="Deadlock" />-->
53: <!--<event package="AS" name="LockAcquired" />-->
54: <!--<event package="AS" name="LockReleased" />-->
55: <!--<event package="AS" name="LockTimeout" />-->
56: <!--<event package="AS" name="LockWaiting" />-->
57:
58: <!-- ### NOTIFICATION EVENTS ### -->
59: <!--<event package="AS" name="Notification" />-->
60: <!--<event package="AS" name="UserDefined" />-->
61:
62: <!-- ### PROGRESS REPORTS ### -->
63: <!--<event package="AS" name="ProgressReportBegin" />-->
64: <!--<event package="AS" name="ProgressReportCurrent" />-->
65: <!--<event package="AS" name="ProgressReportEnd" />-->
66: <!--<event package="AS" name="ProgressReportError" />-->
67:
68: <!-- ### QUERY EVENTS ### -->
69: <!--<event package="AS" name="QueryBegin" />-->
70: <event package="AS" name="QueryEnd" />
71:
72: <!-- ### QUERY PROCESSING ### -->
73: <!--<event package="AS" name="CalculateNonEmptyBegin" />-->
74: <!--<event package="AS" name="CalculateNonEmptyCurrent" />-->
75: <!--<event package="AS" name="CalculateNonEmptyEnd" />-->
76: <!--<event package="AS" name="CalculationEvaluation" />-->
77: <!--<event package="AS" name="CalculationEvaluationDetailedInformation" />-->
78: <!--<event package="AS" name="DaxQueryPlan" />-->
79: <!--<event package="AS" name="DirectQueryBegin" />-->
80: <!--<event package="AS" name="DirectQueryEnd" />-->
81: <!--<event package="AS" name="ExecuteMDXScriptBegin" />-->
82: <!--<event package="AS" name="ExecuteMDXScriptCurrent" />-->
83: <!--<event package="AS" name="ExecuteMDXScriptEnd" />-->
84: <!--<event package="AS" name="GetDataFromAggregation" />-->
85: <!--<event package="AS" name="GetDataFromCache" />-->
86: <!--<event package="AS" name="QueryCubeBegin" />-->
87: <!--<event package="AS" name="QueryCubeEnd" />-->
88: <!--<event package="AS" name="QueryDimension" />-->
89: <!--<event package="AS" name="QuerySubcube" />-->
90: <!--<event package="AS" name="ResourceUsage" />-->
91: <!--<event package="AS" name="QuerySubcubeVerbose" />-->
92: <!--<event package="AS" name="SerializeResultsBegin" />-->
93: <!--<event package="AS" name="SerializeResultsCurrent" />-->
94: <!--<event package="AS" name="SerializeResultsEnd" />-->
95: <!--<event package="AS" name="VertiPaqSEQueryBegin" />-->
96: <!--<event package="AS" name="VertiPaqSEQueryCacheMatch" />-->
97: <!--<event package="AS" name="VertiPaqSEQueryEnd" />-->
98:
99: <!-- ### SECURITY AUDIT ### -->
100: <!--<event package="AS" name="AuditAdminOperationsEvent" />-->
101: <event package="AS" name="AuditLogin" />
102: <!--<event package="AS" name="AuditLogout" />-->
103: <!--<event package="AS" name="AuditObjectPermissionEvent" />-->
104: <!--<event package="AS" name="AuditServerStartsAndStops" />-->
105:
106: <!-- ### SESSION EVENTS ### -->
107: <!--<event package="AS" name="ExistingConnection" />-->
108: <!--<event package="AS" name="ExistingSession" />-->
109: <!--<event package="AS" name="SessionInitialize" />-->
110:
111:
112: <target package="Package0" name="event_file">
113: <!-- Make sure SSAS instance Service Account can write to this location -->
114: <parameter name="filename" value="C:\SSASExtendedEvents\MyTrace.xel" />
115: <!--Example: <parameter name="filename" value="C:\Program Files\Microsoft SQL Server\MSAS11.SSAS_MD\OLAP\Log\trace_results.xel" />-->
116: </target>
117: </event_session>
118: </ddl300_300:XEvent>
119: </Trace>
120: </ObjectDefinition>
121: </Create>
You can download a version of this script without line numbers here.
I modified Bill’s original script for my own purposes in a few places.
I used my own Trace ID and Trace Name in lines 13 and 15 respectively.
12: <Trace>
13: <ID>MyTrace</ID>
14: <!--Example: <ID>QueryTuning_20130624</ID>-->
15: <Name>MyTrace</Name>
16: <!--Example: <Name>QueryTuning_20130624</Name>—>
I uncommented the Query End event on line 70 as well as the AuditLogin event on line 101 since those were the events I wanted to trace, to keep things simple. 70: <event package=“AS” name=“QueryEnd” /> 101: <event package=“AS” name=“AuditLogin” /> I put my own output file path on line 114. 114: <parameter name=“filename” value=“C:\SSASExtendedEvents\MyTrace.xel” /> I also added a comment on line 113. 113: <!– Make sure SSAS instance Service Account can write to this location –> I did this because I tripped over this myself. I initially got an Access Denied message when running the script above. Once I gave my SSAS instance service account rights to modify the C:\SSASExtendedEvents folder, I was good to go and the trace started just fine. When you execute the query, your Results pane should look like the screenshot below. This indicates success. Gotta love XMLA, huh? 
You can verify your Extended Events trace is running by executing the following query in an MDX query window connected to the same instance in which you started the trace. The query below is in all of the blog posts referenced above.
SELECT * FROM $system.discover_traces
My results for this query looked like this:
Note the line highlighted in the red rectangle indicates “MyTrace” and the type is XEvent. Hazzah! You can also take a look at the destination folder specified for your output file. In my case, that is C:\SSASExtendedEvents, shown below.
There are two files here because I kept the output file from a test run earlier. I did that to show you that the function I will use to import this information into a tabular form in the database engine can iterate over multiple files easily. You will note that the engine added lots of numbers to the filename. I have not run this long enough to spill over into multiple files, but I am assuming the _0_ would refer to the first file in a tracing session. As in, the next file would have the same name, but with _1_, the next file _2_, and so on. But, that is just a guess. The long string of numbers after that seem to just be there to make sure the trace file name is unique.
OK. So, we have an Extended Events trace running. Now what? Well, let’s run some queries. In my case, I just ran some of the MDX queries from my MDX Trek: First Contact presentation. The queries themselves don’t really matter. Just query a database in your SSAS instance in some fashion.
Reading from the xel file in code (as opposed to manually in Management Studio) involves one of two processes I am aware of.
1. The sys.fn_xe_file_target_read_file function followed by shredding some XML. This function was mentioned by Bill Anton and Francesco De Chirico in their posts.
2. Jonathan Kehayias (Blog|Twitter) mentioned to me, on Twitter, the use of the QueryableXEventData class via .Net code. He stressed that this is his preferred method as it is much faster then using the sys.fn_xe_file_target_read_file function and then the XML shredding.
Trusting Jonathan on Extended Events, among many other topics, is a good idea. However, not being a .Net person, and wanting to post this while it is fresh in my mind, I am going to demonstrate the first method. I did find that method 1 is not ultra speedy, to be sure. But for the moment, event at my client, it will serve. I do intend to dig into the .Net and perhaps blog that when I do. 🙂
In Francesco De Chirico’s post, he not only discusses the use of the sys.fn_xe_file_target_read_file function to read in the xel files, but also provides great examples of the XML shredding. XML and I have an understanding: we both understand that I am horrible at XML. 🙂 So, the fact that Francesco provided the XML shredding syntax was a great find for me.
1: /****
2: Base query provided by Francesco De Chirico
3: http://francescodechirico.wordpress.com/2012/08/03/identify-storage-engine-and-formula-engine-bottlenecks-with-new-ssas-xevents-5/
4:
5: ****/
6:
7: SELECT
8: xe.TraceFileName
9: , xe.TraceEvent
10: , xe.EventDataXML.value('(/event/data[@name="EventSubclass"]/value)[1]','int') AS EventSubclass
11: , xe.EventDataXML.value('(/event/data[@name="ServerName"]/value)[1]','varchar(50)') AS ServerName
12: , xe.EventDataXML.value('(/event/data[@name="DatabaseName"]/value)[1]','varchar(50)') AS DatabaseName
13: , xe.EventDataXML.value('(/event/data[@name="NTUserName"]/value)[1]','varchar(50)') AS NTUserName
14: , xe.EventDataXML.value('(/event/data[@name="ConnectionID"]/value)[1]','int') AS ConnectionID
15: , xe.EventDataXML.value('(/event/data[@name="StartTime"]/value)[1]','datetime') AS StartTime
16: , xe.EventDataXML.value('(/event/data[@name="EndTime"]/value)[1]','datetime') AS EndTime
17: , xe.EventDataXML.value('(/event/data[@name="Duration"]/value)[1]','bigint') AS Duration
18: , xe.EventDataXML.value('(/event/data[@name="TextData"]/value)[1]','varchar(max)') AS TextData
19: FROM
20: (
21: SELECT
22: [FILE_NAME] AS TraceFileName
23: , OBJECT_NAME AS TraceEvent
24: , CONVERT(XML,Event_data) AS EventDataXML
25: FROM sys.fn_xe_file_target_read_file ( 'C:\SSASExtendedEvents\MyTrace*.xel', null, null, null )
26: ) xe
27:
In line 25, note that the file target indicates MyTrace*.xel. This is because the latter part of the file name(s) will not necessarily be known. The MyTrace*.xel tells the function to iterate over all files matching that spec. Thus, when I run this query, it will pull the data from both of the files shown earlier in my C:\SSASExtendedEvents folder.
In Line 24, we are converting the Event_Data column, which the function returns as an nvarchar(max), into XML to enable use to use the value() method.
Please note that I am not pulling all of the information available in the xel file. I am just pulling the fields I cared about for my purposes. There is more in there. And that will vary depending on the events you choose when creating the trace.
When I run this query, I get the following:
I can use this, like I did at my client, to insert into a SQL Server database table for later analysis. We are actually planning a Tabular model on this data to help track usage of their BI offerings in their organization. That will be fun to play with.
Once you are ready to stop the trace, execute the following XMLA:
1: <Delete xmlns="http://schemas.microsoft.com/analysisservices/2003/engine">
2: <Object>
3: <TraceID>MyTrace</TraceID>
4: </Object>
5: </Delete>
That’s about it. I hope this proves to be a meaningful addition to what is available for working with Extended Events on Analysis Services. It was certainly a great learning experience for me.
Mark Vaillancourt 