Trace System CILS

Sometimes, it's helpful to trace system api cils 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

#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     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 cils 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 shoshould 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:

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

3. strace on Linux
Strace is similar to logger on windows in that it only trace API cballs in a flat structure.