Trace Predefined Probe

From OC Systems Wiki!
Jump to: navigation, search

Trace Probe: trace.ual

The trace.ual predefined probe traces the execution of selected subprograms within any application program. This probe creates a report that lists which subprograms were invoked, in which order, and optionally the time when each was invoked. In addition, line tracing may be applied to selected subprograms to log the order in which any source lines within the subprograms were executed. The probe also traces the switching from one program thread to another.

Note: if you're using Aprobe as part of OC Systems' RootCause product, you should use RootCause to define your traces. It's much easier..

As your application program is running, the trace data is collected and logged. It can be logged directly into a file (an APD file), or it can reside in memory in a circular buffer. Either way, you can log many millions of calls, and you can analyze the data after the application has completed using apformat. This "trace report" is simply ASCII text and can be viewed with a text editor or processed with other text-manipulation tools.

The APD file size is limited only by your hard disk space. If the trace data resides in memory, then the oldest contents of that circular buffer are simply overwritten by the newest trace data each time the buffer fills up and wraps around; and of course, the entire contents can be saved into a file at any time by taking a snapshot.

Snapshots of the circular buffer's contents may be taken at any time while the program is running. A snapshot takes the current state of any logged trace data in the circular buffer in memory and writes it out to an APD file. Taking periodic snapshots at known events, like the entry or exit to a particular subprogram, allows you to compare and contrast the state data that was recorded at those various times, and allows you to save a historical log of what happened just prior to those moments. A final snapshot also automatically occurs at program termination, if the circular buffer is being used and still contains data. For more information, see Snapshots.

Usage

This probe is applied at run time using aprobe as described under Trace UAL Parameters below. The only functions that will be traced are those selected with the Trace or Snapshot keywords in the configuration file (see Configuration File and Configuration GUI). The Remove keyword allows you to remove a function from the set to be traced, and the Trigger keyword limits tracing to specific paths rooted at a specified function.

By default, trace information is written to an APD file. The aprobe -if option may be used to send trace output directly to the screen as the program executes. The configuration keywords SaveTraceDataTo and Snapshot may be used to save trace data to a circular memory buffer instead, and write out its contents only at specified events to an APD file.

Trace UAL Parameters

trace.ual is specified on the aprobe command line or in an APO file as described in Command Line. The specific options are:

aprobe -u trace.ual     [-p "[-h] [-v] [-g] [-t] [-l] [-c config_filename]"] your_program

where:

-c config_filename

specifies that the name of the probe configuration options file will follow immediately after -c. The default file name is your_program.trace.cfg. For example, if your executable program is called wilbur.exe, then the default file name would be wilbur.exe.trace.cfg.
-g
starts the Java configuration GUI at probe startup, before running your program.
-h
produces brief help text.
-l
records the source line numbers of lines that were executed in a probed subprogram invocation. This supersedes the configuration option LogLines FALSE that may appear in the configuration file. Note that only routines that have the Trace_Lines modified specified (see TRACE_LINES) will have their lines logged.
-t
records a time-stamp on entry to and exit from each probed subprogram. This supersedes the configuration option LogTimes FALSE that may appear in the configuration file
-v
verbose mode, which produces additional progress messages.

Trace Configuration File

The Trace configuration file is used to specify what subprograms are to be analyzed, when snapshots are to be taken, and other options, as described in Configuration File. The example below shows one possible Trace configuration file.

 PROBE CONFIGURATION FILE FOR TRACE VERSION 2.1.0
 
 // Boolean Options:
 LogTimes TRUE
 LogLines TRUE
 TracingEnabledInitially TRUE
 StartWithGUI FALSE
 VisualHistogram FALSE
 LogJavaClassLoads TRUE
 
 // Numeric Options:
 NumberOfTracedItems 10000
 DefaultLevels 5
 LoadSheddingThreshold 0
 
 // Other Options:
 SaveTraceDataTo APD_FILE
 // SaveTraceDataTo CIRCULAR_BUFFER
 
 // Here we select which subprograms we want to trace:
 //
 // Use 'Trigger' to identify the functions we're
 // directly interested in, and Trace to identify what
 // ''called'' functions should also be traced.
 //
 // We want to see OpenCallback and a few things it calls:
 TRIGGER "OpenCallback()" LEVELS 20
 
 // see who's calling open, read:
 TRACE "open()" in "libc.so"
 TRACE "read()" in "libc.so"
 
 // see who's calling Motif library functions
 TRACE "*" in "libXm.so" LEVELS 5
 
 // For Java, specify "$java$" module.
 // TRACE "MyClass::*" in "$java$"
 

