Tracing

Tracing a (portion of a) Cmajor program consists of the following phases:

  1. Insert RtBeginTracing and RtEndTracing function calls to the program being traced.
  2. Compile the system library and the program using the trace configuration option.
  3. Run the program compiled with the trace configuration.
  4. Convert the trace.bin binary trace file that is generated to the Cmajor trace subdirectory to a text file using the cmtrace2txt utility.
  5. Inspect the trace text file.

Starting and stopping tracing

Tracing begins when the program being traced issues the RtBeginTracing function call and ends when the program issues the RtEndTracing function call. When the tracing ends the RtEndTracing function writes a binary trace.bin file to the trace subdirectory of the Cmajor installation directory.

Compiling the system library and the program using the trace configuration option.

To instrument the system library for tracing, compile it using the trace configration option: 

			C:\cmajor\system\platform\windows> cmc -u -v -c=trace System.cms

To instrument the program being traced, for example program.cmp, compile it using the trace configuration option: 

			cmc -u -v -c=trace program.cmp

These two commands generate a text file trace.tab to the trace subdirectory of the Cmajor installation directory. The trace.tab contains one line for each function contained by the system library and the program. The line consists of an integer identifier for the function, a colon, and the full name of the function.

When the system library and the program is compiled with the trace configration, each function in the system library and the program begin traced is instrumented by function calls RtBeginTraceFunction and RtEndTraceFunction that generate a trace entry to the trace.bin file.

Each trace entry (14 bytes) consists of

  1. The type of the entry: begin=0 or end=1 (1 byte).
  2. A thread identifier character set by the program using RtSetThreadId function call, or '0' if the thread identifier is not explicitly set (1 byte).
  3. A function identifier integer of the function (4 bytes).
  4. A timestamp containing nanoseconds elapsed since the RtBeginTracing function call (8 bytes).

Running the instrumented program.

When the instrumented program is run, the RtEndTracing function generates a binary trace.bin file to the trace subdirectory of the Cmajor installation directory that contains the trace information.

Converting the trace.bin file to a text file.

Run the following command: 

			C:\cmajor\trace> cmtrace2txt -v trace.bin
The command converts the trace.bin to trace.txt.

Inspecting trace.txt.

The trace looks like the following: 

00:00:01.936.268.100 M  >System.Windows.Control.ProcessMessageInternal(Message&)
00:00:01.936.268.500 M   >System.Windows.Window.ProcessMessage(Message&)
00:00:01.936.268.700 M    >System.Windows.ContainerControl.ProcessMessage(Message&)
00:00:01.936.269.100 M     >System.Windows.Control.ProcessMessage(Message&)
00:00:01.936.269.400 M      >System.Windows.Control.DoTimer(uint)
00:00:01.936.269.700 M       >System.Windows.TimerEventArgs.TimerEventArgs(uint)
00:00:01.936.269.700 M       <System.Windows.TimerEventArgs.TimerEventArgs(uint) duration=00:00:00.000.000.000
00:00:01.936.270.000 M       >cmcode.MainWindow.OnTimer(TimerEventArgs&)
00:00:01.936.270.400 M        >cmcode.MainConfiguration.Instance()
00:00:01.936.270.700 M         >UniquePtr<cmcode.MainConfiguration>.operator*()
00:00:01.936.270.700 M         <UniquePtr<cmcode.MainConfiguration>.operator*() duration=00:00:00.000.000.000
00:00:01.936.270.800 M        <cmcode.MainConfiguration.Instance() duration=00:00:00.000.000.400
00:00:01.936.270.900 M        >cmcode.MainConfiguration.Save(bool)
00:00:01.936.271.100 M        <cmcode.MainConfiguration.Save(bool) duration=00:00:00.000.000.200
00:00:01.936.271.200 M       <cmcode.MainWindow.OnTimer(TimerEventArgs&) duration=00:00:00.000.001.200
00:00:01.936.271.200 M      <System.Windows.Control.DoTimer(uint) duration=00:00:00.000.001.800
00:00:01.936.271.500 M     <System.Windows.Control.ProcessMessage(Message&) duration=00:00:00.000.002.400
00:00:01.936.271.600 M    <System.Windows.ContainerControl.ProcessMessage(Message&) duration=00:00:00.000.002.900
00:00:01.936.271.700 M   <System.Windows.Window.ProcessMessage(Message&) duration=00:00:00.000.003.200
00:00:01.936.271.800 M  <System.Windows.Control.ProcessMessageInternal(Message&) duration=00:00:00.000.003.700
00:00:01.936.271.900 M  >System.Windows.Debug.Messages()
00:00:01.936.271.900 M  <System.Windows.Debug.Messages() duration=00:00:00.000.000.000
00:00:01.936.272.100 M <System.Windows.Application.ProcessMessage(void*, uint, uint, long, long&, void*&) duration=00:00:00.000.011.700

