PI-SDK Tracing for Troubleshooting and Programming

Sometimes when troubleshooting a problem it is useful to determine what PI-SDK calls a running application is making and how long those calls take to execute. A tracing facility has been added to the PI-SDK to enable configurable logging of this information. The sections below describe the type of information logged and how to configure tracing. Note that when tracing is turned on it will negatively impact performance. It is intended only as a troubleshooting device.

Also, when developing programs using the PI-SDK, it may be helpful to examine the methods called and frequency of those methods. This may assist in designing a more efficient program.

Tracing Overview

What is traced?

The SDK can be configured to log calls made to a published object's methods and properties. Within each of these calls, a depth of tracing can also be set to provide more detailed information, such as how much time is spent waiting for a server call placed on the wire. Each trace covers a particular scope. The tracing log will show two entries for each trace, one where the scope of the trace is entered and one where it is exited. The second trace will contain a time in milliseconds that elapsed during the trace's scope. For example consider the following trace output:

OBJ:ENTRY(3636) : Server.Open
		GEN:ENTRY(3636) : CPI3Server.Open
			WIRE:ENTRY(3636) : CPI3Server.Open:CreateSession
			WIRE:EXIT (3636) : CPI3Server.Open:CreateSession : 578 ms
		GEN:EXIT (3636) : CPI3Server.Open : 578 ms
		GEN:ENTRY(3636) : CPI3Server.Open
			WIRE:ENTRY(3636) : CPI3Server.Open:CreateSession-non trust
			WIRE:EXIT (3636) : CPI3Server.Open:CreateSession-non trust : 453 ms
		GEN:EXIT (3636) : CPI3Server.Open : 453 ms
		GEN:ENTRY(3636) : CPI3Server.IsSupportedTimeZone
		GEN:EXIT (3636) : CPI3Server.IsSupportedTimeZone : 0 ms
		GEN:ENTRY(3636) : CPI3Server::GetServerID
			WIRE:ENTRY(3636) : CPI3Server:GetServerIDSDK
			WIRE:EXIT (3636) : CPI3Server:GetServerIDSDK : 109 ms
		GEN:EXIT (3636) : CPI3Server::GetServerID : 125 ms
OBJ:EXIT (3636) : Server.Open : 1203 ms

Here a call to Server.Open is made by a program. The scope of this trace is not closed until the last line of the trace where we can see that call took 1203 milliseconds (1.2 seconds). Because of the depth configured for this tracing session, we can also see other traces, each with their own scope. The indent level and the text identify the scope of the trace. In the output above we see where the PI3 server level is called several times and within those calls, where it places calls on the wire. It is apparent from the trace above that the time spent in this call is primarily time spent on the wire and that multiple calls are placed to the server to obtain a valid login. The number shown in the parenthesis is the thread ID so calls can be traced to their calling thread.

Where is it logged?

Logging can be configured to be either to files in a configured location or to a Windows debugging window. For simple debugging, using a window rather than a file can be quite useful. Many programming tools support a debugging window but perhaps a more serviceable, freely available tool for viewing output to a debug window called DebugView is available from Microsoft System Internals (sysinternals).

How do you turn it off and on?

Tracing is configured using a time rather than just an on/off setting. By setting a time in the future, say by one hour, you are in effect saying you want tracing for all programs started within the next hour. The advantage of this approach is you can easily avoid accidentally leaving tracing on and filling your disk with logs or negatively affecting performance as the setting basically times out. For those who needing extended periods of tracing, a longer time span can be used.

Tracing Configuration

Tracing is configured from the "Tracing Setup" menu in the PISDKUtility program delivered with the PI-SDK. This utility makes entries in the registry that control tracing.

Selecting Tracing from PISDKUtility shows the following configuration options.

The screen above shows the default settings for the dialog. To configure tracing, you change the desired settings and click the Save button which will close the dialog and write the new values to the registry. If you reopen the dialog you should see your new values retained. If you want to return the settings to their default values, click on the Reset to Defaults button.

Tracing Until

This field is used to control whether tracing is on or off. Any program started after this date/time will not be traced. The screen above shows the default which is back in time meaning tracing is off. The field takes PI time strings so you can enter an absolute date/time or even more useful a relative time as shown in the parenthesis. Entering *+1h means programs started in the next hour will be traced. Note when entering a relative time, the time is evaluated when you hit the Save button and stored as an absolute time. When you reopen the dialog you will see that absolute date/time string.

Trace Level

This field controls which objects are traced. The most important objects are given lower numbers so a higher setting means more objects are traced. Some examples of the trace level of objects are shown below. Within an object, the main methods are all set to the same trace level however properties which require little processing time and/or are accessed very frequently are given the object's trace level number plus 100. This keeps the tracing output reasonable. If you must see everything, set the trace level high (200).

Example object trace levels.

Object Trace level
PISDK 1
Servers 3

Server

5

PIPoints

13

PIPoint

15

PIData

10

PIValues

20

PIValue

30

PointAttributes

25

PointAttribute

40

 

Objects from the PISDK.dll and PISDKCommon.dll are traced. This means time objects from the PITimeServer.dll are not traced.

Trace Depth

Tracing depth controls how deep in the call stack of a particular method or property call you wish to log. There are four options:

  1. Object calls
  2. Server specific calls
  3. Wire calls
  4. Verbose

These options represent a hierarchy so the higher numbered options above include logging for the lower numbers. For example, if you choose to log Wire calls then Object calls and Server specific calls are also logged.

Object calls are those calls made directly into the PI-SDK from a program (e.g., Server.Open). Server specific calls are those made at a lower level in the PI-SDK code where specific action is taken depending on the type of server being addressed. Wire calls bound queries sent directly to the server so you can see how long a particular client call waits for its request to be sent, processed and returned. Finally verbose tracing includes all of the above plus other code paths in the PI-SDK source the developer thought should be measured.

Output Mode

This setting controls where the trace output is written. If "File" is selected (the default) the tracing program will write files in the directory shown under "Output file path". The path entered must already exist for tracing to be successful. One file is written for each program started while tracing is on. The format of the file name is:

pisdktrace_date/time_processID.log

Where date/time is in the format YYMMDDhhmm and processID is the numeric process identifier of the program as shown in Task Manager. For example:

pisdktrace_0409200900_00836.log

If "Debug Window" is selected, tracing output is done to a special Windows debugging window supported by debuggers and third party tools as described above. For short interactive debugging sessions this is often the most efficient method.

Enabling Operational Intelligence