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…
- a trace definition that includes the [QueryBegin] event (in addition to the [QueryEnd] event)
- to ensure the [RequestProperties] field is also included as part of the [QueryBegin] event
- another cup of coffee cause we’re about to shred some XML
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)', 'varchar(255)'), [ActivityIDxfer] = E.value('(/event/action[@name="attach_activity_id_xfer"]/value)', 'varchar(255)'), [ConnectionID] = E.value('(/event/data[@name="ConnectionID"]/value)', 'int'), [CPUTime] = E.value('(/event/data[@name="CPUTime"]/value)', 'int'), [CurrentTime] = E.value('(/event/data[@name="CurrentTime"]/value)', 'datetime'), [DatabaseName] = E.value('(/event/data[@name="DatabaseName"]/value)', 'varchar(255)'), [Duration] = E.value('(/event/data[@name="Duration"]/value)', 'int'), [EndTime] = E.value('(/event/data[@name="EndTime"]/value)', 'datetimeoffset'), [ErrorType] = E.value('(/event/data[@name="ErrorType"]/value)', 'int'), [EventClass] = E.value('(/event/data[@name="EventClass"]/value)', 'int'), [EventSubclass] = E.value('(/event/data[@name="EventSubclass"]/value)', 'int'), [IntegerData] = E.value('(/event/data[@name="IntegerData"]/value)', 'int'), [NTCanonicalUserName] = E.value('(/event/data[@name="NTCanonicalUserName"]/value)', 'varchar(255)'), [NTDomainName] = E.value('(/event/data[@name="NTDomainName"]/value)', 'varchar(255)'), [NTUserName] = E.value('(/event/data[@name="NTUserName"]/value)', 'varchar(255)'), [ObjectPath] = E.value('(/event/data[@name="ObjectPath"]/value)', 'varchar(255)'), [RequestID] = E.value('(/event/data[@name="RequestID"]/value)', 'varchar(255)'), [ServerName] = E.value('(/event/data[@name="ServerName"]/value)', 'varchar(255)'), [SessionID] = E.value('(/event/data[@name="SessionID"]/value)', 'varchar(255)'), [Severity] = E.value('(/event/data[@name="Severity"]/value)', 'int'), [StartTime] = E.value('(/event/data[@name="StartTime"]/value)', 'datetimeoffset'), [Success] = E.value('(/event/data[@name="Success"]/value)', 'int'), [QueryString] = E.value('(/event/data[@name="TextData"]/value)', 'varchar(max)'), [RequestProperties] = CAST(E.value('(/event/data[@name="RequestProperties"]/value)', '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…
- [RequestProperties] trace field is cast to XML so that the xml query method can be used to extract the value from the EffectiveUserName element.
- [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).
14 replies on “On-Premise Data Gateway: Capturing SSAS Query Activity By User”
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!
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 🙂
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 !
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.
[…] Bill Anton explains why and how he captures query activity by user in SSAS: […]
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?
Duplicates removed by a join on QueryEnd ActivityID-1 = QueryBegin ActivityID.
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
We have been working on implementing this, and I am beginning to believe this isn’t actually possible, based on a blog post by SQL Chick about a year before this article was originally posted. https://www.sqlchick.com/entries/2015/3/12/monitoring-the-ssas-connector-in-the-power-bi-preview.
In this posting, she says:
EffectiveUserName: When the active user is also the original author, this is the active user. When the active user is viewing a dashboard that’s been shared with them, the EffectiveUserName is still the original author — not the active user.
I’m searching for a resolution to the fact that I’m seeing EffectiveUserName with a timestamp repeated for users who aren’t even online when the query event is being recorded. It seems like the queries themselves cannot even be occurring.
Why is SSAS event logging writing events at random times?
that’s odd… it’s been working just fine for me and my clients. also, it appears Melissa updated that post on 7/24/2015, crossing out the part you quoted.
for your specific issue – it’s hard to say what is generating those seemingly random queries… if you’d like to send me a trace file I’d be happy to take a quick look… anton at opifexsolutions.com
despite being a year later, I wanted to add a comment now for future readers…
These queries coming in for users at random times is likely due to the Power BI dashboard tile caching mechanism. This wasn’t well understood until a few months ago due to some issues that were discussed on one of the Azure AS forums.
Great post Bill. I am finally implementing this at Össur the week before I leave! Just had to read your post to refresh my memory. I’m using PowerShell to shred the xel file and it’s pretty fast.
Asgeir – very cool! You’ll have to give me a demo sometime of that PowerShell script.
I can do that. I will send it to you next week when I’m done