fed: Tracing in Dynamics AX 4 and 2009

[Blog bot]

Источник: http://fedotenko.info/?p=164
==============

I’ve spent considerable time trying to figure out how tracing works in newer versions of Dynamics AX. Although manual for Trace Parsers seems to be quite satisfactory on topics related to analysis of collected trace, it is pretty terse on the topic of trace collection and setting up; Dynamics AX Performance Team log has two very useful posts on trace parser (http://blogs.msdn.com/axperf/archive...tallation.aspx and http://blogs.msdn.com/axperf/archive...importing.aspx), but it seems that these trainings cover some early beta of trace parser tool and prerelease version of DAX2009. So, I decided to write small article about my findings related to trace parsing in Dynamics AX.

To have a full picture of tracing subsystem in DAX, keep in mind that actually DAX supports THREE kind of tracing:

1. SQL Tracing
2. Server Tracing
3. Client tracing

SQL Tracing

This kind of tracing was supported from the earliest version of Axapta, I’ve met. Even in Axapta 2.1 it was possible to have a log of SQL Statements issued by your application, by checking appropriate checkboxes in SQL tab of user settings. I won’ describe these settings in detail, You’d better play with them to understand. I only want to mention two SQL tracing-related peculiarities, introduced in version 4.0:

1. SQL Tracing work ONLY if your AOS configuration has “Allow client tracing on Application Server Instance” setting checked. In versions 2 and 3, SQL trace worked independent from any server configuration settings, so I was  little surprised when I tried to run familiar SQL trace on DAX4.0 without any results. It seems,that in attempt to gain couple of extra percents of performance, DAX kernel’s team decided to make this SQL tracing globally switchable starting from version 4.0.
2. If you are trying to log SQL Trace into file, expect to find this file ON SERVER SIDE. In versions 2 and 3, SQL trace file was being stored on local log directory. Starting from version 4.0, SQL trace file is being stored on Server side log directory. Probably, this is because performance team decided to completely decouple tracing process from client. Before attempt to commence SQL Tracing to file, please ensure that your AOS user (I mean – AD user, under which account AOS is run) has enough rights to create and write files in log directory. (Normally, It is something like C:\Program Files\Microsoft Dynamics AX\50\Server\DynamicsAx\Log).

Also, Normally results of SQL Tracing is stored in SQL table, browsable from Axapta itself. The only reason for usage of SQL Tracing to log-file is a special request from Microsoft support team (because it is much easier to e-mail a log-file than log-table).

Server tracing

The most useful way of tracing to my experience. First of all, I want to mention that this tracing module was introduced in Dynamics AX 4.0 and it heavily depends on Events Tracing for Windows subsystem (described in details in http://msdn.microsoft.com/en-us/libr...87(VS.85).aspx) So, if You have some problems with starting server trace, You should check that your AOS Server has appropriate Trace Provider installed. You can do it by running “logman query providers” command in AOS’ command prompt. Resulting output must have a line starting with “AOS Trace”. If your server does not have appropriate query provider, You can try to fix this by going into server’s BIN directory and running ‘mofcomp aos_trace.mof’ command. If your server has UAC turned on, this command must be run from command prompt with elevated privileges.

Tracing parameters can be configured on the ‘Tracing’ tab of Dynamics AX server configuration utility. I won’t go into detail about every checkbox and number on this tab,coz they are described in reasonable details in trace parser’s manual. The most funny thing about server tracing is that important-looking ‘Start Trace’ and ‘Stop Trace’ buttons actually DO NOT start a trace at all. They only change the value of Tracestart parameter in registry to 1 or to 0 respectively.

Somewhere in the heart of AOS’ server process, there is a separate thread which wakes up every second and check the value of TraceStart parameter in the registry. If the value of this parameter has changed from 0 to 1, this thread reads all other tracing related parameters from the registry (these parameters described in more details on Trace Parser’s manual) and starts the trace. If the value of this parameter has changed from 1to 0, this thread stop the trace.

So – If you want to start trace on live system, You need not restart AOS Service. You can just set necessary tracing parameters, then press Apply button to store them into registry (do not agree to restart service if Configuration Utility will try to propose it) and then just press ‘Start Trace” to set TraceStart Parameter value to 1. AOS will check the registry for changes and start tracing just in  few seconds.

The very first time, when I tried to run server trace I’ve faced the situation when my log directory, where I had expected to see trace file, was empty and my event log had rather cryptic error message from AOS Server:”Fail to start ETW tracing session: return code is 5”. After spending several hours trying to reinstall and reconfigure everything in my system, I figured out, that probably tracing is started with standard StartTrace WinAPI function, so 5 is an error code described in detail in the MSDN’s description of this function. Actually, this description is quite useful when You have some strange error message from Axapta’s ETW tool and You are trying to figure out what is happening. Moreover, this article has detailed description of all these in/max buffer and buffer size registry parameters, which, according to Trace Parser’s manual You should set before actual attempt to collect the trace.

From reading of the mentioned article, I comprehend two important rule related to security and ETW in Dynamics AX:

1. The AOS’ user must belong to the ‘Performance Log Users’ user group if it is running on Windows Server 2003 or 2008. WMI event tracing subsystem requires that tracing can be started ONLY from user belonging to the user group or to Administrators user group. Since the idea of including AOS’ user into Admin group sounds completely wrong, the only solution is to include AOS’ user into ‘Performance Log Users’ group.
2. The AOS’ user must have full access rights to server’s log directory.

Once, I also saw the ”Fail to start ETW tracing session: return code is 132” error message. It was caused by incorrect setting of tracefilesize in Dynamics AX configuration in registry. By default, this setting is set to 10000. So, on attempt to start tracing, WMI Event tracing subsystem checks that target drive for log file has 10000 MBytes available (10Gbytes actually). If available space is less than 10Gbytes, attempt to start tracing fails with the error message mentioned. I recommend to set this setting to something like 1000, because actually Trace Parser tools tends to choke on attempt to import event file larger than several hundreds megabytes.

A Trace log file, with the results of tracing session is created in server’s log directory and has binary format. Result of the tracing can be analyzed via usage of Trace Parser tool, available somewhere at Microsoft’s PartnerSource site.

Another small hint: First time then You try to work with server trace in trace parser tool, do not forget to select correct user in a small window in the upper left corner of the trace form. It seems obvious, but on my first try I spend couple of minutes trying to comprehend relation between what I had been doing in Axapta and what I saw on a screen. Somehow, It did not occur to me immediately that server tracing actually collect trace for ALL current user on a server.

Also – Keep in mind that if server has around 150-200 users, then server trace will produce around 150-300 MBytes of trace data every minute, so do not keep tracing your server longer than necessary.

Now, I want to discuss, why I consider Server Tracing extremely important for every DAX implementation technician. Most of developers heard that this tracing can be used for performance profiling of application. It is true. But actually, there is much more interesting application of Sever Tracing. You can treat it as a magical almost non-intrusive flight recorder which can be used to pip into already running application which suddenly went crazy and you do not have an idea what is happening. Say – You have a call from end-user, who complained that scheduling for one production order already took 20 minutes and still is running, while normally it take no more than a minute. You must try to start server tracing ASAP! Even if this scheduling finish in a minute or so, You hopefully would have enough trace data to analyze the situation later on.

As a conclusion: I consider Server Trace as a primary tool for nailing down floating errors, which does not have clear reproduction scenario by now.

Client tracing

First of all: You will be surprised, but Client Tracing just does not work in default installation. At least, all dynamics ax installations, I’ve checked does not have appropriate trace provider installed. I do not know, whatever it is an error or feature of Dynamics Installer. Before attempt to start client tracing, please run ‘logman query providers’ command and check whatever the command’s output has line starting with “AX Trace” in it. If it is not the case, first thing You should install AX Trace provider by running mofcomp ax_trace.mof from DAX Client’s bin directory. (In case of Vista/W7/WS2008, mofcomp must be run with elevated privileges).

The approach used for starting client tracing is similar to the approach used to start server tracing. Client periodically (I think – in the main message loop) checks the value of TraceStart parameter in the corresponding section of registry. If the value of the parameter has changed from 0 to 1, client starts tracing and so on.

So – The basic approach to starting/stopping tracing on a client side is the same as in case of server side tracing.

Here are several hints on Client Tracing.

1. Client tracing only works if Axapta’s client is started with Administrative privileges. This requirement arises from usage of StartTrace function. I believe, If you include yourself into “Performance Log Users”, it would achieve the same result, but I never have tried this. Actually, when I need to run client trace I simply start DAX Client in “Run as Administrator” mode.
2. FIles with client trace are located in Client’s log directory. In default configuration it is set to \Users\Public\Microsoft\Dynamics Ax\Log\ or \Document and Settings\All Users\Microsoft\Dynamics Ax\Log\.
3. As I said – You can start tracing at any time, by pressing “Start Trace” button in client configuration utility. Since the client checks registry settings less regularly than server, expect some delay between pressing the button and actual start of client tracing.

In a conclusion, I want to mention that client tracing is the most useless kind of a tracing in Axapta. First of all, normally most of business logic is performed on a server side (so no much to see on a client side trace). Second, client trace does not contain information about performed SQL statements at all. (Since statements are always executed on server side).



Источник: http://fedotenko.info/?p=164