Each trace line consists of the following fields:

  1. Timestamp that shows hours, minutes, seconds, milliseconds, microseconds and nanoseconds elapsed since the RtBeginTracing function call.
  2. Thread identifier character (here 'M' for the main thread). The thread identifier can be set by calling the RtSetThreadId function from the program being traced.
  3. Space characters show the nesting level of the function being traced.
  4. '>' character for the start of the function trace entry and '<' character for the end of the function trace entry.
  5. The full name of the function being traced.
  6. If the entry is an end function entry, the duration field shows the duration of the function call.

Usage

Usage: cmtrace2txt [options] trace.bin

Convert trace.bin to trace.txt.

Options:

Long option Short option Description
--help -h Print help and exit.
--verbose -v Be verbose.
--filter="EXPR" -f="EXPR" Filter the trace using given filter expression.

Filter expressions

Trace entries can be filtered using filter expressions. Only trace entries matching the filter expression will be included in the converted trace.

Syntax

filter‑expression → and‑expr (or and‑expr)*
and‑expr → boolean‑expr (and boolean‑expr)*
boolean‑expr → match‑expr | relational‑expr
match‑expr → primary‑expr match primary‑expr
relational‑expr → primary‑expr (rel‑op primary‑expr)*
rel‑op → == | <> | <= | >= | < | >
primary‑expr → name | thread | duration | time | level | message | parent | true | false | pattern | string | integer unit? | ( filter‑expression )
pattern → ' pattern‑expression '
string → " [^"]* "
integer → [0-9][0-9']*
unit → ns | us | ms | s
pattern‑expression → alternative
alternative → catenation (| catenation)*
catenation → repetition repetition*
repetition → * | ? | primary
primary → ( alternative ) | class | char
class → [ ^? range* ]
range → char (- char)?
char → 'a character or an escape'

Components of filter expressions

A filter expression is a sequence of boolean‑exprs combined with and and or operators. The precedence of and is greater than the precedence of or.

Boolean expressions

A boolean‑expr is either a match‑expr or a relational‑expr

Match expressions

A match‑expr is a primary‑expr combined with a pattern using a match operator.

A pattern consists of character classes, characters that are not operator characters and wild cards * and ?.

Wild card * matches any string of characters including an empty string. Wild card ? matches any single character.

A character class begins with a left bracket and is followed by an optional inverse operator ^ followed by any number of character ranges followed by a right bracket. The inverse operator means "any but the following ranges".

A character range is a ordinary character or an escape optionally followed by a dash character and another ordinary character or an escape. It denotes a range of ordinary characters.

An escape begins with the backslash and is similar to an escape sequence in the C programming language.

Relational expressions

A relational expression is a primary expresssion optionally followed by a sequence of relational operators and primary expressions.

A relational operator is:

Primary expressions

A primary‑expr selects a field from a trace entry, is a pattern, a string, an integer, or a parenthesized filter expression.

name

The name keyword selects the function name field from a trace entry.

thread

The thread keyword selects the thread name field from a trace entry.

duration

The duration keyword selects the duration field from a trace entry.

time

The time keyword selects the time field from a trace entry.

level

The level keyword selects the level of the trace entry. Level is an integer.

message

The message keyword selects Windows message name from a trace entry.

parent

The parent keyword evaluates to true if parent trace entry is selected, otherwise it evaluates to false.

Integers

A primary expression can be an unsigned integer optionally followed by a time unit.

When the left side of a relational expression is either a duration or time, the right side can be an unsigned integer followed by a time unit. The time unit can be:

If a time unit is absent the time is assumed to be in nanoseconds.

Examples 

  1. 			cmtrace2txt -v --filter="duration>=10ms" trace.bin

    Selects only those function trace entries whose duration is equal to or greater than 10 milliseconds. 

  2. 			cmtrace2txt -v --filter="name match 'System.*' and duration>=10ms" trace.bin

    Selects only those function trace entries whose function name starts with "System" followed by a period and duration is equal to or greater than 10 milliseconds. 

  3. 			cmtrace2txt -v --filter="level=0 and duration>=10ms or parent" trace.bin

    Selects only those function trace entries that are either top level (level=0) and whose duration is equal to or greater than 10 milliseconds, or whose parent entry is selected. That is, the parent expression selects all child entries of included top level entries.