Events Predefined Probe

From OC Systems Wiki!
Jump to: navigation, search

Performance Probe: events.ual

'The events.ual' predefined probe records the start and end times of program functions and user-defined "events", organizes them by call tree, and provides several reports which help to analyze the performance of an application. This probe supports Java as well as native programs.

An event can be any particular operation that the application performs that it makes sense for the application to report. An instance of an event should have a specific start and end point somewhere within the application. For instance, we might recognize that we have an "incoming missile" message and start the IncomingMissile event. At the point at which we display this to the user we can record the end point for the IncomingMissile.

All events are logged as they occur. At format time, the events can be analyzed in a summary or detailed format.

You can find an example in the directory $APROBE/examples/predefined_probes/events/.

Usage

This probe is applied at run time using aprobe as described under Events UAL Parameters. The data to be collected is defined by a configuration file specific to the application being probed. See Configuration File. This configuration file is constructed by the user with a text editor starting with a template defined in $APROBE/probes/event.cfg.

Events UAL Parameters

events.ual is specified on the aprobe command line or in an APO file, and with apformat, as described in Command Line. The specific options are:


aprobe   -u events.ual     [-p "[-h] [-v] [-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.events.cfg. For example, if your executable program is called wilbur.exe, then the default file name would be wilbur.exe.events.cfg.
-h
produces brief help text.
-v
verbose mode, which produces additional progress messages.

Note that the -c argument is stored by this probe, so you don't need any other arguments, you don't need specify the UAL and configuration file with apformat.

Events UAL Configuration File

The Events configuration file specifies everything about the behavior of the Events performance probe. Without explicitly defining the events in the configuration file, the probe will do nothing. The configuration file is responsible for defining the events (runtime options) as well as several format time options.

By default the events probe will be looking for base_exe_name.events.cfg file in the current directory. You can override this location by passing it as a parameter to events probe. For example:


aprobe -u events -p "-c ./my_events.cfg" prog.exe

When formatting the data with apformat command, the configuration file will be expected to remain in the same location where it was found when the data was collected. Again, you can override this location by passing it as a parameter to the events probe:


apformat -u events -p "-c ./my_events.cfg" a.apd

The example below shows one possible Events configuration file.


PROBE CONFIGURATION FILE FOR EVENTS VERSION 1.1.0

CorrectCpuTime    FALSE
DisplayReport     TotalReport
PrintHeaders      TRUE
EventNameLength   30
SaveReportsToFile FALSE
SummarizeWallTime FALSE

EVENT FUNCTION foo*
EVENT FUNCTION * in "libc.so"
EVENT FUNCTION com.sun.java.* in $java$
EVENT START ProcessMessage MessageGet() ON EXIT
EVENT STOP  ProcessMessage MessageGet() ON ENTRY

Example D-4. events.cfg File

Run Time Configuration Options

The events.cfg file defines the behavior of the Events probe both when the program is running and when the collected data is formatted. This section defines the run-time EVENT directive and related options.

Events

Events can be either LEAF or NON-LEAF events. LEAF events are those that signify one point in time and can not have any other events nested underneath them. NON-LEAF events, on the other hand, are comprised of a START and STOP event pair. They signify a time interval or a PROCESS. There is a special kind of NON-LEAF events that we call MESSAGES. Just like PROCESSES these events also have duration, but they can not be properly nested inside of other events or have other events nested underneath them. They also don't have to originate and stop in the same thread (though this is not precluded). The MESSAGE events are signified by SEND and RECV points. The syntax of an event specification formally defined as follows:

 event ::= EVENT event_details
 event_details ::= 
   event_name function_name
   | LEAF ''event_name function_name'' [ON ENTRY | ON EXIT]
   | START ''event_name function_name'' [ON ENTRY | ON EXIT]
   | STOP ''event_name function_name'' [ON ENTRY | ON EXIT]
   | SEND ''event_name function_name'' [ON ENTRY | ON EXIT]
   | RECV ''event_name function_name'' [ON ENTRY | ON EXIT]
   | FUNCTION ''function_name"
 

START signifies the starting point of a NON-LEAF event pair; STOP signifies the ending point of a NON-LEAF event pair

When none of LEAF, START, STOP or FUNCTION are specified the event is assumed to signify both the starting and ending points.

FUNCTION Events

FUNCTION events will have their function name be used also as their event name. FUNCTION events are the simplest and quickest events one may define. They allow the use of wildcards, which helps one to setup the initial configuration in minutes. For example:

 EVENT FUNCTION foo*
 EVENT FUNCTION * in "libc.so"
 EVENT FUNCTION com.sun.java.* in $java$
 

Function events may be easy to define, but a bit harder to refer to by name, e.g.
from a FOCUS or IGNORE directive. This is because you have to refer to function events using the full function/method name known to Aprobe. For example,

 extern:foo(), or "my_file.c":"local_function()".
 

Examples of Events

EVENT START ProcessMessage MessageGet() ON EXIT
EVENT STOP  ProcessMessage MessageGet() ON ENTRY

In the example above we defined one event: ProcessMessage. This non-leaf event starts when we get a message (on exit from MessageGet()) and stops when we come back for more messages (on entry to MessageGet()). Notice that the above definition will result in the first STOP ProcessMessage event occur before the first START ProcessMessage. While this probe will produce a warning and recover in such a situation it may be better to avoid it. We can do that by adding another START and STOP points pair for ProcessMessage event on on entry/exit to/from main(). These two event points could be added in one statement: EVENT ProcessMessage main().

Some events may be best described by their function name. The keyword FUNCTION would tell this probe that it should use the function name as the name of the event:


EVENT FUNCTION extern:"MyFunctionEvent()"

Leaf events are a good way to record an occurrence of a "point in time" event:


EVENT LEAF  Error#10 extern:"ReportFileNotFoundError()"
EVENT SEND SendMessage "MyClass::SendMsg*" in "$java$" ON ENTRY
EVENT RECV  ReceiveMessage "MyClass::GetMsg*"  in "$java$" ON EXIT

Hook Events

Some event points may be hard to define with configuration file alone. To help you identify such events you may build the event points into your application, by using hook functions. For example, your application may make the following call before processing an event:


hook_start2(99, Event->EventId);
Event->Process();
hook_stop2(99, Event->EventId);

Events identified by the calls to the hooks library are automatically recorded by the events probe. The parameters passed to the hook function will be recorded together with the event and will be used for the event identification. For example, if the EventId == 10in the example above, the event will name "Hook.99.10" will be recorded. You can use "Define" directive to assign a more meaningful name to this event. The complete list of the hooks routines may found in hooks.h.

Time measurement

We take a sample time at each user defined event. Two types of time stamps are recorded: WALL time and CPU time. Wall time will only appear in the detailed report, all statistics such as total/min/max/avg times are based on CPU times. CPU time measurement may be corrected for the overhead of time sampling itself. This is controlled by CorrectCpuTime flag, which is set to FALSE by default. Change this to CorrectCpuTime=TRUE if do wish to have CPU time corrected. Warning: this may result in negative deltas reported for very short events.

Formatting Options

Formatting options in the configuration file don't affect what data is collected. They only affect they way the data is presented when apformat is run. Therefore you can change these options and get a different report of your data without rerunning your application.

DisplayReport Option

The DisplayReport option will tell the formatter whether you would like to see data in detailed or summary formats.

DetailedReport

will contain information from each individual event.

SubtotaReport

summary report will contain information summarized from the detailed events since the last summary. One "Subtotal" report will be generated for each top level event.

TotalReport

will contain the summary of the data collected for the whole run. This is the initial value in the configuration file.

DEFINE

One may change the way the event name is presented in the report, without having to rerun the application, using the DEFINE directive followed by the event name and the desired representation.

For example:


DEFINE Event#256 "Process Radar Data"
DEFINE Hook.999 "Move Troops"
DEFINE "ThisIsAVeryVeryVeryLooooooooooooooooooongFunctionName()" BetterName

Note that the new name is for report purposes only and the original event name must still be used to identify the event, e.g. to FOCUS or IGNORE. For function events, the name you have to use is the full function name. If you would like to use a more readable name for your event you can define it together with your event.

Hook events have to be referred to by the name generated for them using one of the following formats:


Hook.HookParam1 Hook.HookParam1.HookParam2

FOCUS

"The FOCUS directive followed by an event name will allow you to limit the reporting to the events that have a focus set on them and those events that are nested underneath them. When no FOCUS directive is used all events are assumed to be "in focus". For example, if your events.cfg file contained only one FOCUS event:


FOCUS Hook.999

You would see only information about events which occurred between start and stop of Hook.999 event.

IGNORE

Once you collected the data you may find that you would like to filter out some of the events either because they are not properly defined (e.g. START doesn't match STOP) or, perhaps, because they add too much clutter to the report. You can filter such events out by using "Ignore" directive followed by the event name. For example, specifying

IGNORE Hook.999

would eliminate the appearance of this event in the output. Note that this does not eliminate events "under" (occurring during) the ignored event.

Runtime modifier

One may precede FOCUS and IGNORE directives with a modifier "Runtime" to make sure that no data is collected at run time for those events that would be filtered out by these directives at format time. For example.

Runtime IGNORE Hook.999

Would record the minimum amount of data for the Hook.999 event. Since other events may depend upon this one, it is not necessarily the same as commenting out the original event definition.

PrintHeaders

The PrintHeaders flag controls whether report headers will be printed out. The default is TRUE.

EventNameLength

EventNameLength specifies the length to which FUNCTION event's names will be abbreviated in the report. The default is 30.

SummarizeWallTime

Setting SummarizeWallTime=TRUE results in total and subtotal reports summarizing the Wall Clock Time, instead of Cpu Time. The default is FALSE.

Report File Options

SaveReportsToFile

When set to TRUE, this causes the results to be written to files named according to their contents. The default is FALSE, wherein the reports are be written out to standard output.

ReportsDirectory

The ReportsDirectory option specifies the location of where the report files should be created. By default, they are created in the directory containing the APD files.

ReportsBaseNamePrefix

This option specifies the prefix used to generate report files' base names. The default name is:

TimeStampOnProgramEntry.pid=PID.BaseApdName

For example:

2002-10-10@15:33.pid=11286.hello

You can override the value of ReportsBaseNamePrefix specified in the configuration file with -b format-time option. For example:

 apformat -u events -p "-b node10" hello.apd

Reports

There are three output formats specified using the DisplayReport Option: DetailedReport, SubtotalReport, and TotalReport. The Detailed report shows every event. The Subtotal and Summary reports merge all events with the same traceback. As generated, all reports are about 160 characters wide, and include all columns to facilitate automatic postprocessing. These columns are, in order:

  1. Thread Id
  2. Nesting Level - This is the event's nesting level within a given thread relative to other events.
  3. Event type
    • " " - StartEvent
    • "-" - StopEvent
    • " " - LeafEvent
    • "X" - Placeholder StopEvent created for unmatched StartEvent (error condition)
  4. Event Name - This is a short form of the name. The width of this column is determined by the EventNameLength variable, which defaults to 30.

Fields 5-9 are filled in only for the DetailedReport.

  1. Event Sequence Id - Unique Id assigned to each instance of an event (DetailedReport only).
  2. Parent Event Sequence Id - Sequence Id of the parent event or 00000 if the event is not nested.
  3. Event Wall Time - the time at which the event occurred.
  4. Delta Wall Time - Wall time in microseconds since the matching start event This field is only filled for Stop events in the DetailedReport.
  5. Delta CPU Time - CPU time in microseconds since the matching start event. This field is only filled for Stop events in the DetailedReport.

Fields 10-14 are only filled in for summary reports (SubtotalReport and TotalReport).

  1. Call Count - the number of times the given event took place.
  2. Total CPU Time - the sum of the CPU time taking by all instances of this event.
  3. Minimum CPU Time - the longest time any instance of this event took.
  4. Maximum CPU Time - the short time any instance of this event took.
  5. Average CPU Time - the average time of all instances of this event.
  6. Last Label - This field will contain the last value of the label recorded by a call to hook_label1(). See Hook Events.

Additional fields (16 and onward) may contain user data.

In the examples that follow, blank columns have been deleted so they fit on a page. You can do this yourself using the cut command, for example:

apformat events_example | cut -d'|' -f1-4,10-14 > summary.out

Detailed Report

The detailed report simply contains all the recorded events in their chronological order. A small subset of the table is shown below, with columns 10-15 not shown.

 
 --|--|-|---------------|-----|-----|---------------|-----------|-----------|-...
 Th|Ns|N|          Event|Event| Prnt|          Event|      Delta|      Delta|
 Id|Lv|N|          Name |SeqId|SeqId|      Wall Time|   Wall(us)|   CpuT(us)|
 --|--|-|---------------|-----|-----|hh:mm:ss.mmmuuu|sssssmmmuuu|sssssmmmuuu|-...
  0| 0| |         main()|00002|00000|16:58:03.190531|           |           |
  0| 1| |     BubbleSort|0001e|00002|16:58:03.206741|           |           |
  0| 1|-|     BubbleSort|0001e|00002|16:58:04.413698|    1206957|     730000| ...
  0| 1| |             QS|002bx|00002|16:58:04.424019|           |           |
  0| 1|-|             QS|002bx|00002|16:58:04.530950|     106931|      60000|
 

Example D-5. Detailed Events Report

Summary Reports

The TotalReport and SubTotalReport options contain similar output -- identical in-fact if there is only one thread and hence one call tree. Below is a subset of the TotalReport corresponding to the Detailed report above. Note that again the blank fields (5-9) are not shown here but will exist in your output.

 --|--|-|---------------|-----|-----------|-----------|-----------|-------|
 Th|Ns|N|          Event|     |       Min |       Max |       Avg |   Last|
 Id|Lv|N|          Name | ... |   CpuT(us)|   CpuT(us)|   CpuT(us)|  Label|
 --|--|-|---------------|-----|sssssmmmuuu|sssssmmmuuu|sssssmmmuuu|-------|
  S| 0| |THREAD # 26672 |     |    7820000|    7820000|    7820000|       |
  S| 1| |         main()| ... |    7820000|    7820000|    7820000|       |
  S| 2| |     BubbleSort|     |     600000|     890000|     717000|       |
  S| 2| |             QS|     |      10000|      90000|      51000|       |
 

Example D-6. Total Events Report