Power BI Diagnostics, Trace Logs And Query Execution Times (Again)

I’ve blogged a few times now about how to monitor Power BI query execution times, most recently here, and while using functions like DateTime.FixedLocalNow() is all very well I’ve never been happy with the fact that you have to alter your queries in order to be able to time them. Using the Power BI trace logs always seemed a much better option – and since the log files are in a reasonably easy to understand text format, you can use a Power BI query to load data from them. I wrote a post on importing data from the trace logs (using Power Query) here back in 2014 and Rui Romano has a great post on doing the same thing for Power BI here. The big problem with the Power BI trace logs, though, is that there is too much information in them: they’re really meant for Microsoft internal use, I guess, and not for the likes of you or me. In fact it’s all low-level data in there and there’s no way to see (as far as I know) the overall time taken for a query to run.

However, last month when I was looking for new M functions using the old #shared trick I came across the Diagnostics.Trace() function which allows you to write to the Power BI trace log direct from your query.  After a bit of experimentation, I found out that this function is the key to a truly elegant way of logging query execution times. Here’s a proof-of-concept that I’ve put together to show how it could be used…

First of all, consider the following query called LongQuery:

It returns the text “Hello” and uses the Function.InvokeAfter() and Number.RandomBetween() functions to wait anything from one to six seconds before doing so. Let’s pretend that this is a real query that does something complex and that we’re trying to tune it.

Rather than alter this query, instead the best thing to do is to create a new query that calls this query through Diagnostics.Trace(). Here’s the code:

I’ve called this query Diagnostics. All it does is return the same value as LongQuery but in doing so it also writes a single message to the trace log. #”Trace Message” is a text parameter that allows you to specify what message to write – you might want to put some kind of version number in here, or a description of any changes you’ve made to your query while tuning it:

You should also make sure that the Diagnostics query doesn’t get loaded into the data model by making sure the Enable Load option is deselected:

One important thing to remember is that for the Diagnostics query to actually log anything, you need to have the Enable Tracing option turned on in the main Options dialog (you can find this on the File menu in the main Power BI window under Options and settings/Options):

You will also need to remember to turn this on every time you open Power BI Desktop.

With that done, you just need to hit the Refresh Preview button to refresh the Diagnostics query in the Query Editor window:

The Diagnostics query will run, calling the LongQuery query and making an entry in the Power BI trace log. You can find the directory with the trace logs in them by clicking on the Open Traces Folder link in the Options dialog shown above, and you can open the any of the trace log files using your favourite text editor.

Loading this trace file into Power BI is pretty straightforward using code similar to that in Rui’s or my blog post. The difference is now, instead of loading everything, you can filter the rows to only load the events created by Diagnostics.Trace(). as far as I can see you can identify these rows because they have the value

“Action”:”Engine/User”,”Message”

Somewhere inside them, as you can see from the last screenshot. Most importantly of all, the duration logged for this event is the amount of time taken to execute the query.

Therefore, with some Power BI M magic, you can load all the data from all of the log files in the log directory, filter the rows to only those created by Diagnostics.Trace(), and end up with a query that gives you something like this:

The Execution Index and Date Time columns tell you when the query was executed, the Message column contains the value of the Trace Message parameter at the time the query was executed, and the Duration column tells you how long the query took to execute. You can then, of course, load this table into the data model and build a report that helps you analyse these execution times:

To sum up, the workflow for tuning your query is:

• Make some changes to the LongQuery query that hopefully make it faster
• Update the Trace Message parameter with some notes about which version of the LongQuery query it is that you’ll be testing
• Click the Refresh Preview button for the Diagnostics query to test how long LongQuery now runs for
• Refresh, or load, the query that reads the data from the trace logs so you can see how all of your changes have affected query execution times

Some other closing comments:

• As I said before, this is just a proof-of-concept and I although haven’t tested it thoroughly but it seems to work.
• Microsoft may well change the format of its trace logs or make other changes in the future that could break this code shown here.
• Although I haven’t tried it, this approach should work for Power Query too with some minor modifications.
• Since it relies on you turning on tracing in Power BI Desktop, this won’t work after you have published your reports. In fact I’ve deliberately structured the queries here so that logging only takes place when you click the Refresh Preview button for the Diagnostics query in the Query Editor window – I found this was the best way to reduce noise in the log files, especially given the fact that a query can be executed multiple times when data is actually being loaded into the data model.
• That said, the Power BI Enterprise Gateway has its own log files, so maybe you could adapt this approach somehow to work with them?
• I suspect there are lots of other uses that Diagnostics.Trace() could be put to for even lower-level debugging and analysis of queries, but that’s something for a future blog post.

You can download the sample code as a Power BI template from here. When you open the template you’ll be prompted to enter two parameter values: the message to record for your events in the trace log and the path of your trace log directory.