Dynamic Instrumentation Tool Platform
DynamoRIO
Logging

This page describes some of the useful information available in DR's logfiles. See also the general page on debugging.

Enabling Logging

Logging can be enabled with the `-loglevel` runtime option in a debug build. A number specifies the logging level. For example:

% bin64/drrun -debug -loglevel 2 -- ls

Log Directories and Files

Logs are written to the logs/ subdirectory of the DR install or build directory. A new subdirectory is created for each process, with a name composed of the executable name, the process id, and an instance number to ensure that it is unique. This directory name is reported at the start of the run:

% bin64/drrun -debug -loglevel 2 -c samples/bin64/libopcodes.so -- ls
<log dir=/work/dr/git/exports/bin64/../logs/ls.4611.00000000>
<Starting application /usr/bin/ls (4611)>
...

Within the log directory for a process, there is a single process-wide file and a separate file for each thread. Log messages are typically sent to the executing thread's file, but events that affect the whole process are sent to the process log file instead. The process file's name is similar to the directory name. The thread file names start with log followed by the sequential number of the thread and then the thread id. For example:

% ls /work/dr/git/exports/bin64/../logs/ls.4611.00000000
log.0.4611.html ls.0.4611.html

The files are named with the .html for historical reasons, to make it easy to open via double-clicking on a Windows machine. They are not really in HTML format but are plain text.

Fragments

A fragment is a unit of code executed in the code cache, with a single entry and multiple exits. A fragment is either a dynamic basic block or a trace.

Loglevel 2

At -loglevel 2, a thread log file prints the start address of each fragment created as well as the entries and exits from the cache. Fragments that are linked or indirect branch lookup hits stay within the cache and such transitions do not show up in the log.

For example:

dispatch: target = 0x00007f9c9ba10b80
Entry into F1581(0x00007f9c9ba10b80).0x0000000049b69ba8 (shared)
Exit from sourceless ibl: bb jmp*
(target 0x00007f9c9b016900 in cache but not lookup table)
dispatch: target = 0x00007f9c9b016900
Entry into F3826(0x00007f9c9b016900).0x0000000049bbc1d0 (shared)
Exit from F3836(0x00007f9c9b0edb69).0x0000000049bbc346 (shared)
(cannot link F3836->F3837) (target F3837 is trace head)
dispatch: target = 0x00007f9c9b0edb60
Entry into F3837(0x00007f9c9b0edb60).0x0000000049bbc35c (trace head)(shared)
Exit from sourceless ibl: bb ret
(target 0x00007f9c9b3a0033 not in cache)

Loglevel 3

At loglevel 3, details of the instructions that are processed to create each fragment are given. First, the instructions decoded from application code by the "interpreter" are listed:

dispatch: target = 0x00007fbd5cfb2b10
interp: start_pc = 0x00007fbd5cfb2b10
0x00007fbd5cfb2b10 4c 89 d9 mov %r11 -> %rcx
0x00007fbd5cfb2b13 48 29 c1 sub %rax %rcx -> %rcx
0x00007fbd5cfb2b16 48 83 f9 0b cmp %rcx $0x000000000000000b
0x00007fbd5cfb2b1a 77 14 jnbe $0x00007fbd5cfb2b30
end_pc = 0x00007fbd5cfb2b1c

Next, the intructions are listed in DR's IR format as they are passed to the client. The first column in an instruction list printout shows the offset in bytes from the start of the list if the instructions were to be encoded as-is. The second column identifies the type of instruction: typically either L3 for an unmodified application instruction or m4 for a client-added tool instruction:

instrument_basic_block ******************
before instrumentation:
TAG 0x00007fbd5cfb2b10
+0 L3 4c 89 d9 mov %r11 -> %rcx
+3 L3 48 29 c1 sub %rax %rcx -> %rcx
+6 L3 48 83 f9 0b cmp %rcx $0x000000000000000b
+10 L3 77 14 jnbe $0x00007fbd5cfb2b30
END 0x00007fbd5cfb2b10
after instrumentation:
TAG 0x00007fbd5cfb2b10
+0 m4 @0x0000000048850840 f0 81 05 61 90 7b 29 lock add $0x00000001 <rel> 0x000000007200396c[4byte] -> <rel> 0x000000007200396c[4byte]
01 00 00 00
+11 m4 @0x0000000048850c28 f0 81 05 a9 8f 7b 29 lock add $0x00000001 <rel> 0x00000000720038b4[4byte] -> <rel> 0x00000000720038b4[4byte]
01 00 00 00
+22 m4 @0x000000004884d8c0 f0 81 05 b9 8f 7b 29 lock add $0x00000001 <rel> 0x00000000720038c4[4byte] -> <rel> 0x00000000720038c4[4byte]
01 00 00 00
+33 m4 @0x000000004884e868 f0 81 05 05 90 7b 29 lock add $0x00000001 <rel> 0x0000000072003910[4byte] -> <rel> 0x0000000072003910[4byte]
01 00 00 00
+44 L3 4c 89 d9 mov %r11 -> %rcx
+47 L3 48 29 c1 sub %rax %rcx -> %rcx
+50 L3 48 83 f9 0b cmp %rcx $0x000000000000000b
+54 L3 77 14 jnbe $0x00007fbd5cfb2b30
END 0x00007fbd5cfb2b10

Loglevel 4

At -loglevel 4, the mangling performed by DR is visible as the precise code layout encoded in the code cache is shown:

interp: start_pc = 0x00007fbff7a2ccb2
0x00007fbff7a2ccb2 f3 c3 ret %rsp (%rsp)[8byte] -> %rsp
mbr exit target = 0x00000000516af500
end_pc = 0x00007fbff7a2ccb4
instrument_basic_block ******************
before instrumentation:
TAG 0x00007fbff7a2ccb2
+0 L3 f3 c3 ret %rsp (%rsp)[8byte] -> %rsp
END 0x00007fbff7a2ccb2
after instrumentation:
TAG 0x00007fbff7a2ccb2
+0 m4 @0x000000005171dd38 65 48 a3 18 00 00 00 mov %rax -> %gs:0x18[8byte]
00 00 00 00
+11 m4 @0x000000005171e1e8 9f lahf -> %ah
+12 m4 @0x000000005171db40 0f 90 c0 seto -> %al
+15 m4 @0x0000000051765b50 f0 81 05 99 90 8e 20 lock add $0x00000001 <rel> 0x00000000720039a4[4byte] -> <rel> 0x00000000720039a4[4byte]
01 00 00 00
+26 m4 @0x000000005171eb08 <label>
+26 m4 @0x0000000051765bd0 04 7f add $0x7f %al -> %al
+28 m4 @0x000000005171e8e8 9e sahf %ah
+29 m4 @0x000000005171dc40 65 48 a1 18 00 00 00 mov %gs:0x18[8byte] -> %rax
00 00 00 00
+40 m4 @0x0000000051765800 <label>
+40 L3 f3 c3 ret %rsp (%rsp)[8byte] -> %rsp
END 0x00007fbff7a2ccb2
bb ilist before mangling:
TAG 0x00007fbff7a2ccb2
+0 m4 @0x000000005171dd38 65 48 a3 18 00 00 00 mov %rax -> %gs:0x18[8byte]
00 00 00 00
+11 m4 @0x000000005171e1e8 9f lahf -> %ah
+12 m4 @0x000000005171db40 0f 90 c0 seto -> %al
+15 m4 @0x0000000051765b50 f0 81 05 99 8f 8e 20 lock add $0x00000001 <rel> 0x00000000720039a4[4byte] -> <rel> 0x00000000720039a4[4byte]
01 00 00 00
+26 m4 @0x000000005171eb08 <label>
+26 m4 @0x0000000051765bd0 04 7f add $0x7f %al -> %al
+28 m4 @0x000000005171e8e8 9e sahf %ah
+29 m4 @0x000000005171dc40 65 48 a1 18 00 00 00 mov %gs:0x18[8byte] -> %rax
00 00 00 00
+40 m4 @0x0000000051765800 <label>
+40 L3 f3 c3 ret %rsp (%rsp)[8byte] -> %rsp
+42 L4 @0x00000000517205f8 e9 fb 4a f9 ff jmp $0x00000000516af500 <shared_bb_ibl_ret>
END 0x00007fbff7a2ccb2
bb ilist after mangling:
TAG 0x00007fbff7a2ccb2
+0 m4 @0x000000005171dd38 65 48 a3 18 00 00 00 mov %rax -> %gs:0x18[8byte]
00 00 00 00
+11 m4 @0x000000005171e1e8 9f lahf -> %ah
+12 m4 @0x000000005171db40 0f 90 c0 seto -> %al
+15 m4 @0x0000000051765b50 f0 81 05 99 8f 8e 20 lock add $0x00000001 <rel> 0x00000000720039a4[4byte] -> <rel> 0x00000000720039a4[4byte]
01 00 00 00
+26 m4 @0x000000005171eb08 <label>
+26 m4 @0x0000000051765bd0 04 7f add $0x7f %al -> %al
+28 m4 @0x000000005171e8e8 9e sahf %ah
+29 m4 @0x000000005171dc40 65 48 a1 18 00 00 00 mov %gs:0x18[8byte] -> %rax
00 00 00 00
+40 m4 @0x0000000051765800 <label>
+40 m4 @0x000000005171e070 65 48 89 0c 25 10 00 mov %rcx -> %gs:0x10[8byte]
00 00
+49 m4 @0x0000000051765ad0 59 pop %rsp (%rsp)[8byte] -> %rcx %rsp
+50 L4 @0x00000000517205f8 e9 fb 4a f9 ff jmp $0x00000000516af500 <shared_bb_ibl_ret>
END 0x00007fbff7a2ccb2
Fragment 76, tag 0x00007fbff7a2ccb2, flags 0x1000030, shared, size 55:
0x00000000516b7100 65 48 a3 18 00 00 00 mov %rax -> %gs:0x18[8byte]
00 00 00 00
0x00000000516b710b 9f lahf -> %ah
0x00000000516b710c 0f 90 c0 seto -> %al
0x00000000516b710f f0 81 05 8a c8 94 20 lock add $0x00000001 <rel> 0x00000000720039a4[4byte] -> <rel> 0x00000000720039a4[4byte]
01 00 00 00
0x00000000516b711a 04 7f add $0x7f %al -> %al
0x00000000516b711c 9e sahf %ah
0x00000000516b711d 65 48 a1 18 00 00 00 mov %gs:0x18[8byte] -> %rax
00 00 00 00
0x00000000516b7128 65 48 89 0c 25 10 00 mov %rcx -> %gs:0x10[8byte]
00 00
0x00000000516b7131 59 pop %rsp (%rsp)[8byte] -> %rcx %rsp
0x00000000516b7132 e9 c9 83 ff ff jmp $0x00000000516af500 <shared_bb_ibl_ret>
-------- exit stub 0: -------- <target: 0x00000000516af500> type: ret
<no stub created since linked>

The final listing is a disassembly of that fragment in the code cache.