Trace System Calls
Sometimes, it's helpful to trace system api calls during debugging so that we can determine if the incorrect behavior is caused by passing wrong argument to a function or not. Or we can try to identify the performance bottleneck with it. There are several tools to use with this purpose.
For demonstration purpose, we'll use code below to try these tools
1. Logger
This tool can be used as a standalone application or used as a debugger extension in windbg. It's capable of keeps records of all system api calls and corresponding parameters, return value, time spent, calling module and thread.
To run as a application, simply call "logger.exe application to be traced". Then you can specify some option and filter in the window popped up. But stand alone application isn't suitable for tracing windows service.
And we can attach windbg to a target process and load logexts extension to work against a service.
The report of logger is in flat structure. So we can't identify calling relationships between those api. The figure belows shows the result of tracing ProcessAndThreads and ioFunctions module:
From the row #42 which is expanded, we can see the parameter passed to Sleep function is 0x000007d0 which is 2000 in decimal.
2. wt command in windbg
windbg has another powerful command wt. Compared with logger extension, it has more controls over which apis shall be traced. Actually, it can also trace user's function call. And the wonderful thing with it is it can show the calling relationship with a tree. It should be a preferable way.
To use it, we set a break point in the place of interest. Then issue wt command. The debugee shall continue executing until this function returns.
We perform wt on the sample code, the output is:
strace is similar to logger on windows in that it only trace api calls in a flat structure.
For demonstration purpose, we'll use code below to try these tools
#include "Windows.h" / "unistd.h"
#include "fstream"
using namespace std;
void foo()
{
Sleep(2000); // windows
sleep(2); // linux
}
void bar()
{
ofstream of("foo.dat");
char buf[] = {1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16};
of << buf;
of.close();
foo();
}
int main()
{
bar();
foo();
return 0;
}
1. Logger
This tool can be used as a standalone application or used as a debugger extension in windbg. It's capable of keeps records of all system api calls and corresponding parameters, return value, time spent, calling module and thread.
To run as a application, simply call "logger.exe application to be traced". Then you can specify some option and filter in the window popped up. But stand alone application isn't suitable for tracing windows service.
And we can attach windbg to a target process and load logexts extension to work against a service.
The report of logger is in flat structure. So we can't identify calling relationships between those api. The figure belows shows the result of tracing ProcessAndThreads and ioFunctions module:
![](http://4.bp.blogspot.com/_n5BzA0M85tM/SpHnbv8-11I/AAAAAAAAATQ/PcpZQPscbxY/s320/1.png)
2. wt command in windbg
windbg has another powerful command wt. Compared with logger extension, it has more controls over which apis shall be traced. Actually, it can also trace user's function call. And the wonderful thing with it is it can show the calling relationship with a tree. It should be a preferable way.
To use it, we set a break point in the place of interest. Then issue wt command. The debugee shall continue executing until this function returns.
We perform wt on the sample code, the output is:
3. strace on linux
0:000> wt -l 4
Tracing 1!main to return address 004096a1
3 0 [ 0] 1!main
1 0 [ 1] 1!ILT+540(?barYAXXZ)
12 0 [ 1] 1!bar
...
37 1069 [ 1] 1!bar
1 0 [ 2] 1!ILT+735(?fooYAXXZ)
4 0 [ 2] 1!foo
6 0 [ 3] kernel32!Sleep
37 0 [ 4] kernel32!SleepEx
8 37 [ 3] kernel32!Sleep
6 45 [ 2] 1!foo
39 1121 [ 1] 1!bar
...
42 1209 [ 1] 1!bar
3 0 [ 2] 1!__security_check_cookie
45 1212 [ 1] 1!bar
4 1258 [ 0] 1!main
1 0 [ 1] 1!ILT+735(?fooYAXXZ)
4 0 [ 1] 1!foo
6 0 [ 2] kernel32!Sleep
3 0 [ 3] kernel32!SleepEx
19 0 [ 4] kernel32!_SEH_prolog
15 19 [ 3] kernel32!SleepEx
20 0 [ 4] ntdll!RtlActivateActivationContextUnsafeFast
20 39 [ 3] kernel32!SleepEx
19 0 [ 4] kernel32!BaseFormatTimeOut
26 58 [ 3] kernel32!SleepEx
1 0 [ 4] ntdll!ZwDelayExecution
3 0 [ 4] ntdll!NtDelayExecution
31 62 [ 3] kernel32!SleepEx
4 0 [ 4] kernel32!SleepEx
36 66 [ 3] kernel32!SleepEx
9 0 [ 4] kernel32!_SEH_epilog
37 75 [ 3] kernel32!SleepEx
8 112 [ 2] kernel32!Sleep
6 120 [ 1] 1!foo
7 1385 [ 0] 1!main
1392 instructions were executed in 1391 events (0 from other threads)
Function Name Invocations MinInst MaxInst AvgInst
1!ILT+1010(??0?$basic_ofstreamDU?$char_traitsDs 1 1 1 1
1!ILT+1040(?sputn?$basic_streambufDU?$char_trai 1 1 1 1
1!ILT+1060(?close?$basic_ofstreamDU?$char_trait 1 1 1 1
1!ILT+1090(??0sentry?$basic_ostreamDU?$char_tra 1 1 1 1
1!ILT+1125(?flagsios_basestdQBEHXZ) 1 1 1 1
1!ILT+1155(?getloc?$basic_streambufDU?$char_tra 1 1 1 1
1!ILT+1185(??0_Sentry_base?$basic_ostreamDU?$ch 1 1 1 1
1!ILT+1210(?_Osfx?$basic_ostreamDU?$char_traits 1 1 1 1
1!ILT+130(??1localestdQAEXZ) 1 1 1 1
...
1!ILT+950(??0?$basic_streambufDU?$char_traitsDs 1 1 1 1
1!ILT+965(??1?$basic_ofstreamDU?$char_traitsDst 1 1 1 1
1!__security_check_cookie 1 3 3 3
1!__uncaught_exception 1 6 6 6
1!bar 1 45 45 45
1!fclose 1 27 27 27
1!foo 2 6 6 6
1!main 1 7 7 7
1!std::_Fiopen 1 29 29 29
...
1!strlen 1 52 52 52
kernel32!BaseFormatTimeOut 1 19 19 19
kernel32!Sleep 2 8 8 8
kernel32!SleepEx 3 4 37 26
kernel32!_SEH_epilog 1 9 9 9
kernel32!_SEH_prolog 1 19 19 19
ntdll!NtDelayExecution 1 3 3 3
ntdll!RtlActivateActivationContextUnsafeFast 1 20 20 20
ntdll!ZwDelayExecution 1 1 1 1
0 system calls were executed
eax=00000000 ebx=7ffd6000 ecx=7c80240f edx=7c90e514 esi=00dcf766 edi=00dcf6f2
eip=004096a1 esp=0012ff80 ebp=0012ffc0 iopl=0 nv up ei pl zr na pe nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000246
1!__tmainCRTStartup+0xfb:
0
strace is similar to logger on windows in that it only trace api calls in a flat structure.