Example D-10. trace.cfg File

Configuration Variables

The following are the only valid keywords that identify lines to set configuration variables. Each such line must begin with one of these keywords, and the keyword must be followed by its value. Nothing else is allowed on the same line.

LogLines

This must be followed by the value TRUE or FALSE. The default is TRUE. If this is TRUE then any TRIGGER or TRACE function which specifies TRACE_LINES will have lines traced. If this is false, no function's lines will be traced even if TRACE_LINES is specified for them..

LogTimes

This option is deprecated; time information is always recorded.

DefaultLevels

This must be followed by an unsigned integer value that specifies the maximum nesting level of any traced calls that will be logged as a result of tracing within calls to a TRACE function. The default is 5. Note that this value can be overidden for each TRIGGER function. This value used to be called MaxDepthOfTracedCalls which is still allowed but deprecated (for commonality with profile).

LoadSheddingThreshold

The trace probe provides automatic, load-based disabling of probes. This is called "load shedding". The LoadSheddingThreshold variable must be followed by an integer. The default is zero, indicating that load shedding is disabled. A nonzero number specifies an acceptable level of tracing overhead, which, when exceeded, will cause tracing of the most frequently-called functions to be disabled. Thus a lower number means lower overhead and more load-shedding.

LogJavaClassLoads

This must be followed by TRUE or FALSE. The default is TRUE. When TRUE, and the Java virtual machine is traced as part of the application, the initial load of each Java class is reported For example: Java class loaded: "Pi".

NumberOfTracedItems

This must be followed by a non-zero unsigned integer value that specifies how many traced items (either calls or lines) will be logged at once in the circular buffer. The default is 10,000 and there is an upper limit of 1 million. This value indirectly specifies the amount of memory that will be reserved for data logging purposes, and therefore, it can adversely affect the total amount of memory left for the application program itself.

TracingEnabledInitially

This must be followed by the value TRUE or FALSE. The default is TRUE. The value TRUE indicates that data logging will begin as soon as the application program starts running. The value FALSE indicates that data logging will not begin until a call is made to the probe's function ap_EnableTracing or a TRIGGER function is encountered (rather than as soon as the application program starts running).

SaveTraceDataTo

This must be followed by a value that is one of APD_FILE or CIRCULAR_BUFFER. The default is APD_FILE. A circular buffer is in memory, not in a file, and it will only hold a finite number of traced items (calls), so after the buffer is full, any further data logged into it will wrap around and overwrite the oldest previously logged data. Thus, a circular buffer will always contain only the most recently logged data. Logging the data to an APD file instead would typically allow you to log a much larger amount of data, limited only by the space available on your file system, but with a slowdown in the execution of the traced program.

StartWithGUI

This must be followed by the value TRUE or FALSE. The default is FALSE. The value TRUE indicates that the configuration GUI should be started before the target program runs, even if -g wasn't specified on the command-line. A FALSE value is overridden by the -g command-line option.

VisualHistogram.

This must be followed by the value TRUE or FALSE. The default is FALSE. When set to TRUE this displays a simple Ascii histogram representation after each event (routine entry / exit, etc) of the time that has elapsed since the last event. For instance, **000oooo..... is 2.345 seconds - the scale is displayed as part of the output. This option is only meaningful if LogTimes is also TRUE.

Configuration of Traced Functions

By default, if no TRACE or TRIGGER lines exist, only the "main()" function of the application module will be traced.

TRACE

Each function to be traced must be specified explicitly using the TRACE keyword followed by the name of the function, as described in Configuration of Selected Functions

TRIGGER

This keyword limits tracing to those functions called directly or indirectly by the specified functions. Entry to the trigger function will enable tracing and the corresponding exit will disable profiling. This is similar to the behavior of nested probes (see Nesting Of Probes).

Note that TRIGGER does imply TRACE, so you needn't specify both.

REMOVE

The REMOVE keyword allows you to specify functions that should not be traced. This is useful when used in conjunction with a wildcard ("*"), to gather data about everything except certain routines. For example


TRACE "*" in "myModule"
REMOVE "Bad File.c" : "Bad_Function1" in "myModule"
REMOVE  "Bad File.c" : "Bad_Function2" in "myModule"

DoNotLoadShed

This keyword, followed by a function or method name specifies a function that should not be subject to load shedding regardless of how often it is called. See LoadSheddingThreshold.

LEVELS

