Using SQL Server to Analyze Analysis Services Profiler Traces from Tabular Models.

My last blog post was focused on using SQL Server to analyze profiler traces against Multidimensional Analysis Services databases, so I though it only appropriate to follow-up with a post on using SQL Server to analyze profiler traces from a Tabular Analysis Services database. In July of 2013,  John Sirmon, Greg Galloway (Artis Consulting), Cindy Gross and Karan Gulati published the Performance Tuning of Tabular Models in SQL Server 2012 Analysis Services whitepaper (https://msdn.microsoft.com/en-us/library/dn393915.aspx). They described the process that they used for determining whether a bottleneck was in Storage Engine for Formula Engine. I tried that approach (basically did a cut and paste of the SQL Query that begins on page 35) with a brand new profiler trace and was more than a bit surprised to see the user name associated with the fastest query in the trace associated with the slowest query in the trace. I was also a bit surprised to find that the Storage Engine time values exceeded the durations for the queries and that the duration reported was the sum of the durations of all eight (8) queries that were captured in the trace..

Never one to be discouraged, it didn't take me too long to figure out that this is basically the same task as analyzing profiler traces from Multidimensional databases. The big difference is the events that indicate Multidimensional Storage Engine events and those that indicate Vertipaq Engine events. In the case of multidimensional queries, Storage Engine events and durations are associated with EventClass 11 (Query Subcube) and EventSubclass 2 (Non-cache data). With Tabular models, VertiPaq engine events and durations are associated with EventClass 83 (VertiPaq SE Query End), with particular interest in EventSubclass 0 (VertiPaq Scan). Taking that bit of information, I came up with the following SQL Query that gave me exactly the information that I was looking for:

 

with ProcAnalysis (Rownumber, EventClass, EventSubClass, TextData, QueryDuration, SETime, MinRow, Bottleneck, NTUserName, ConnectionID, ZScore)
AS
(
select a.Rownumber, pec.name as EventClass, pes.name as EventSubclass, cast(a.TextData as nvarchar(max)) as TextData, a.duration,
(select sum(duration) from ProfilerTraceTable b where b.eventclass=83 and b.eventsubclass=0 and b.connectionID=a.ConnectionID and b.rownumber between
(select max(rownumber) from ProfilerTraceTable c where c.eventclass=9 and c.rownumber<a.rownumber) and a.rownumber) as SETime,
(select max(rownumber) from ProfilerTraceTable c where c.eventclass=9 and c.rownumber<a.rownumber) as MinRow,
case when (select sum(duration) from ProfilerTraceTable b where b.eventclass=83 and b.eventsubclass=0 and b.connectionID=a.ConnectionID and b.rownumber between
(select max(rownumber) from ProfilerTraceTable c where c.eventclass=9 and c.rownumber<a.rownumber) and a.rownumber)>a.duration*.5 then 'VertiPaq Engine'
else
'Formula Engine'
end as Bottleneck,
a.NTUserName, a.ConnectionID,
case when (select stdev(b.duration) from ProfilerTraceTable b where a.eventclass = b.eventclass and a.eventsubclass=b.eventsubclass and duration is not null) = 0
          or (select avg(b.duration) from ProfilerTraceTable b where a.eventclass = b.eventclass and a.eventsubclass=b.eventsubclass and duration is not null)=0 then 0
else
 (a.duration-(select avg(b.duration) from ProfilerTraceTable b where a.eventclass = b.eventclass and a.eventsubclass=b.eventsubclass and duration is not null))
/
(select stdev(b.duration) from ProfilerTraceTable b where a.eventclass = b.eventclass and a.eventsubclass=b.eventsubclass and duration is not null)
end
as ZScore
from ProfilerTraceTable a
inner join ProfilerEventClass pec on a.EventClass=pec.EventClassID
inner join ProfilerEventSubclass pes on a.EventClass=pes.EventClassID
   and a.EventSubclass=pes.EventSubClassID
)
select RowNumber, EventClass, EventSubclass, TextData, QueryDuration, SETime, Bottleneck, NTUserName, Connectionid, ZScore
From ProcAnalysis
where EventClass = 'Query End'
-- and cast(zscore as float)>0.01
order by queryduration desc, ZScore desc