For demonstration purpose, we'll use code below to try these tools
1 #include "Windows.h" / "unistd.h"
2 #include "fstream"
3 using namespace std;
4
5 void foo()
6 {
7 Sleep(2000); // windows
8 sleep(2); // linux
9 }
10
11 void bar()
12 {
13 ofstream of("foo.dat");
14 char buf[] = {1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16};
15 of << buf;
16 of.close();
17
18 foo();
19 }
20
21 int main()
22 {
23 bar();
24 foo();
25 return 0;
26 }
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 standalone logger application isn't suitable for tracing windows service. In this case, we can attach windbg to a target process and load logexts extension to work against a service.2 #include "fstream"
3 using namespace std;
4
5 void foo()
6 {
7 Sleep(2000); // windows
8 sleep(2); // linux
9 }
10
11 void bar()
12 {
13 ofstream of("foo.dat");
14 char buf[] = {1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16};
15 of << buf;
16 of.close();
17
18 foo();
19 }
20
21 int main()
22 {
23 bar();
24 foo();
25 return 0;
26 }
The result of logger is saved in a binary file placed in LogExts folder, and the file need to be opened in LogViewer. The file only records all APIs being called based on their orders, so we can't identify calling relationships between them. 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:
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: 03. strace on linux strace is similar to logger on windows in that it only trace api calls in a flat structure.
