Introduction To Analysis Services Extended Events

21 February, 2014 (12:00) | Extended Events, SSAS | By: Mark V

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? image 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:

image

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.

image

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:

image

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.

Comments

Comment from Bill Anton
Time February 23, 2014 at 8:59 am

Great post – very comprehensive.

Bob Beauchemin also has some solid posts/presentations on using xEvents w/ the database engine that really highlight its strengths (e.g. super light-weight, etc). Should be interesting to see if/how the SSAS dev team plans to build out the xEvents (or detail of logging via xEvents) for the SSAS engine.

Comment from Mark V
Time February 26, 2014 at 8:53 pm

Thanks much, Bill. I will check out Bob’s blog about it.

Comment from Jitash Bhatia
Time May 2, 2014 at 1:59 pm

Thanks Mark!
By default, the extended events generate multiple files each 1GB in size, totaling 5GB. Is there a way to control this file size? I would like smaller files being generated, making it faster to read those using sys.fn_xe_file_target_read_file on a schedule.

Comment from Mark V
Time May 4, 2014 at 9:15 am

Hi, Jitisha. As far as file size, Bill Anton made an update to his blog post ( http://byobi.com/blog/2013/06/extended-events-for-analysis-services/ ) that includes information on how you can use additional parameters to control max file size and a few other things as well.

Pingback from SSAS Tabular Logging Methods | jessekraut
Time May 15, 2014 at 11:41 am

[...] SQL Server Extended Events (XEvents) to Monitor Analysis Services – Using XMLA to run the trace and delete the trace which logs the data to a Microsoft SQL Server Extended Event log file (.xel). This can be parsed in a simple SQL statement to get the columns from the file. Note: This is very powerful you can create the start and stop XMLA scripts to begin the profiler trace and configure any elements in the XMLA to be logged. You can query the (.xel) file via a SQL statement that parses the columns and then you can access the data just like a regular table. The advantage is less overhead then the GUI. Link: http://markvsql.com/2014/02/introduction-to-analysis-services-extended-events/ [...]

Comment from Tom Marshall
Time June 10, 2014 at 3:55 pm

Hi Mark, I attended your presentation at SQL Saturday 294. I found it informative. Thank you.

Write a comment