…brew your own Business Intelligence

On-Premise Data Gateway: Capturing SSAS Query Activity By User

When I’m managing an Analysis Services environment, I’m not just interested in the performance of the workload… yeah that’s important, but I’m also interested in the users who are generating that workload… especially the top users… and here’s why:

These top users are your biggest customers. They’ve already bought-in to the product/solution and you should be providing them with good customer service because in most cases it is easier (/cheaper) to keep (or even upsell) an existing customer than it is to find a new one. Take care of these folks and you’ll do well.

Once I know who my top users customers are, I like to reach out to them directly and ask if they have some time to chat or invite them to lunch. Once they accept (most do), I can ask them all sorts of questions that help me provide a better service to them going forward. What are their day-to-day tasks that involve using the cube/model? What do they like/dislike about it? Is anything missing? Often times we learn from each other and both walk away better for it.

This feedback is golden and the process of obtaining it helps fortify the relationship between IT & the business users – a vital component of a successful BI program.

So Who Ran That Query?

In most environments, it is trivial to obtain the name of the user who ran each query… all you have to do was capture the [QueryEnd] event in a profiler/xevent trace and pull the information from the [NTUserName] field. However, in environments involving Power BI and the Enterprise On-Premise Data Gateway, there’s a bit more to it.

The main issue is how authentication is handled in this type of architecture. When working with Power BI reports connected to an on-premise data source via the On-Premise Data Gateway, the account of the user running the report is passed as the “EffectiveUsername”. The implication here is that the value shown in the [NTUserName] field of the xevent/profiler trace is going to be the Data Gateway account – NOT the account of the user who actually generated the activity.

Note: If you’re interested in more details, you can check out the following blog posts by Melissa Coates & Koos van Strien.

In order to find out the actual user generating the queries, here’s what you’ll need…

  1. a trace definition that includes the [QueryBegin] event (in addition to the [QueryEnd] event)
  2. to ensure the [RequestProperties] field is also included as part of the [QueryBegin] event
  3. another cup of coffee cause we’re about to shred some XML

Demo

Taking the output file from the xEvent trace definition below…

<Create xmlns="http://schemas.microsoft.com/analysisservices/2003/engine">
    <ObjectDefinition>
        <Trace>
            <ID>QuerySummary-PBI</ID>
            <Name>QuerySummary-PBI</Name>
            <XEvent xmlns="http://schemas.microsoft.com/analysisservices/2011/engine/300/300">
                <event_session
                        name="QuerySummary-PBI" dispatchLatency="0" maxEventSize="0"
                        maxMemory="4" memoryPartition="none"
                        eventRetentionMode="AllowSingleEventLoss" trackCausality="true"
                        xmlns="http://schemas.microsoft.com/analysisservices/2003/engine">
                    <event package="AS" name="QueryBegin" />
                    <event package="AS" name="QueryEnd" />
                    <target package="package0" name="event_file">
                        <parameter name="filename" value="QuerySummary-PBI.xel" />
                        <parameter name="max_file_size" value="32" />
                    </target>
                </event_session>
            </XEvent>
        </Trace>
    </ObjectDefinition>
</Create>

…we can run the following query… to obtain the username from the [QueryBegin] event and associate it to the corresponding [QueryEnd] event…

WITH  
  XMLNAMESPACES ('urn:schemas-microsoft-com:xml-analysis' as ns_RequestProperties)
    ,XmlEvents AS ( 
        SELECT   CAST (event_data AS XML) AS E
        FROM     sys.fn_xe_file_target_read_file('E:\SSASLog\QuerySummary-PBI*.xel', NULL, NULL, NULL)
    )
    ,TabularEvents  AS ( 
        SELECT  [ActivityID] = E.value('(/event/action[@name="attach_activity_id"]/value)[1]', 'varchar(255)'),
                [ActivityIDxfer] = E.value('(/event/action[@name="attach_activity_id_xfer"]/value)[1]', 'varchar(255)'),
                [ConnectionID] = E.value('(/event/data[@name="ConnectionID"]/value)[1]', 'int'),
                [CPUTime] = E.value('(/event/data[@name="CPUTime"]/value)[1]', 'int'),
                [CurrentTime] = E.value('(/event/data[@name="CurrentTime"]/value)[1]', 'datetime'),
                [DatabaseName] = E.value('(/event/data[@name="DatabaseName"]/value)[1]', 'varchar(255)'),
                [Duration] = E.value('(/event/data[@name="Duration"]/value)[1]', 'int'),
                [EndTime] = E.value('(/event/data[@name="EndTime"]/value)[1]', 'datetimeoffset'),
                [ErrorType] = E.value('(/event/data[@name="ErrorType"]/value)[1]', 'int'),
                [EventClass] = E.value('(/event/data[@name="EventClass"]/value)[1]', 'int'),
                [EventSubclass] = E.value('(/event/data[@name="EventSubclass"]/value)[1]', 'int'),
                [IntegerData] = E.value('(/event/data[@name="IntegerData"]/value)[1]', 'int'),
                [NTCanonicalUserName] = E.value('(/event/data[@name="NTCanonicalUserName"]/value)[1]', 'varchar(255)'),
                [NTDomainName] = E.value('(/event/data[@name="NTDomainName"]/value)[1]', 'varchar(255)'),
                [NTUserName] = E.value('(/event/data[@name="NTUserName"]/value)[1]', 'varchar(255)'),
                [ObjectPath] = E.value('(/event/data[@name="ObjectPath"]/value)[1]', 'varchar(255)'),
                [RequestID] = E.value('(/event/data[@name="RequestID"]/value)[1]', 'varchar(255)'),
                [ServerName] = E.value('(/event/data[@name="ServerName"]/value)[1]', 'varchar(255)'),
                [SessionID] = E.value('(/event/data[@name="SessionID"]/value)[1]', 'varchar(255)'),
                [Severity] = E.value('(/event/data[@name="Severity"]/value)[1]', 'int'),
                [StartTime] = E.value('(/event/data[@name="StartTime"]/value)[1]', 'datetimeoffset'),
                [Success] = E.value('(/event/data[@name="Success"]/value)[1]', 'int'),
                [QueryString] = E.value('(/event/data[@name="TextData"]/value)[1]', 'varchar(max)'),
                [RequestProperties] = CAST(E.value('(/event/data[@name="RequestProperties"]/value)[1]', 'varchar(max)') AS XML)
        FROM    XmlEvents
    )
    ,CTE_query_base AS (
        SELECT   te.RequestID
                ,te.CPUTime
                ,te.DatabaseName
                ,te.Duration
                ,EndTime = CAST (CASE WHEN te.EndTime >= CAST ('20100101' AS DATETIMEOFFSET) THEN te.EndTime ELSE NULL END AS DATETIME)
                ,te.NTCanonicalUserName
                ,te.ServerName
                ,StartTime = CAST (CASE WHEN te.StartTime >= CAST ('20100101' AS DATETIMEOFFSET) THEN te.StartTime ELSE NULL END AS DATETIME)
                ,te.[QueryString]
        FROM    TabularEvents te
        WHERE   te.EventClass = 10 -- QueryEnd
                AND te.EventSubclass IN ( 0, 3 ) -- Only gets MDX and DAX
    )
    
    ,CTE_powerbi_user AS (
        SELECT   te.RequestID
                ,EffectiveUserName = 
                    te.RequestProperties.query('ns_RequestProperties:PropertyList/ns_RequestProperties:EffectiveUserName').value('.','VARCHAR(128)')
        FROM    TabularEvents te
        WHERE   te.EventClass = 9 -- QueryBegin
                AND te.EventSubclass IN ( 0, 3 ) -- Only gets MDX and DAX
    )