If this special identifier is specified, it must be followed by an unsigned integer value. The default is DefaultLevels. It specifies the nesting level for which additional calls from the traced function will also be traced. A value of 0 means only the invocation of the function itself will be traced, but not any calls it makes. A value of 1 or more means that the invocation of the function itself will be traced, plus all other instrumented functions that it calls, either directly or indirectly, as long as the specified function is no deeper in the call stack than the specified value. (This used to be called MAX_DEPTH, which is still accepted but is deprecated.)

A non-zero LEVELS helps you to trace what the function was doing in addition to tracing the fact that it was called. For example, a value of 1 means that tracing will occur for the invocation of the function itself, plus, while still inside it, any other functions that it directly calls. A value of 2 means the same as a value of 1 except that we also trace 1 level deeper, thus including any further functions called directly from the other functions if they were called directly from the specified function.

The LEVELS has an effect only in a TRIGGER line, and is valid but simply ignored in a TRACE line. This is purely for convenience, to permit easy switching of the keyword at the beginning of the line without forcing changes to the rest of the line.

TRACE_LINES

This must be followed by TRUE or FALSE. If TRUE this TRIGGER or TRACE function will be instrumented for lines (if debug information is available for this routine) and the line trace will be displayed in the formatted data. Note that if the global LogLines option is set to FALSE (and -l is not specified on the command line), this value will be ignored.

PARAMETERS

This must be followed by TRUE or FALSE, and applies only to the special Java module name "$java$". If TRUE, all parameters of the matching Java method or methods will be logged.

Configuration of Trace Snapshots

SNAPSHOT

This keyword in the trace probe configuration file allows you to specify the name of some functions for which snapshots of the circular buffer's contents are to be automatically taken. Each SNAPSHOT line must specify a particular function in the usual manner, just as is done for a TRACE line. The remainder of the SNAPSHOT line contains pairs, where each pair has a special identifier keyword followed by its own associated value. These pairs give supplementary information about the snapshot.

ON

This optional special identifier must be followed by the value ENTRY or EXIT. These signify that the snapshot is to be taken on entry to the function, or upon exit from the function, respectively. The default is ON ENTRY.

IS

This optional special identifier must followed by an arbitrarily long string enclosed within "" quotation marks. It specifies a textual description or title that is to be logged along with the snapshot.

Enabling and Disabling Probes

ACTION

This keyword is used to introduce special actions on functions that were introduced to support RootCause. Note that these should not be used in conjunction with the TRIGGER and MAX_DEPTH keywords described above. The ACTION keyword is followed by a function name as for the TRACE keyword, or by one of the special names PROGRAM or THREAD. This is followed by a specification of where the action is to occur: ON ENTRY or ON EXIT. Last comes the action itself, which should be one of LOGGING ENABLE or LOGGING DISABLE. For example:

TracingEnabledInitially TRUE
TRACE "Pi::*" in "$java$" PARAMETERS TRUE
ACTION PROGRAM ON ENTRY LOGGING DISABLE
ACTION "Pi::calc_pi()" IN "$java$" ON ENTRY LOGGING ENABLE
ACTION "Pi::calc_pi()" IN "$java$" ON EXIT LOGGING DISABLE

Is roughly equivalent to

TracingEnabledInitially FALSE
TRACE "Pi::*" in "$java$" PARAMETERS TRUE
TRIGGER "Pi::calc_pi()" IN "$java$"

Trace Configuration GUI

The configuration GUI (Graphical User Interface) for trace.ual is the "Trace Probe Configuration" dialog. This dialog allows you to set the options that control the trace probe and is generally as described in Configuration GUI.

Note: If you have RootCause, you should use the RootCause Console GUI to develop your trace. This interface is deprecated, is not applicable to Java applications, and does not provide access to all configuration options.

The Help button provides the following description:

This dialog allows you to set the options that control the trace probe,and to override any options from either the configuration file or thecommand-line. The default settings for the options will come from theconfiguration file, if one exists.

'Trigger Functions' lists the functions whose invocation can be used to control tracing. If trigger functions are listed then tracing will occur when in functions are called directly or indirectly from the trigger function. If no trigger functions are present then every invocation of traced functions will be traced.

If one clicks on the 'Advanced selections' button, then thelists for 'Traced Functions' and 'Snapshot Functions appear.

'Traced Functions' lists the functions whose invocation you want to trace.

'Circular Buffer Snapshot Functions' lists the functions whose invocation will cause the contents of the circular buffer to be logged to an APD file. This list is ignored when not using the circular buffer.

