C++ code tracing and logfile writing under windows and linux

How to do things
AI Noob vs. Pro

List biggest files
List newest files
Show subdir sizes
Search in files
Replace word in files
List dir differences
Send files in LAN

Free Open Source:

Swiss File Knife

a command line
multi function tool.

remove tabs
list dir sizes
find text
filter lines
find in path
collect text
instant ftp or
http server
file transfer
send text
patch text
patch binary
run own cmd
convert crlf
dup file find
md5 lists
fromto clip
hexdump
split files
list latest
compare dirs
save typing
trace http
echo colors
head & tail
dep. listing
find classes
speed shell
zip search
zip dir list

Depeche View
Source Research
First Steps

windows GUI
automation

command line
file encryption

free external tools,
zero install effort,
usb stick compliant:

zip and unzip
diff and merge
reformat xml
reformat source

cpp sources

log tracing
mem tracing
hexdump
using printf

articles

embedded
stat. c array
stat. java array
var. c array
var. java array
view all text
as you type
surf over text
find by click
quick copy
multi view
find nearby
fullscreen
bookmarks
find by path
expressions
location jump
skip accents
clip match
filter lines
edit text
highlight
load filter
hotkey list
receive text
send in C++
send in Java
smooth scroll
touch scroll
fly wxWidgets
fly over Qt
search Java

Are you still using printf in your C++ code? Read how to replace this easily by logfile based tracing, using the free sfk micro tracing kernel for windows and linux.

Chapter 1: from printf to a simple logfile.

This article expects that your code currently looks like in this example:

#include <stdio.h>

int main(int argc, char *argv[])
{
printf("start reached\n");
char *p1 = 0;
printf("step2 reached\n");
*p1 = '\0';
printf("step3 reached\n");
return 0;
}

The tracing outputs are dumped to terminal. This creates two problems:

writing the trace output is very slow. a printf to terminal takes much time.

if you're writing a GUI program, e.g. with a WinMain() method, you cannot see the trace outputs at all.

Now follow these steps:

cd into the root directory of your source code base.

create a directory mtk, and copy the following two files into there:
mtktrace.hpp and mtktrace.cpp (use Save Link As).

Then adapt your code like in this example:

#include <stdio.h>
#include "mtk/mtktrace.hpp"

int main(int argc, char *argv[])
{
mtklog("start reached");
char *p1 = 0;
mtklog("step2 reached");
*p1 = '\0';
mtklog("step3 reached");
return 0;
}

The mtklog() syntax is just as with printf, but you can leave out the "\n".
Now you have to adapt your build script, to also compile and link "mtk\mtktrace.cpp".
For example, if you currently say

cl myprog.cpp

then extend this to

cl myprog.cpp mtk\mtktrace.cpp

(Linux users type something like "g++-4.0 myprog.cpp mtk/mtktrace.cpp" instead).

By default, mtk tracing is not active, and must be activated through an environment variable:

SET MTK_TRACE=filename:log.txt

Now, running the above sample program will create a file "log.txt" containing:

[00:D] start reached
[00:D] step2 reached

The characters at the beginning of each line are nesting level and message type - for our simple example, you can ignore them.

Chapter 2: simple program flow tracing, using manually inserted statements.

Let's have a look at a variation of above example:

#include <stdio.h>
#include "mtk/mtktrace.hpp"

void myfunc(char *p)
{
*p = '\0';
}

int main(int argc, char *argv[]) 
{
char *p1 = 0;
myfunc(p1);
return 0;
}

Again, the program crashes, and we want to easily find out where. We may again insert statements of the kind "step x reached", but it can be done easier with a small macro:

#include <stdio.h>
#include "mtk/mtktrace.hpp"

#define _ mtklog("[%s %d]", __FILE__, __LINE__);

void myfunc(char *p)
{_
*p = '\0';
_}

int main(int argc, char *argv[]) 
{_
_  char *p1 = 0;
_  myfunc(p1);
_  return 0;
}

This will create a logfile with a content like this:

[00:D] [examp3.cpp 12]
[00:D] [examp3.cpp 13]
[00:D] [examp3.cpp 14]
[00:D] [examp3.cpp 7]

so we see: the last line reached is number 7, just before the pointer write.

And when you found the bug, you can easily deactivate the "_" traces by changing the macro definition into:

#define _ // mtklog("[%s %ld]\n", __FILE__, __LINE__)

which replaces "_" by nothing in the code.

Chapter 3: advanced program flow tracing, using source code instrumentation.

Let's have a true C++ example, with a hierarchy of methods calling each other:

#include <stdio.h>
#include "mtk/mtktrace.hpp"

class Foo 
{
public:
char myfunc    (char *p);
void myfunc2   (char *p);
};

char Foo::myfunc(char *p) 
{
myfunc2(p);
return *p;
}

void Foo::myfunc2(char *p) 
{
*p = '\0';
}

