Chris Webb's BI Blog

Analysis Services, MDX, PowerPivot, DAX and anything BI-related

Investigating the Resource Usage Profiler Event

with 4 comments

As I mentioned a few months back, some new functionality snuck into SSAS with SQL 2008 R2 SP1, the most interesting of which is a new Profiler event called Resource Usage (Thomas Ivarsson recently blogged about some other new events too). I’ve been doing some investigations on it recently, and asking the SSAS dev team what the information it returns actually means (Akshai Mirchandani is the source for much of the content of this post and I’m very grateful for his help), so I thought I’d blog my findings.

When you’re defining a new trace, you can find the Resource Usage event in the Query Processing section as shown below:

image

It is raised immediately after a query has finished executing (in which case it follows the Query End event):

image

It is also raised after any XMLA command has finished executing, and this means you’re also able to use it to monitor the resource usage of a processing operation:

image

Essentially, it gives you information that is very similar to what’s already available in Perfmon but specific to a particular query or command. The problem with Perfmon is that it’s easy to spot strange things happening in the data it gives you, but there’s no sure-fire way of linking what you see in Perfmon back to individual events such as queries executing; the Resource Usage event solves this problem.

Here’s a breakdown of the data returned by the event:

  • READS: The number of disk read operations tracked for this query
  • READ_KB: The size of disk reads in KB
  • WRITES: The number of disk write operations tracked for this query
  • WRITE_KB: The size of disk writes in KB
  • CPU_TIME_MS: The CPU time as measured in milliseconds for this query (although this seems to bear very little relation to the CPU time shown elsewhere in Profiler – perhaps it is only the CPU time for the Storage Engine?)
  • ROWS_SCANNED: The number of rows scanned (decoded/filtered/aggregated) by the Storage Engine for this query
  • ROWS_RETURNED: The number of rows resulting from the scans after decoding/filtering/aggregation by the Storage Engine for this query

The data returned relates purely to Storage Engine operations as far as I can see and does not relate to the Formula Engine – I get no values back for queries that hit the Storage Engine cache but are nonetheless slow because they are Formula Engine bound.

To investigate things further, I took a look at three queries (slightly modified to run on my antique version of Adventure Works) from Jeffrey Wang’s recent post on prefetching, which illustrate scenarios where the Storage Engine does radically different amounts of work; they’re particularly interesting because Jeffrey describes in detail what goes on in the Storage Engine when each of them run. First of all, the first test query from Jeffrey’s post where prefetching does not take place gives me the following values for Resource Usage on a cold cache:

READS, 8
READ_KB, 361
WRITES, 0
WRITE_KB, 0
CPU_TIME_MS, 15
ROWS_SCANNED, 18210
ROWS_RETURNED, 337

On a warm cache (ie in a situation where the Storage Engine does not need to go to disk because it can get the values it needs from cache) I get the following values:

READS, 0
READ_KB, 0
WRITES, 0
WRITE_KB, 0
CPU_TIME_MS, 0
ROWS_SCANNED, 0
ROWS_RETURNED, 0

Here’s Jeffrey’s second query, where an acceptable amount of prefetching is taking place:

select [Internet Sales Amount] on 0,
head(descendants([Date].[Calendar].[Calendar Year].&[2003],[Date].[Calendar].[Date]), 32) on 1
from [Adventure Works]

On a cold cache this is what I get from Resource Usage, showing slightly more activity going on:

READS, 16
READ_KB, 738
WRITES, 0
WRITE_KB, 0
CPU_TIME_MS, 15
ROWS_SCANNED, 36932
ROWS_RETURNED, 693

If we now look at Jeffrey’s third query, where he shows a scenario where excessive prefetching is taking place:

select [Internet Sales Amount] on 0,
head(descendants([Date].[Calendar].[Calendar Year].&[2003],[Date].[Calendar].[Date]), 33) on 1
from [Adventure Works]

Here’s what I get on a cold cache from Resource Usage:

READS, 32
READ_KB, 1889
WRITES, 0
WRITE_KB, 0
CPU_TIME_MS, 46
ROWS_SCANNED, 74655
ROWS_RETURNED, 63831

It’s clear from these numbers that a lot more work is going on in the Storage Engine compared to the previous two queries, although I’m not sure it’s worth trying to read too much into what the exact values themselves actually represent (unless of course you happen to be Jeffrey). I think it’s also going to be dangerous to make simplistic general recommendations about these values: while in some cases trying to keep the values returned as low as possible will be a good idea, I’m pretty sure there are going to be other situations where a more efficient query would involve more reads from disk, or scanning or returning more rows, than a less efficient version of the same query would. That said, this is useful and interesting information and another weapon in the arsenal of the SSAS consultant out in the field trying to diagnose why a query is slow and what can be done to tune it.

Written by Chris Webb

November 19, 2011 at 9:12 am

4 Responses

Subscribe to comments with RSS.

  1. Very useful information.
    Thanks Chris.

    Gautham KAMATH

    November 21, 2011 at 10:50 am

  2. I think I need to do some more processing which is good, because it means I am in a place where I can actually do that.

    Zoe Blomfield z

    December 20, 2011 at 9:17 am

  3. [...] There are no Query Subcube events so no activity has been going on in the storage engine. The query was sent to the server and a result was returned(Serialize Results Current).Resource usage shows zero on all counters. Thanks to Chris Webb research about these counters here [...]

  4. [...] There are no Query Subcube events so no activity has been going on in the storage engine. The query was sent to the server and a result was returned(Serialize Results Current).Resource usage shows zero on all counters. Thanks to Chris Webb research about these counters here [...]


Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

Join 3,240 other followers

%d bloggers like this: