When deploying Voyager there are times where you need to troubleshoot performance problems. Checking for long running MDX statements is one of those trouble shooting steps. This article describes how to use Micosoft SQL Server Profiler to capture MDX execution times.
Why use SQL Server Profiler?
Using SQL Server Profiler to capture Voyager MDX timings is one of the least invasive and most flexible ways to do this. It does not require any servers to be restarted and the SQL Server Profiler tool has functionality to filter down the information it logs to particular users and particular sessions, so if the system you are trying to profile is being used by multiple people you can easily sift out the information you don’t want and focus on the information you do want.
Voyager does have logging mechanisms that log out MDX statements and captures query times but this method has two drawbacks. If you have not set up the correct logging settings you will need to restart the MDAS server before these settings take effect. If there are multiple users on the system at the same time, all MDX statements from all these users will be logged. It will be difficult if not impossible to tell which MDX statements correspond to your test.
Why shouldn’t I use SQL Server Profiler?
If you are doing a test to compare the proportion of time spent at various layers in the Voyager stack then the times logged by SQL Server Profiler will not represent the amount of time spent between when the Voyager data access component executes an MDX statement and when that execution returns. This is because the Voyager data access component calls the ODBO interface on the Microsoft Analysis Services (MSAS) client component msolap90.dll (for MSAS 2005). SQL Server Profiler does not log time spent in this component. Voyager’s own MDX logging does include the time spent in the component.
For trouble shooting exercises that just require the identification of long running MDX statements using SQL Server Profiler is usually fine. If you need a true breakdown of where time is being spent then you will need to cross-reference the SQL Server Profiler times with times logged by Voyager’s own logging. It is not unheard of for the amount of time logged by the Voyager MDX logging to be twice as much as the time logged in SQL Server Profiler. In this example this would indicate that 50% of the time was being spent inside the Microsoft client component which is not measured by SQL Server Profiler.
Where is SQL Profiler located?
SQL Server Profiler is included with installations of Microsoft SQL Server 2005 and 2008. You can use the version included with 2008 to profiler a 2005 server instance.
Starting a new trace
Once SQL Server Profiler has been invoked you can start a new trace by going to the File menu and choosing New Trace.
You will now see the ‘Connect to Server’ dialogue. Ensure that you have selected a server type of ‘Analysis Services’ and enter the server name.
Given that you are not able to enter in specific credentials to connect to the server, ensure your user has sufficient rights to run traces against the Analysis Server.
Configuring the trace
It is not necessary to log all the information that can be captured by SQL Server Profiler, so when starting the trace you can tune SQL Server Profiler to log just the information necessary to capture the MDX timings.
Once you have connected to the server you should see the Trace Properties window. Click on the Events Selection tab of the Trace Properties window.
This window allows you to select or deselect individual events, and for an event that you have selected it allows you to select which information you want to see for that event. For capturing Voyager MDX timings you can turn off all the events apart from the following ones.
The Query End event logs the MDX statement executed plus the time it took to execute. It also gives you a time stamp for when the query started and ended.
The Session Events are also useful as the initialization of session should correspond to the creation or opening of a Voyager workspace.
Running tests from Voyager
Before and while running tests from Voyager it is important to do the following:
Note the windows user name of the user that will be authenticating against the Analysis Services server. You will need this to filter down the results in the SQL Server Profiler log if there are multiple users using the system at the time the trace is running
Try and ensure that there will be no one else using this user name at the time you are conducting your tests so as not have test and non-test information logged against that particular user name in the trace log
When you start a test, note the time so you can verify this to a session initialization entry or an MDX statement in the SQL Server Profiler logs
Once your tests are complete
Once your tests are complete you can stop the trace and save the trace log as a trc file from SQL Server Profiler.
Retrieving the MDX times
To retrieve the MDX times you open the trace file you just saved in the SQL Server Profiler tool and then filter the results down so that you are just looking at the MDX statements relating to one of your test runs. You can then copy this information into an Excel spreadsheet and use Excel’s formula functionality to add up the times or do any other manipulation of the data you want.
Filtering the results down to a particular user
When you have opened the trace file, go to the File menu and choose properties:
Now click on the Events Selection tab. Locate the Column Filters button towards the bottom right and click. Find the NTUserName entry in the list on the left hand side and add the user name of the user who conducted the tests.
Filtering the results down to a particular session
If you have run test that, for example, consists of opening a number of Voyager documents, the opening of each Voyager document will be in a different session. This is because each Voyager document has its own instance of a connection to the Analysis Services server and will create a new session. Therefore if you want to just look at the MDX times for one session, you can locate this session number in the trace file and then add a filter for just this session.
If you noted what time you opened the Voyager document at you should be able to locate a Session Initialize line corresponding to the time you opened the Voyager document.
Here there is a Session Initialize logged at 11:31:59 so if the Voyager document you are interested in was opened at this time, you know that all entries associated with ConnectionID 30 will be to do with this report.
Getting the MDX times
There is a column in the trace file called ‘Duration’ this contains the time it took to execute that MDX statement.
If you need to sum up the total amount of time executing MDX you can dump this information into Excel. Shift select all the rows you are interested in and use Ctrl+C or go to the Edit menu and choose Copy. You should then be able to paste the contents into an Excel spread sheet and add up the times by placing a sum at the foot of the Duration column.