SELECT     q.*
        ,usr.EffectiveUserName
FROM    CTE_query_base q
        LEFT OUTER JOIN CTE_powerbi_user usr 
            ON usr.RequestID = q.RequestID
;

Couple of key points…

  1. [RequestProperties] trace field is cast to XML so that the xml query method can be used to extract the value from the EffectiveUserName element.
  2. [RequestID] is the key to linking events originating from the same Query (or Command if we’re analyzing processing activity)… but (I *think*) it is only available in SQL 2012 and forward. If you’re using a version older than that…you probably should hop off this blog and focus your efforts on making a case to upgrade (there are plenty of reasons to).

 

Additional References:

8 thoughts on “On-Premise Data Gateway: Capturing SSAS Query Activity By User

  1. David Squires says:

    Awesome post, just what I was looking for! My company has an SSAS tabular model that’s been in production and stable for a few months now. It’s being used more and more now so we’re starting to think about trying to track who our best customers are, how long they’re using it for, what fields are being used / not being used, what measures are taking the longest (if possible), etc.

    Currently they’re accessing mostly through Excel but Power BI through a gateway is a possibility for us. I don’t have much trace/extended events experience. Is this the only method to access those logs querying through XML? it’s unfortunate you can’t just log to a table. Do you run this extended event all the time without a large performance hit ?

    We were hoping to log an events like user query counts, or time between log in/out, etc. 24/7.

    Thanks again for the post!

    1. Bill says:

      Hi David – glad you found the post helpful.

      Shredding the XML via SQL is not the only method, but its usually the easiest for SQL Server developers. An alternative option is to use .NET if that’s a tool in your toolbox.

      In terms of running the trace 24/7… definitely not a problem if all your capturing in the trace is the QueryBegin/QueryEnd events. Those are very lightweight and will have nearly zero impact on the server. That said, if you decide to start collecting some of the more granular events (e.g. VertiPaq SE Query End) or very large events (e.g. DAX Query Plan) you will want to be more careful.

      If you’re on SSAS 2016, you might want to check out the following open-source project a few of us have been working on: https://github.com/marcosqlbi/SsasEventsAnalyzer/wiki

      The time between log in/out is an interesting metric 🙂

      1. David Squires says:

        Great- we are moving to 2016, i will check out your open-source project.

        In regards to getting the logs into a table, I was really hoping there was a “store to table” option I was missing, but it doesn’t sound like it’s there. I might have to steal some of your XML shredding code ! Thanks in advance for that that !

        I was thinking time between log in/out but would be concerned how many people leave an excel connection open all the time. Maybe an average query count per day would log activity more precisely.

        Thanks again !

        1. Bill says:

          Nice – 2016 is awesome-sauce!

          Good luck with the code and feel free to reach out if you need any help or want to bounce some ideas around.

          Cheers,
          Bill

  2. Niels says:

    Nice post, thanks. Unfortunately in my test the join on ActivityIDxfer results in duplicates, because of multiple EffectiveUserName having the sameActivityIDxfer in CTE_powerbi_user. As a result from this there are some queries that looks like they are run by two users at the exact same time. Any suggestions?
    Br, Niels

    1. Niels says:

      Duplicates removed by a join on QueryEnd ActivityID-1 = QueryBegin ActivityID.

    2. Bill says:

      doh – you’re absolutely right (not sure how I missed that)… if you use RequestID to the join, it should come out correct… will update the post shortly

Leave a Reply