How to format profiling time stamp messages

Carsten Driesner and Andre Fischer, last change on August 2^nd, 2001

Introduction

Each use of the macros RTL_LOGFILE_CONTEXT_AUTHOR, RTL_LOGFILE_CONTEXT_TRACE<n>, andRTL_LOGFILE_TRACE_AUTHOR<n> writes a time stamp into a logfile that can be parsed by post-processing scripts. This works only if the text that is given as arguments to the macros follows certain rules.

The next section describes the overall format of the time stamps written by the macros. The format of the text passed as arguments to the macros is described int the third section.

Overall time stamp format

Each time stamp written by one of the macros RTL_LOGFILE_CONTEXT_AUTHOR, RTL_LOGFILE_CONTEXT_TRACE<n>, and RTL_LOGFILE_TRACE_AUTHOR<n> has the format

%d %d %c %s : %s

with the following arguments:

Time in milliseconds after the first time stamp. This implies that the first time stamp has always a value of 0 in this field. To convert the relative times into absolute ones or ones that are relative to the application start you can evaluate the first line in the log-file which is described below.
Id of the thread from which the time stamp has been emitted. The process id can be determined from the name of the log-file.
A character the classifies the time steps into three classes:

An { indicates the beginning of a function or other scope.
An } indicates the end of a function or other scope.
An | indicates a message from within a scope or without a scope.

Name or description of a function or other scope. This name is used to group beginnings and ends of a scope together. If RTL_LOGFILE_TRACE_AUTHOR<n> is used instead of RTL_LOGFILE_CONTEXT_TRACE<n> then this field remains empty.
Arbitrary message written by RTL_LOGFILE_TRACE_AUTHOR<n> and RTL_LOGFILE_CONTEXT_TRACE<n>. If RTL_LOGFILE_CONTEXT_AUTHOR is used instead then this field remains empty.

Note that the dividing colon between the last two fields is written even if one of them remains empty.

As you can see, you can only specify the content of the last two fields. The format that they may have is described in the following section.

Admissable format of scope names and messages

This section focuses on the format of the last two fields of a time stamp. The first one should have format

%s (%s) %s

with the following arguments:

Module name. This will be strings like sfx2 or desktop.
Sun id with prefixed shortcut of responsible developer. That would be cd100003 or af119097 for the authors. Use the Sun id of the project owner, if you have no Sun id.
Fully qualified function name with leading double colon. Add a simplified signature only if that is necessary to distinguish it from other functions with the same name. The function name starts with the complete namespace, the class name (if it is really a method) and finally the actual function name.

The three fields are separated by singles spaces.

The second argument may have any format you like with two constraints:

It may not contain a newline character.
If it starts with an opening or a closing curly bracket then it has a meaning similar to the third field of the overall format: it describes the beginning or end of a scope. You can define a logical scope with this format even though you don't have an analog physical representation and don't want to introduce a new scope for it.

Use RTL_LOGFILE_CONTEXT_AUTHOR<n> if possible to automatically write the fields described above with every time stamp emitted from the context. If that is not possible or usefull then start the message field with a string that has the format described above. Use your common sense to fill in the second and fourth field. Divide that string with a colon surrounded by spaces from the actual message string.

Examples

The following pseudo code uses a context to write time stamps at the beginning and end of scopes in the implicit form and the explicit one that uses the message string to indicate the scope boundaries.

void ::Desktop::OpenStartupscreen (arguments)

{

RTL_LOGFILE_CONTEXT_AUTHOR (aInstance, „desktop“, „cd100003“, „::Desktop::OpenStartupscreen“);

...

RTL_LOGFILE_CONTEXT_TRACE (aInstance, „{ lengthy calculation“);

for (...)

{

do something

}

RTL_LOGFILE_CONTEXT_TRACE (aInstance, „} lengthy calculation“);

}

It generate time stamps like these:

001234 11 { desktop (cd100003) ::Desktop::OpenStartupscreen

002345 11 | desktop (cd100003) ::Desktop::OpenStartupscreen : { lengthy calculation

003456 11 | desktop (cd100003) ::Desktop::OpenStartupscreen : } lengthy calculation

004567 11 } desktop (cd100003) ::Desktop::OpenStartupscreen

This pseudo code uses the context free version:

void ::Desktop::CloseStartupscreen

{

...

RTL_LOGFILE_TRACE_AUTHOR („desktop“, „cd100003“, „::Desktop::CloseStartupscreen : Startup finished“);

}

It's output might look like this:

099999 11 | desktop (cd100003) ::Desktop::CloseStartupscreen : Startup finished