What is ASPerfCounters.JSON?

In a previous blog post, I have talked about the various diagnostic data that Power BI Desktop has available for troubleshooting issues.  One of the interesting files generated is ASPerfCounters.JSON.

I originally thought the name came from  ASP.NET performance counters but I am guessing that it actually has its roots with Analysis Services.

I was curious to see what data was contained in this file so I used Power BI Desktop to open and parse the file.  Power BI Desktop has a JSON file connector so it was relatively simple to crack the file open and see what was inside.  I was pretty surprised to see that the file actually had PERFMON data from the time that the file was generated to an hour earlier.  The data is collected every 60 secs for the following performance counters:

PagedMemorySize64inBytes & PeakPagedMemorySize64inBytes

VirtualMemorySize64inBytes & PeakVirtualMemorySize64inBytes

WorkingSet64InBytes and PeakWorkingSet64inBytes

PrivateMemorySize64inBytes

SystemAvailableDiskSpaceInBytes

SystemAvailableMemoryInMB

SystemCPUUsagePercentage

TotalProcessorTimeInMillisecs

To load the data into Power BI Desktop, I did the following.

  1. Use the process in the earlier blog post to generate a Frown Snapshot File.  Open the zip file generated and copy out the the ASPerfcounters.json file that has been generated.
  2. Use the JSON File connector to ‘Get Data’ and open the ASPerfCounters.json file.

3.   The Power Query Editor will open and it will show a list of records.  *Note – the following steps are how I imported and cleaned the file, no doubt there are other ways that it can be done as well.*

4.  First we need to convert the list to table.  If you right click the list column, you will see an option called ‘To Table’.

Select ‘To Table’ and you will get a confirmation dialogue asking for delimiters and how to handle extra columns.

I left everything as default as shown and selected ‘Ok’.

5.  At this point, your list has been converted to a table.  I selected the expand icon and selected ‘ok’ to the dialogue that appeared:

6.  Once expanded, Column1.p is yet another list that needs to be expanded.  When you select the expand icon, you get the option to expand to new rows.  Select that and will now see that Column1.p contains records that need to be expanded.  Expand Column1.p once more time and select both the key and value.  You will most likely want to ensure that ‘Use original column name as prefix’ is unchecked.

7.  At this point, you have all of your data expanded and accessible but there are some more things to be done to get at least a basic set of useful data.

First, delete columns ‘Column1.i’, ‘Column1.n’ and ‘column1.u’.  Nothing useful there.

Next you will want to pivot the key column.  Select the key column and choose ‘Pivot Column’ from the Transform section of the ribbon as shown:

When the dialogue pops up, select the default which should have the ‘Value’ column chosen as the ‘Values Column’.

This will display the data in a nice familiar format, date in the first column and columns for each performance counter.  Of course, the data looks pretty odd:

The date is displayed in what is apparently a native JSON date format.  I had to go hunting on the Power BI Forum to find out how to handle this format.  Luckily, Greg Deckler had this one in the bag.  The date is stored as milliseconds from 1/1/1970.  He lists a way to convert it using a calculated column but I wanted to convert it in power query so I used the following steps.

I selected the date column, then chose ‘Extract’ from the Transform section of the ribbon.  I chose ‘Text Between Delimiters’ and used the open and close parentheses as delimiters as shown.

Now I was dealing with a column that was in milliseconds so I set about parsing out the date and time.  I first renamed ‘Column1.t’ to ‘DateMill’, converted that column and all of the perf counter columns to actual numbers and then to get the current date, I added a custom column with the following code:

Date.AddDays(#date(1970,1,1), Number.IntegerDivide([DateMill], 86400000))

To get the time value in GMT, I created the following custom column:

= Table.AddColumn(#”Added Custom”, “Custom.1”, each Time.From(([DateMill]/86400000) – Number.IntegerDivide([DateMill],86400000)))

At this point, you can spend more time cleaning up the data and charting it as you wish:

 

So, why is this useful?  Well, its cool that you can use Power BI Desktop to parse JSON files.  This file might prove useful if you have a large Power BI model that takes hours to refresh.  In case of a crash, you can look at this file and see what was going on with your desktop performance.  You could also use these metrics to review performance during a refresh in case Perfmon is not your cup of tea.

 

Copy Session Diagnostics to Clipboard

Another quick hitter on Power BI Diagnostics.

If you have your model open in Power BI Desktop, you can get a quick dump of all of your Power Query code by doing the following:

  1.  From the top ribbon, Choose ‘Help, then ‘About’

2.  This will launch a popup window.  Choose ‘Copy diagnostics to clipboard’.

3.  Open Notepad (or Word, or OneNote, etc.) and paste.  All of your PowerQuery M code will be included in the information that is copied.

4.  Note also that when you do this, you generate a ‘Frown Snapshot’ file in your diagnostic folder.  By default, this snaphshot will have some ASPerfCounter data and ‘FlightRecorderCurrent.trc’, which is your Power BI ‘black box’ recorder.

Nifty eh?

Getting started with troubleshooting a slow Power BI report page

Performance always is an issue, isn’t it?  Throughout a career that wandered through IIS (My web pages are slow), SharePoint (My web parts/lists/search queries/indexes are slow), SQL Reporting (My SSRS reports/stored procedures/excel pages are slow) and now Power BI (My visuals are taking forever to load), troubleshooting slow performance is always a big part of what I do.

Troubleshooting Power BI visuals can be a little tricky.  There aren’t any obvious dials or gauges to look at, you can’t spin up perfmon and attach it to Power BI desktop and the logs, while impressive looking, won’t help you narrow in on the poorly written measure that is killing your performance.  What I am going to layout next is a quick approach that you can take to not only get a good look at the performance of a report page but how also you can narrow in on the measures that are dragging you down.

Quick Setup Note – I am using the customer profitability sample from Microsoft for my PBIX file.  Its visuals load super quickly but its a quick and easy download here.

First things first, your reports and data model need to be in the same PBIX.  We will be using Dax Studio to connect to the data model and run a trace so everything we are testing needs to be in the same PBIX.  If you have your visuals and data model in separate PBIX files, you will need to recreate your visuals in the PBIX where your data model live.

STEP ONE:

Create a blank report page.  Power BI desktop will load visuals on the report page that it opens when you open the PBIX so in order to capture a true idea of the page performance, you need to create a blank report page and save the PBIX with that page active.

STEP TWO:

Close and reopen your PBIX file.  If you did step one, you should be looking at a blank report page.

STEP THREE: 

Open Dax Studio and the ‘Connect’ screen should open.  Select your open PBIX dpcument as shown and select ‘connect‘.

STEP FOUR:

Once connected, click on the ‘All Queries’ button in the ribbon.  This actually starts a trace on your SSAS instance that is running in Power BI desktop.  Once the trace is ready, you will see ‘Query Trace Started’ in the output window.

STEP FIVE:

Return to your PBIX that you have open in Power BI desktop.  Click on the report tab that you wish to trace and let the page fully load.  Once the page loads, you can stop the trace by returning to DAX Studio, choosing the ‘All Queries’ tab and selecting the stop button.

STEP SIX:

Once the trace is stopped, click on the duration column header to sort the queries by duration.  As  I mentioned earlier, this demo is super fast so the ‘slowest’ query took 21ms but hopefully you get the point.  You know have a list of queries that were performed to build your page, along with the time it took to execute each of the queries.

STEP SEVEN:

Continuing on, double click on the query text in the ‘Query’ column.  The actual code used will show up in the editor section above the output section.  Now you can analyze the DAX being called as well as run an individual trace to dig in deeper.

DIGGING DEEPER:

At this point, you can run all of the DAX in the editor or you can highlight and run just sections of it, just like normal in DAX Studio.  If you enable the Query Plan and Server timings options, you can capture a trace and see the actual queries that are being passed to the formula and storage engine for processing.  Enabling the query plan option does just what it says, it gives you the query plans, both physical and logical, that were chosen to run the queries.

I have a long animated GIF below that shows turning on the query plan and server timings options, setting the ‘Run’ option to flush the cache each time I run a query, then running the query.  I then show where you can find the query plan and server timings information.  Since I got the whole screen in the GIF, its a pretty lousy resolution but perhaps if you open it in another tab, you can see enough detail.

Questions, comments, suggestions on digging deeper into Power BI visuals/reports performance?  Throw me a comment or hit me up on Twitter – @szBigDan.

A little bit about Power BI Diagnostics

Gilbert Quevauvillie from FourMoo posted a great blog post identifying all of the different processes that are running when you have Power BI running.

He identifies four different processes that you will see running and a quick blurb on each.  I wanted to post a quick follow up to show how the diagnostic logging in Power BI captures output from these processes.

Power BI Desktop has diagnostic logs?  Absolutely!

To turn on the logging, enable it from your options as follows:

There is a link that you can click on that will take you directly to the traces folder in case you aren’t the type to memorize logging locations for software.

When you open this folder, \%username%\AppData\Local\Microsoft\Power BI Desktop\Traces, there are actually two sets of logs.  The first set is stored directly in this folder and they will only be created once you turn on tracing.

If you open the Performance folder that is in this directory, you will see that Power BI Desktop actually is ALWAYS logging.  I am fairly certain that these are a rolling set of logs that are captured in case of an unexpected failure.  When Power BI crashes, it will create a FrownSnapShot zip file and a PerformanceTraces.zip file.  The latter is a zip of the Performance folder.  The FrownSnapShot zip file is pretty cool because it contains the latest SQL Flight Recorder data that has been captured.  Interestingly enough, the FrownSnapshot zip also includes a file called ASPPerfCounters.json which looks like Perfmon data that is dumped into a JSON file.  Interesting……

The log files that you will find in the Traces folder are as follows.

  1.  PBIDesktop.<version>.TimeStamp
    • This file logs information for the Power BI Desktop Application.
  2.  Microsoft.Mashup.Container.NetFX45.<version>.<TimeStamp>
    • This log appears once you go into the Query Editor or refresh your data.  This is where Power Query actions are logged during the processing and cleaning of your data.
    • Once you start a data refresh in Power BI Desktop, you will see multiple log files that start with this name.  I am going to assume that Power BI Desktop will spin up multiple Power Query engines as necessary and each will have its own log file.
  3.  MSMDSRV.<version>.TimeStamp
    • From my experience, you will only see this log if an exception is captured by the SSAS engine in Power BI Desktop.  For instance, I saw this log appear when I was troubleshooting a crash that was occurring during data refresh.  This log is also included in the FrownSnapshot zip that is created during a crash.

If you have questions about Power BI Logging or want to add corrections, please leave me a comment!