Identify Storage Engine and Formula Engine bottlenecks with new SSAS XEvents

Undoubtedly, the big news of Analysis Services 2012 is the introduction of the new Tabular model and its language DAX.

However, there are some interesting news also in the multidimensional model – I just mentioned one of these, the SSAS Storage String limit, in my previous post, but I will write a specific post about it -, including the introduction of Extended Events (XEvents).

Three months ago, Chris Webb wrote this interesting post where you can find all the information to start to play with Extended Events.

Today, I will show how to use Extended Events as an alternative to use Profiler to monitor the activities of our MDX queries.

In particular, we will see how to determine the Storage Engine and Formula Engine usage by our MDX query, and we will compare the solution that uses Extended Events with the more traditional one using the Profiler.

Some background info

Optimizing the performance of our cubes and MDX queries can be a very challenging activity, not only because it requires a strong knowledge of MDX and the SSAS Engine, but also because – usually – it is an iterative and time consuming activity.

If you want to start with a very complete overview of this complex activity, I strongly recommend having a look at these two precious posts by Chris Webb:

http://www.packtpub.com/article/query-performance-tuning-microsoft-analysis-services-part1

http://www.packtpub.com/article/query-performance-tuning-microsoft-analysis-services-part2

As perfectly described in the above posts, the performance tuning activity of an MDX query typically start determining the Storage Engine and Formula Engine usage to identify which one – or both! – could be the bottleneck.

That is exactly what we are going to do!

Step 1: using XEvents to trace MDX query information

First step is to create the XEvent trace using XMLA command.

As Chris showed in his post about XEvents, the create command is very simple and allows us to declare the events we need to collect with the trace.

For our purpose these are the minimal events we need to trace:

  • EventClass = 10 (Query End)
  • EventClass = 11 (Query Subcube)

and this is an example of the complete XMLA command:

In the command, you can see the list of events to trace – in yellow – and the path of the “.xel” file to output to – in green.

After executing it, we can easily verify that our XEvent trace is running using this query:

Here’s the result on my machine:

where you can also immediately discriminate – looking at the [Type] column – XEvent traces from the other traces.

Step 2: execute MDX queries to collect data

Now that our trace is running, it is a simple matter of execute our MDX queries to collect data for further investigations.

Note:    remember to clear the SSAS cache before execute the queries, otherwise time values collected for the Storage Engine could be lowered by the use of the cache.

Step 3: stop XEvents trace

Even if we could to start to analyze the data when XEvents trace is running, is a good practice to stop it and it can be done using a XMLA command like this:

 

Note:    before to execute the command, be sure the TraceID is the correct one! J

We can also verify that our trace has stopped querying again the “discover_traces” DMV as seen in the Step 1.

Step 4: extracting data about FE and SE duration

Now that we have collected all the necessary data, we simply need to do few calculations to retrieve the information about time spent in Storage Engine and Formula Engine by our queries.

In fact, with the collected data, we are able to obtain:

a)      Query Duration

Is the value of the column [Duration] for rows with [EventClass] = 10 (“Query End” event). Since this event is fired only one time per query – when the query ends – we are sure that every row represents a single query.

b)      Storage Engine Duration

For every query, it is the sum of the value of the column [Duration] for rows with [EventClass] = 11 (“Query Subcube” event). Since this event indicates the usage of the Storage Engine, here we could find zero, one or many rows per query.

Note:    even if this value is not accurate – because we should consider parallelism – , it can be considered adequate to our purpose.

c)      Formula Engine Duration = Query Duration – Storage Engine Duration

But how could we retrieve these values from our trace file?

Well, one of the big advantages of using XEvents is that we can easily query the trace file using this System Stored Function: sys.fn_xe_file_target_read_file

This is a simple query to obtain all the rows from the trace file:

And the following is an example of the result in Management Studio:

As you can see, our collected data are stored in the [event_data] field as XML text.

Hence, we can convert the information in XML data and modify the query – using XQuery and the Value() method – to focalize on data we need for our calculations:

Note:    since XEvent traces usually split the result in more than one file, we can easily query all trace files using the keyword “*” in the name of the file.

     In the above example, we queried all files generated from our trace, in this way:

that means “Read all files, whose name begin with ‘XEventMDXQueryTrace_’ and whose extension is ‘.xel’, contained in the folder ‘C:\ExtendedEvents\Traces’.”.

The above query produced this result on my machine:

 

Note:    to make T-SQL code more readable, and – at the end – to merge all steps in a single usable T-SQL statement, I will use one or more specific CTE for every step involved in our calculations.

Step 4a: retrieve Query Duration value

As stated above, Query Duration value is the simplest to obtain.

In fact, we only need to filter all the rows of the trace file with this condition [Event] = ‘QueryEnd’

Here an example of such a query and its result:

Every row represents a single query and it is uniquely individuates by its [ConnectionID] value.

The value in the [Duration] column is exactly the Query Duration value we need for our calculations.

Note:    as you can see, the trace also collected information about queries executed to retrieve traces information. Those rows will be removed in our final query.

Step 4b: retrieve Storage Engine Duration

The next step is to retrieve information about the time spent by the Storage Engine.

Also this value is very simple to obtain, because we only need to filter all the rows of the trace file with the condition [Event] = ‘QuerySubcube’ and, for every query – identified by its [ConnectionID] -, summarize the value of the [Duration] column as shown below:

The result has only two columns: the [Storage Engine Duration] that is the aggregated value we need and the [ConnectionID] that is the field that we will use later – in the complete version of the query – to join to data that we extracted in the Step 4a.

Step 4c: calculate Formula Engine Duration

In the last step we simply need to subtract the value retrieved in the Step 4b (Storage Engine Duration) from the value retrieved in the Step 4a (Query Duration).

We can easily do it using the [ConnectionID] field to join the data retrieved by the two queries:

and this is the result of the above query:

You can download here a XMLA command to collect also these events:

  • EventClass = 12  (Query Subcube Verbose)
    • EventSubclass = 22 (Non-cache data)
  • EventClass = 60 (Get Data From Aggregations)

and a query that gives you some other information like:

  • Percentage of time spent in Formula Engine
  • Percentage of time spent in Storage Engine
  • Number of Storage Engine queries
  • Number of Aggregations read

XEvents vs Profiler trace

The same result can also be obtained using a Profiler trace, but there are two main reasons that make me prefer XEvents:

1)      XEvents is a light weight performance monitoring system that uses very few performance resources

2)      Queries can be directly executed against XEvents trace files, while Profiler trace need to be loaded   into a table

On the other hand, Xevents is available only starting from SSAS 2012.

Anyway, if you are interested to try to use Profiler trace instead XEvents, you should take a look at this post by Bojan Penev before.

Conclusions

In this post I’ve tried to show you how to use the new SSAS XEvents feature to collect and querying basic – but very useful – information of MDX queries.

Starting from the proposed example, it should be quite simple to implement a more complete solution.

Hope you enjoy it.

Advertisements