Difference between revisions of "Trace Predefined Probe"

From OC Systems Wiki!
Jump to: navigation, search
(Created page with " === Command Line === In the on-line "<code>4.predefined</code>" example, a command line like the following is used: aprobe -u trace.ual -p "-g -v" main The <code>trace....")
 
m
Line 1: Line 1:
 +
== Trace Probe: trace.ual ==
  
−
=== Command Line ===
+
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.
  
−
In the on-line "<code>4.predefined</code>" example, a command line like the following is used:
+
'''Note'''<nowiki>: if you're using Aprobe as part of OC Systems' </nowiki>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 [aprobe-9.html#MARKER-9-1035 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 [#MARKER-9-1970 "Snapshots"].
 +
 
 +
=== Usage ===
 +
 
 +
This probe is applied at run time using [aprobe-9.html#MARKER-9-1075 aprobe] as described under [#MARKER-9-2124 "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 [#MARKER-9-1955 "Configuration File"] and [#MARKER-9-1961 "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 [aprobe-10.html#MARKER-9-1325 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-9.html#MARKER-9-1075 aprobe] command line or in an [aprobe-10.html#MARKER-9-1332 APO file] as described in [#MARKER-9-1941 "Command Line"]. The specific options are:
  
 
   
 
   
−
  aprobe -u trace.ual -p "-g -v" main
+
  aprobe -u '''trace.ual '''    [-p "[-h] [-v] [-g] [-t] [-l] [-c config_filename]"]
 +
    your_program
  
−
The <code>trace.ual</code> file is actually located in the directory <code>$APROBE/ual_lib</code>, but this directory searched by default for any UAL not found in the current working directory, so you only need to provide the base name of the UAL file.
+
where:
  
−
The '''-p''' option which follows <code>trace.ual</code> indicates that the next argument is a string of options to be passed to the UAL. In this case, those options are '''-g''', which indicates that the Java Graphical User Interface (GUI) is to be started; and '''-v''', which causes "verbose" informative output to be generated by the probe. Every predefined probe accepts the option '''-h''', which describes the full set of command-line options available to that probe. So, to display the full set of options for <code>trace.ual</code>, execute:
+
; '''-c ''config_filename'''''
 +
: <br />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 [#MARKER-9-2149 "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 [#MARKER-9-1955 "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$"
 
   
 
   
−
aprobe -u trace.ual -p -h main
 
  
−
Predefined probes are generally initiated by invoking [aprobe-9.html#MARKER-9-1075 aprobe] explicitly. However, they may also be invoked implicitly by linking your application with <code>libdal.so</code> or using the <code>run_with_aprobe_apo</code> script and specifying the command-line options in a <code>.apo</code> file as described in [aprobe-7.html#MARKER-9-868 Chapter 4, "Loading Probes Without aprobe"].
+
==== Example D-10. trace.cfg File ====
  
−
=== Configuration File ===
+
==== Configuration Variables ====
  
−
The ''configuration file'' is used to designate which functions in the target application are to be analyzed, and to specify other options. The easiest way to get an initial configuration file is simply to invoke the predefined probe with no options. You'll get a warning about not finding a configuration file, but one will be created.
+
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.
  
−
You can use the [#MARKER-9-1961 Configuration GUI] to create or change the configuration file by specifying the '''-g''' option. This provides a point-and-click interface in which to choose your functions and other options and save them in a configuration file. (Note that this GUI can be quite slow for very large applications, so editing the file directly may be more practical in such cases.)
+
==== LogLines ====
  
−
The default name for the probe configuration file is ''your_program'''.probe_name.cfg''''', where ''your_program'' stands for the name of your executable application program, and ''probe_name<code> </code>''is the basename of the predefined probe, e.g., <code>trace</code>. For example, if your program is called wilbur.exe and you're using trace.ual, then the default configuration file name would be wilbur.exe.trace.cfg.
+
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..
  
−
The format of the a probe configuration file is:
+
==== 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: <code>Java class loaded: "Pi"</code>.
 +
 
 +
==== 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 [#MARKER-9-1958 "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 [aprobe-6.html#MARKER-9-574 "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
  
 
   
 
   
−
  PROBE CONFIGURATION FILE FOR ''probe_name'' VERSION 2.0.0
+
  TRACE "*" in "myModule"
−
  ''keyword'' ''data''
+
REMOVE "Bad File.c" : "Bad_Function1" in "myModule"
−
  ...
+
  REMOVE "Bad File.c" : "Bad_Function2" in "myModule"
−
''keyword'' ''data''
+
 
−
// This is a comment line
+
==== 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 [#MARKER-9-2134 "LoadSheddingThreshold"].
 +
 
 +
==== '''LEVELS''' ====
  
−
A warning will be given if the very first line of this file isn't valid, but an attempt will be made to use the information provided. The only allowed variations on this header line are the number of blank spaces between the words, and the case of each character.
+
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.)
  
−
All keywords in the configuration file are case-insensitive. However, all function or module names are always case-sensitive.
+
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.
  
−
Each line begins with a keyword, or is a continuation line. A line is a continuation line if the previous line ends in a backslash ("\"). The continuation character is treated as a word separator, like a blank.
+
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.
  
−
Comment lines can be interspersed with any other lines. Comment lines are those lines whose first 2 non-blank characters are "//". Comment lines are ignored by probe and are intended only for the benefit of the human reader.
+
==== TRACE_LINES ====
  
−
Any invalid line is ignored. An invalid line is one which contains an invalid keyword or value, or has a missing or extraneous word.
+
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.
  
−
==== Configuration of Selected Functions ====
+
==== PARAMETERS ====
  
−
The '''coverage''', '''profile''', and '''trace''' predefined probes operate by probing functions in the user's application, so the names of those functions must be specified in the configuration file. While each predefined probe uses different keywords to designate which functions to probe, the syntax of the function name itself is the same in all cases. It is exactly the same as the syntax used for a probe itself, as described in [aprobe-6.html#MARKER-9-497 "Specifying Function Names"] and repeated here:
+
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:
  
 
   
 
   
−
  [ [''file_name ''<nowiki>| </nowiki>'''extern''']'' '''<nowiki>:</nowiki>''''' ] ''function_name'' [ '''in''' ''module_name'' ]
+
  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
 +
  
−
''file_name, function_name'', and ''module_name ''are all strings that are bounded by quotation marks (that is, ""), which allows each name to contain embedded blank space characters. The ''file_name'' and the ''module_name'' are optional. If ''module_name'' is omitted, the application module is assumed, and the special character "*" can be used to designated every module. The ''file_name'' is required only for static (file-local) functions. A colon must exist between the ''file_name'' and the ''function_name''. The colon may be surrounded by optional whitespace, and the keyword IN must always be surrounded by whitespace. Examples are:
+
Is roughly equivalent to
  
 
   
 
   
−
  "my_file"'''<nowiki>:</nowiki>'''"my_function"
+
  TracingEnabledInitially FALSE
−
extern:"malloc()" in "libc.so"
+
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 [#MARKER-9-1961 "Configuration GUI"].
 +
 
 +
'''Note'''<nowiki>: 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.</nowiki>
 +
 
 +
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.
  
−
In the configuration file for <code>trace.ual</code>, the keyword indicating that a function is to be traced is "Trace", where the cases of the letters is not significant. In the <code>main.trace.cfg</code> file, then should appear one or more lines that look like
+
'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.
−
Trace "my_file":"my_function"
+
 
 +
'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 &amp; 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 [../include/trace.h <code>$APROBE/include/trace.h</code>]. Some of the functions exported by <code>trace</code>.ual are:
 +
 
 +
==== ap_Trace_GetOptions ====
 +
 
 +
Get current set of options controlling probe.
  
−
Predefined probes may have other keywords, such as '''Trigger''', '''Remove''' and '''Snapshot''', which are followed by function names. These are described in their corresponding section below. And, note that '''memwatch.ual''' does ''not'' require specifying application functions this way -- see [#MARKER-9-2173 "Memory Watch Probe: memwatch.ual"].
+
==== ap_Trace_GetDefaultOptions ====
  
−
=== Configuration GUI ===
+
Get the default options applicable if no configuration file is found.
  
−
Some, but not all, predefined probes offer a Configuration GUI (Graphical User Interface). The '''coverage''', '''profile''', and '''trace''' predefined probes do offer it, but not '''events''', memwatch, nor info
+
==== ap_Trace_SetOptions ====
  
−
If the '''-g''' option is specified to the UAL, the probe starts a Java process to run the Configuration GUI. This provides a point-and-click interface for selecting functions and setting other options which are recorded in the ''[#MARKER-9-1955 Configuration File]''. This interface differs for each probe, but generally consists of several panes in which functions and option settings are selected. At the bottom are Save &amp; Run , Run, Save As, Abort, and Help buttons. Run proceeds with the execution of the program under aprobe with the current configuration; Save updates the configuration file on disk with the current settings; Abort quits the GUI and aborts the aprobe and target application processes; and Help brings up a dialog describing each pane and the other buttons.
+
Set current set of options to control probe.
  
−
==== Function Selection Interface ====
+
==== ap_Trace_SaveOptions ====
  
−
The Configuration GUI can be useful for selecting the functions that are to be operated upon by the probe. The "4.predefined" example illustrates this for the trace probe, and this process generally applies to the other probes as well:
+
Save the options to the specified file.
  
−
Click on the ''"Pick..''." button under the top pane (for Trace, the top pane is labeled as "''Traced Functions")''. You'll be presented with a list of modules (the executable plus any shared libraries it loads). When you double-click on one of those, it will be replaced with a dialog that lists all the functions in that module. Those on the left have been selected, those on the right have not. Double-clicking on a function name moves it to the other column. When the functions you want to probe from the selected module are listed on the left, click ''Ok'', and list in the configuration gui itself will be updated.
+
==== ap_Trace_ClearBuffer ====
  
−
Note: this process can be very slow for large applications with many thousands of symbols (see [#MARKER-9-1931 "Performance Issues"]). In such cases it may be easier to use [aprobe-9.html#MARKER-9-1016 apcgen] or [aprobe-9.html#MARKER-9-1052 apinfo] to generate symbol lists, and edit those lists by preceding them with the keyword. For example:
+
; '''Deletes any circular buffer of logged trace data.'''
 +
:
  
−
+
==== ap_Trace_DoSnapshot ====
−
apsymbols main | sed "s/^/Trace / " &gt;&gt; main.trace.cfg
 
  
−
Note that for <code>memwatch.ual</code>, selecting individual functions isn't necessary. Instead the MemWatch probe displays graphs at run time showing memory usage patterns, and allowing interactive snapshots.
+
Dumps circular buffer of trace data and resets. See [#MARKER-9-1970 "Snapshots"] for more information and an example.
  
−
=== Callable API ===
+
=== Trace Performance Issues ===
  
−
You can invoke functions defined by a predefined probe from within your own probes. The interface is defined by the header file in the [../include/ <code>$APROBE/include</code>] directory whose name corresponds to the predefined probe; for example, <code>trace.h</code> is the interface for <code>trace.ual</code>.
+
See [#MARKER-9-1931 "Performance Issues"] for a general discussion of factors that affect performance.
  
−
The most useful functions are generally at the end of the file: those which enable and disable the probes, and those which log a "snapshot" of the data currently selected. See the comments in each file for details.
+
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 [#MARKER-9-2134 LoadSheddingThreshold] to 10. If you discover that functions you are interested in are being load-shed, then you can prevent that by specifying <br />[#MARKER-9-2144 DoNotLoadShed] for such functions.
  
−
Note that there is no <code>info.h</code> file -- its operation is entirely determined by its command-line parameters; and the <code>quick_gui.h</code> file is the ''only'' interface to <code>quick_gui.ual</code>, since it defines no probes.
+
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).
  
−
=== Snapshots ===
+
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.
  
−
Trace, profile, coverage, statprof and memwatch all provide the ability to take a "snapshot" of the data at a point during a program's execution. A snapshot is simply a dump of the data collected in memory since the start of execution or the previous snapshot. The coverage, memwatch, and trace probes support the keyword SNAPSHOT in the configuration file, with which a function name is specified. For example, in your <code>main.trace.cfg</code> file you would do:
+
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 [#MARKER-9-2099 "Profile Performance Issues"] for more information on this.
  
−
+
=== Trace Report ===
−
Snapshot extern:"LOCAL_PROC()" On Exit
 
  
−
This is translated into a probe which calls a function to take the snapshot. You can include this in your own probe--call it <code>mytrace.apc</code>--as follows:
+
The formatted output trace data will look similar to this sample:
  
−
<nowiki>
 
−
#include "trace.h"
 
−
probe thread {
 
−
  probe extern:"LOCAL_PROC()" {
 
−
    on_exit
 
−
      ap_Trace_DoSnapshot("after LOCAL_PROC");
 
−
  }
 
−
}
 
−
Then, compile this probe, using </nowiki><code>trace</code>.ual as a library:
 
−
 
−
apc mytrace.apc trace.ual -o mytrace.ual
 
 
   
 
   
−
  and then use  <code>mytrace</code>.ual instead of <code>trace</code>.ual to gather data:
+
  Switching to thread main 1
 
   
 
   
−
  aprobe -u mytrace.ual main
+
  [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-1. Calling ap_Trace_DoSnapshot() ====
+
==== Example D-11. Trace Report ====

Revision as of 20:27, 5 May 2017

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 [aprobe-9.html#MARKER-9-1035 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 [#MARKER-9-1970 "Snapshots"].

Usage

This probe is applied at run time using [aprobe-9.html#MARKER-9-1075 aprobe] as described under [#MARKER-9-2124 "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 [#MARKER-9-1955 "Configuration File"] and [#MARKER-9-1961 "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 [aprobe-10.html#MARKER-9-1325 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-9.html#MARKER-9-1075 aprobe] command line or in an [aprobe-10.html#MARKER-9-1332 APO file] as described in [#MARKER-9-1941 "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 [#MARKER-9-2149 "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 [#MARKER-9-1955 "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 [#MARKER-9-1958 "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 [aprobe-6.html#MARKER-9-574 "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 [#MARKER-9-2134 "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 [#MARKER-9-1961 "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 [../include/trace.h $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 [#MARKER-9-1970 "Snapshots"] for more information and an example.

Trace Performance Issues

See [#MARKER-9-1931 "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 [#MARKER-9-2134 LoadSheddingThreshold] to 10. If you discover that functions you are interested in are being load-shed, then you can prevent that by specifying
[#MARKER-9-2144 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 [#MARKER-9-2099 "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

Retrieved from "https://www.ocsystems.com/w/index.php?title=Trace_Predefined_Probe&oldid=127"