Let's take a closer look at a recording example. This is an excerpt from a real trace done on a Windows 2000 system. The function KeBalanceSetManager of ntoskrnl.exe has been put under recording.
First, we can look at a sample of the call analysis.
The first entry below corresponds to a call which has been executed. The call is shown, along with the destination address. The address labeled "cur fun" is the one of the current function at the moment of the call (the caller). The address labeled "instr" is the one of the call instruction. "dest" marks the destination address. Finally, following the hyphen, the symbolic name of the destination taken from the Windows debugging symbols can be found. In this case, the call was into KeSetEvent.
# 3 call 804FC9F3 st:open cur fun: 0000:00000000 Frm #34 instr: 0008:80530283 dest: 0008:804fc9f3 - ntoskrnl.exe!KeSetEvent
Why does "cur fun" contain a zero address? Because Foosteps defines the function targeted by the last executed call as the current one and this was the first call of the recording, hence no current function is yet defined.
Thus, the next entry give us an insight of the working of KeSetEvent. First a call to KeRaiseIrqlToDpcLevel is found. Note how this was an indirect call.
# 4 call [804D0588] st:clos cur fun: 0008:804fc9f3 Frm #40 instr: 0008:804fc9f9 dest: 0008:80661ecc - hal.dll!KeRaiseIrqlToDpcLevel
Then, there is the matching ret. The two entries are related through the number (4) at the beginning of the line. They are also equally indented. The target ("dest") address of the ret is obviously inside KeSetEvent.
# 4 retn cur fun: 0008:80661ecc Frm #44 instr: 0008:80661eda dest: 0008:804fc9ff - ntoskrnl.exe!KeSetEvent + 0xc
The next entries show how KeSetEvent goes on by calling KiUnwaitThread (which, in turn calls KiReadyThread) then KiUnlockDispatcherDatabase.
# 5 call 80501FF7 st:clos cur fun: 0008:804fc9f3 Frm #61 instr: 0008:804fca4c dest: 0008:80501ff7 - ntoskrnl.exe!KiUnwaitThread
# 6 call 80500BB7 st:clos cur fun: 0008:80501ff7 Frm #90 instr: 0008:805020b2 dest: 0008:80500bb7 - ntoskrnl.exe!KiReadyThread
# 6 retn cur fun: 0008:80500bb7 Frm #124 instr: 0008:80500cac dest: 0008:805020b7 - ntoskrnl.exe!KiUnwaitThread + 0xc0
# 5 retn 00000004 cur fun: 0008:80501ff7 Frm #127 instr: 0008:805020b9 dest: 0008:804fca51 - ntoskrnl.exe!KeSetEvent + 0x5e
# 7 call 804D389C st:open cur fun: 0008:804fc9f3 Frm #133 instr: 0008:804fca66 dest: 0008:804d389c - ntoskrnl.exe!KiUnlockDispatcherDatabase
...
This trace is the result of a live execution, thus the call sequence we are seeing is actually the result of the "choices" the code made in this particular case.
Now we can have a look at a sample from the instruction trace; let'sconcentrate on the first call instruction of the listing above:
Frm #34
eax = 0x00000000 LU: 0008:80661f33 Frm #27
ebx = 0x00000000 LU: 0000:00000000 Frm #0
ecx = 0x00000000 LU: 0008:8053026c Frm #12
edx = 0x80010031 LU: 0000:00000000 Frm #0
esi = 0xff676980 LU: 0000:00000000 Frm #0
edi = 0xffffffff LU: 0000:00000000 Frm #0
esp = 0xf085bd28 LU: 0000:00000000 Frm #0
ebp = 0xf085bda8 LU: 0000:00000000 Frm #0
eflags = 0x00000346
cs = 0x0008; ss = 0x0010; ds = 0x0023; es = 0x0023; fs = 0x0030; gs = 0x0000
0008:80530283 %80530283 cpl= 0 [...] - ntoskrnl.exe!
KeBalanceSetManager + 0xbb
We can see the instruction address with its symbolic name (inside KeBalanceSetManager). The actual trace shows the call instruction, which here is substituted with "[...]". The register values shown are the one before the instruction executes. These listing entries are called frames. This is frame #34 and its number is reported into the call analysis we saw before (see the first call).
Frame #35 shows the state after the call, that is the first instruction of KeSetEvent (the assembly instruction is not shown here, but in the trace is found in place of "[...]").
Frm #35
eax = 0x00000000 LU: 0008:80661f33 Frm #27
ebx = 0x00000000 LU: 0000:00000000 Frm #0
ecx = 0x00000000 LU: 0008:8053026c Frm #12
edx = 0x80010031 LU: 0000:00000000 Frm #0
esi = 0xff676980 LU: 0000:00000000 Frm #0
edi = 0xffffffff LU: 0000:00000000 Frm #0
esp = 0xf085bd24 LU: 0000:00000000 Frm #0
ebp = 0xf085bda8 LU: 0000:00000000 Frm #0
eflags = 0x00000346
cs = 0x0008; ss = 0x0010; ds = 0x0023; es = 0x0023; fs = 0x0030; gs = 0x0000
0008:804fc9f3 %804fc9f3 cpl= 0 [...] - ntoskrnl.exe!KeSetEvent
This example shows the big difference between the instruction trace and a disassembly listing obtained from a debugger: we are looking at the instruction stream in the order in which it executed, so, after a call, we see the first instruction of the called function, not the caller's instruction following the call.
Let's look at another frame, which highlits more Foosteps features.
Frm #48
eax = 0x00000000 LU: 0008:80661ece Frm #42
ebx = 0x00000000 LU: 0008:804fca02 Frm #46
ecx = 0x8054e630 LU: 0008:804fc9ff Frm #45
edx = 0x80010031 LU: 0000:00000000 Frm #0
esi = 0x8158790c LU: 0008:804fca04 Frm #47
edi = 0xffffffff LU: 0000:00000000 Frm #0
esp = 0xf085bd14 LU: 0000:00000000 Frm #0
ebp = 0xf085bd20 LU: 0008:804fc9f4 Frm #36
eflags = 0x00000346
cs = 0x0008; ss = 0x0010; ds = 0x0023; es = 0x0023; fs = 0x0030; gs = 0x0000
[...] cpl= 0 mov edi, dword ptr 00000004[ecx] - [...]
0023:8054e634 %8054e634 - [...]
0x00000000
This instruction accessed a memory operand and Footsteps recorded it's run-time address (0x8054e634) below the opcode; this address is determined by the value into ecx. The Analyzer provides it's symbolic name (here replaced by "[...]" after the hyphen), so we know what [ecx + 4] actually is.
Another feature is that Footsteps shows, under the operand address, its value. This value has been recorded just before the instruction executed, so it's the actual value used by this particular execution of this piece of code.
The addresses labeled "LU" following each register are the ones of the instruction which last updated it, together with the frame number. This makes extremely easy to trace back a particular register value, thus helping to understand its meaning. A value of 0 means the register has not been updated since the beginning of the recording. After this frame, the "LU" entry for edi will contain the address of the mov above and frame #48.
Finally, the cross reference produced by Footsteps shows a list of memory operand addresses together with the instructions which referenced them. Below is the excerpt corresponding to the access we just saw:
Data addr: 0023:8054e634 %8054e634 - ntoskrnl.exe!KiSwapEvent + 0x4
Instr addr: 0008:804fca07 %804fca07 - ntoskrnl.exe!KeSetEvent + 0x14
In summary, Footsteps has been designed to help the process of understanding what a piece of code for which sources are not available does. It automatically performs cumbersome tasks like keeping track of the sequence of function calls and of the provenance of values stored in the registers. You can get lost in the middle of a long disassembly listing when you face a ret instruction and you don't know where it will bring you, because you don't remember how you got there anymore. Foosteps keeps track of all these things for you, while you concentrate on the actual logic of the code.
I hope to have succeeded in convincing you that Footsteps is worth a try but, to be honest, I must point out from the beginning that it has its limitations. These are better explained after having examined its architecture, therefore details can be found later in this document (see sec. 15.4 and 12.7.2). For instance, the disassembler of the Analyzer is limited to a subset of x86 instructions: the single byte opcodes. I believe this is acceptable because Footsteps is not meant to be a substitute for a real disassembler. Its purpose is to add runtime information like call sequences, taken branch paths and operand values. Thus, the best way to use it is to rely on a real disassembler to obtain code listings and examine Footsteps traces to determine: which functions disassemble first (the innermost ones could be a good choice), which other functions touch the same static data, etc.
|
