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.