int main(int argc, char *argv[]) 
{
char *p1 = 0;
Foo myfoo;
myfoo.myfunc(p1);
return 0;
}

If this example would be really huge, we may not want to insert "_" statements manually. So we may try automated source code instrumentation.

WARNING: before you try the following on any of your existing source code, always create a backup! The modified source may be useful for a temporary debug session, but you may NOT want to continue working with it for all time.

On the command line, go into the root of your source code base, then say:

sfk inst mtk/mtktrace.hpp _mtkb_ -dir . !save_ -file .cpp

The sfk command for windows and linux is available here. All .cpp files will be processed ("instrumented"), and the sources will be modified like this:

#include "mtk/mtktrace.hpp" // [instrumented]
#include <stdio.h>
#include "mtk/mtktrace.hpp"

class Foo 
{
public:
char myfunc    (char *p);
void myfunc2   (char *p);
};

char Foo::myfunc(char *p) 
{_mtkb_("Foo::myfunc");
myfunc2(p);
return *p;
}

void Foo::myfunc2(char *p) 
{_mtkb_("Foo::myfunc2");
*p = '\0';
}

int main(int argc, char *argv[]) 
{
char *p1 = 0;
Foo myfoo;
myfoo.myfunc(p1);
return 0;
}

In (most) c++ methods you will find that some "_mtkb_" statement has been added at the method entry. Furthermore, the changed .cpp files all contain an include statement #include "mtk/mtktrace.hpp", just like what you specified with the 'inst' command.

The source code now contains Block Nesting Control. Now modify the MTK_TRACE setting like this:

set MTK_TRACE=ring:tb,file:tb,filename:log.txt

Which means "trace tracing and block statements both into an internal ring buffer, and to file". After the next test run, log.txt will look like this:

[00:B]  Foo::myfunc
[00:B]   Foo::myfunc2

as you see, the output is now indented by the nesting level. the deeper the call stack is, the more the output is shifted to the right.

Limitations:

Please note that the "sfk inst" command is very selective about the syntax of the source code:

only C++ methods can be instrumented, not simple C functions.

only methods with "{" at line start are instrumented:

void Foo::myfunc2(char *p) 
{
*p = '\0';
}

but not methods in short format, for example:

void Foo::myfunc2(char *p) {
*p = '\0';
}

void Foo::myfunc3(char *p) { *p = '\0'; }

as such methods are often not important enough to have them tracked.

instrumenting source code may slow down the program significantly and should never be used in production code. it makes sense only during a debug phase, e.g. to create once a stack trace for reverse call analysis.

Chapter 4: ring buffers and on-demand stack traces

In the above example, we traced the program flow directly into a tracefile using the "file:tb" option. Now let's change the setting a bit:

set MTK_TRACE=ring:tb,filename:log.txt

As you will see, the program flow is no longer traced into the trace file, speeding up program execution significantly. But how do we see now the flow of execution? We found out that the program crashes in myfunc2(), so we want to know how we got there. Do this by inserting a call before the critical line:

void Foo::myfunc2(char *p) 
{_mtkb_("Foo::myfunc2");

mtkDumpStackTrace(1);

*p = '\0';
}

the mtkDumpStackTrace call simply reads out the internal ring buffer, which is still tracing the program flow ("ring:tb" option). what you now get is:

> ------- stack trace, thread 0, sysid d48, 2 levels -------
> 00 Foo::myfunc examp4.cpp:13
> 00  Foo::myfunc2 examp4.cpp:19
> ---------------------- stack trace end ---------------------

the difference is now that we dump the last steps of the program on demand, instead of permanent flow tracing.

besides mtkDumpStackTrace, which lists only the last _mtkb_ statements reached, there is also a method mtkDumpLastSteps, which dumps the last mtklog() statements which are also recorded in the ring buffer.

furthermore, mtkDumpStackTrace(0) or mtkDumpLastSteps(0) dumps the stack trace/last steps of ALL threads, not just of the current thread. this may create a rather long output (last steps by default lists up to 10000 records).

so much for this short introduction to mtk. experienced developers will find out by themselves how this can be used, for example, in combination with other tracing systems already present in their source base. mtk is very low-level, low-overhead, and can be used as a layer below anything else, to mix tracing statements of different tracing systems back together.

NOTE:

if you decide to integrate mtk permanently within a project, be careful, and make sure that you provide some compile option to disable the whole tracing. mtk is intended as an analysis tool, and as with all free things, there is no guarantee whatsoever that mtk will work reliantly, especially within production systems.
if you use temporary (non-check-in) sfk instrumentation together with sfk patching, it is recommended that you instrument first, and patch second. this way you can redo your patches easily and anytime, whereas re-instrumentation ususally takes much longer.
mtk does not use mutex semaphores so far. this way it stays as low-overhead as possible. however, you have to expect that the one or other tracing record may get lost during heavy multithreading.