'Log mechanism' indicates whether you want the trace data to be logged directly to an APD file on disk or to a circular buffer that resides in memory instead. A circular buffer is useful when you expect potentially large volumes of data, but you are interested in capturing only the most recently traced function invocations that preceded some event. A snapshot is usually taken soon after that event to transfer trace data from the circular buffer to an APD file for later analysis. Typically, this means that you are willing to set aside a finite storage buffer in which trace data will be temporarily logged, and you are willing to discard any older trace data that may get overwritten when the circular buffer fills up and wraps around.

'Number of circular buffer entries' governs the size of the circular buffer and therefore the amount of memory that will be set aside for it.

'Default depth of trigger tracing' is the nesting level of calls made from a trigger function that will be traced for triggers that don't specify such a value.

'Log time stamps' indicates whether the date and time of each function invocation will be logged along with the trace of its entry and exit.

'Log lines executed' indicates whether the line number of each source line that is executed within a traced subprogram will be logged.

'Trace enabled initially' indicates whether the logging of trace data will begin immediately upon target program startup or deferred until after function ap_EnableTracing is called from some other probe.

'Start configuration GUI' causes this graphical user interface to appear every time this UAL is about to begin probing the program, whether or not the -g option was specified on the UAL command line.

'Save As' button saves the current options to a configuration file.

'Run (no save)' button runs the target program using the selected options.

'Save & Run' button save the options to the configuration file, then runs the target program using the selected options.

'Abort' button will abort the target program instead.

Trace API

Users can control the behavior of the trace probe by calls from within their own probes. The API for the trace probe is defined by $APROBE/include/trace.h. Some of the functions exported by trace.ual are:

ap_Trace_GetOptions

Get current set of options controlling probe.

ap_Trace_GetDefaultOptions

Get the default options applicable if no configuration file is found.

ap_Trace_SetOptions

Set current set of options to control probe.

ap_Trace_SaveOptions

Save the options to the specified file.

ap_Trace_ClearBuffer

Deletes any circular buffer of logged trace data.

ap_Trace_DoSnapshot

Dumps circular buffer of trace data and resets. See Snapshots for more information and an example.

Trace Performance Issues

See Performance Issues for a general discussion of factors that affect performance.

The most important mechanism for controlling tracing overhead is load shedding. Unless you are tracing a small set of specific functions or methods, you should set LoadSheddingThreshold to 10. If you discover that functions you are interested in are being load-shed, then you can prevent that by specifying DoNotLoadShed for such functions.

The trace probe is applied to the functions specified in the configuration file, so the run-time overhead is directly proportional to the number of calls to the functions selected. Note that a probe is executed for every function included by a TRACE or TRIGGER line (and not subsequently REMOVEd).

Tracing of each line, by setting LogLines to TRUE in the configuration file or GUI, greatly increases the overhead of the trace probe. Furthermore, the overhead of line probes are not counted when computing load-shedding overhead. It is highly recommended that you use the circular buffer if logging lines, to limit the total amount of data collected.

As with profiling, functions are instrumented in an extended manner that allows traced functions to be executed with very little overhead if there are no currently active triggers. See Profile Performance Issues for more information on this.

Trace Report

The formatted output trace data will look similar to this sample:

 Switching to thread main 1
 
 [Enter : main
   [Enter : ofstream::ofstream(const char*,int,int)
   Leave] : ofstream::ofstream(const char*,int,int)
   [Enter : fstreambase::close()
   Leave] : fstreambase::close()
   [Enter : ofstream::open(const char*,int,int)
   Leave] : ofstream::open(const char*,int,int)
   [Enter : fstreambase::close()
   Leave] : fstreambase::close()
   [Enter : ofstream::~ofstream()
   Leave] : ofstream::~ofstream()
   [Enter : mystream::openlevel1()
     [Enter : mystream::openlevel2()
       [Enter : mystream::openlevel3()
 4:[Enter : mystream::openlevel4()
 5:  [Enter : mystream::openlevel5()
 6:    [Enter : mystream::openlevel6()
 7:[Enter : mystream::openlevel7()
 8:  [Enter : mystream::openlevel8()
 8:  Leave] : mystream::openlevel8()
 7:Leave] : mystream::openlevel7()
 6:    Leave] : mystream::openlevel6()
 5:  Leave] : mystream::openlevel5()
 4:Leave] : mystream::openlevel4()
       Leave] : mystream::openlevel3()
     Leave] : mystream::openlevel2()
   Leave] : mystream::openlevel1()
 Leave] : main
 [Enter : exit
   [Enter : __C_runtime_termination
   Leave] : __C_runtime_termination
 

Example D-11. Trace Report