:authors: Jason Lowe-Power .. _debugging-chapter: ------------------------------------------ Debugging gem5 ------------------------------------------ In the :ref:`previous chapters ` we covered how to create a very simple SimObject. In this chapter, we will replace the simple print to ``stdout`` with gem5's debugging support. gem5 provides support for ``printf``-style tracing/debugging of your code via *debug flags*. These flags allow every component to have many debug-print statements, without all of them enabled at the same time. When running gem5, you can specify which debug flags to enable from the command line. Using debug flags ~~~~~~~~~~~~~~~~~ For instance, when running the first simple.py script from :ref:`simple-config-chapter`, if you enable the ``DRAM`` debug flag, you get the following output. Note that this generates *a lot* of output to the console (about 7 MB). .. code-block:: sh build/X86/gem5.opt --debug-flags=DRAM configs/learning_gem5/part1/simple.py | head -n 50 :: gem5 Simulator System. http://gem5.org DRAM device capacity (gem5 is copyrighted software; use the --copyright option for details. gem5 compiled Jan 3 2017 16:03:38 gem5 started Jan 3 2017 16:09:53 gem5 executing on chinook, pid 19223 command line: build/X86/gem5.opt --debug-flags=DRAM configs/learning_gem5/part1/simple.py Global frequency set at 1000000000000 ticks per second 0: system.mem_ctrl: Memory capacity 536870912 (536870912) bytes 0: system.mem_ctrl: Row buffer size 8192 bytes with 128 columns per row buffer 0: system.remote_gdb.listener: listening for remote gdb #0 on port 7000 Beginning simulation! info: Entering event queue @ 0. Starting simulation... 0: system.mem_ctrl: recvTimingReq: request ReadReq addr 400 size 8 0: system.mem_ctrl: Read queue limit 32, current size 0, entries needed 1 0: system.mem_ctrl: Address: 400 Rank 0 Bank 0 Row 0 0: system.mem_ctrl: Read queue limit 32, current size 0, entries needed 1 0: system.mem_ctrl: Adding to read queue 0: system.mem_ctrl: Request scheduled immediately 0: system.mem_ctrl: Single request, going to a free rank 0: system.mem_ctrl: Timing access to addr 400, rank/bank/row 0 0 0 0: system.mem_ctrl: Activate at tick 0 0: system.mem_ctrl: Activate bank 0, rank 0 at tick 0, now got 1 active 0: system.mem_ctrl: Access to 400, ready at 46250 bus busy until 46250. 46250: system.mem_ctrl: processRespondEvent(): Some req has reached its readyTime 46250: system.mem_ctrl: number of read entries for rank 0 is 0 46250: system.mem_ctrl: Responding to Address 400.. 46250: system.mem_ctrl: Done 77000: system.mem_ctrl: recvTimingReq: request ReadReq addr 400 size 8 77000: system.mem_ctrl: Read queue limit 32, current size 0, entries needed 1 77000: system.mem_ctrl: Address: 400 Rank 0 Bank 0 Row 0 77000: system.mem_ctrl: Read queue limit 32, current size 0, entries needed 1 77000: system.mem_ctrl: Adding to read queue 77000: system.mem_ctrl: Request scheduled immediately 77000: system.mem_ctrl: Single request, going to a free rank 77000: system.mem_ctrl: Timing access to addr 400, rank/bank/row 0 0 0 77000: system.mem_ctrl: Access to 400, ready at 101750 bus busy until 101750. 101750: system.mem_ctrl: processRespondEvent(): Some req has reached its readyTime 101750: system.mem_ctrl: number of read entries for rank 0 is 0 101750: system.mem_ctrl: Responding to Address 400.. 101750: system.mem_ctrl: Done 132000: system.mem_ctrl: recvTimingReq: request ReadReq addr 400 size 8 132000: system.mem_ctrl: Read queue limit 32, current size 0, entries needed 1 132000: system.mem_ctrl: Address: 400 Rank 0 Bank 0 Row 0 132000: system.mem_ctrl: Read queue limit 32, current size 0, entries needed 1 132000: system.mem_ctrl: Adding to read queue 132000: system.mem_ctrl: Request scheduled immediately 132000: system.mem_ctrl: Single request, going to a free rank 132000: system.mem_ctrl: Timing access to addr 400, rank/bank/row 0 0 0 132000: system.mem_ctrl: Access to 400, ready at 156750 bus busy until 156750. 156750: system.mem_ctrl: processRespondEvent(): Some req has reached its readyTime 156750: system.mem_ctrl: number of read entries for rank 0 is 0 Or, you may want to debug based on the exact instruction the CPU is executing. For this, the ``Exec`` debug flag may be useful. This debug flags shows details of how each instruction is executed by the simulated CPU. .. code-block:: sh build/X86/gem5.opt --debug-flags=Exec configs/learning_gem5/part1/simple.py | head -n 50 :: gem5 Simulator System. http://gem5.org gem5 is copyrighted software; use the --copyright option for details. gem5 compiled Jan 3 2017 16:03:38 gem5 started Jan 3 2017 16:11:47 gem5 executing on chinook, pid 19234 command line: build/X86/gem5.opt --debug-flags=Exec configs/learning_gem5/part1/simple.py Global frequency set at 1000000000000 ticks per second 0: system.remote_gdb.listener: listening for remote gdb #0 on port 7000 warn: ClockedObject: More than one power state change request encountered within the same simulation tick Beginning simulation! info: Entering event queue @ 0. Starting simulation... 77000: system.cpu T0 : @_start : xor rbp, rbp 77000: system.cpu T0 : @_start.0 : XOR_R_R : xor rbp, rbp, rbp : IntAlu : D=0x0000000000000000 132000: system.cpu T0 : @_start+3 : mov r9, rdx 132000: system.cpu T0 : @_start+3.0 : MOV_R_R : mov r9, r9, rdx : IntAlu : D=0x0000000000000000 187000: system.cpu T0 : @_start+6 : pop rsi 187000: system.cpu T0 : @_start+6.0 : POP_R : ld t1, SS:[rsp] : MemRead : D=0x0000000000000001 A=0x7fffffffee30 250000: system.cpu T0 : @_start+6.1 : POP_R : addi rsp, rsp, 0x8 : IntAlu : D=0x00007fffffffee38 250000: system.cpu T0 : @_start+6.2 : POP_R : mov rsi, rsi, t1 : IntAlu : D=0x0000000000000001 360000: system.cpu T0 : @_start+7 : mov rdx, rsp 360000: system.cpu T0 : @_start+7.0 : MOV_R_R : mov rdx, rdx, rsp : IntAlu : D=0x00007fffffffee38 415000: system.cpu T0 : @_start+10 : and rax, 0xfffffffffffffff0 415000: system.cpu T0 : @_start+10.0 : AND_R_I : limm t1, 0xfffffffffffffff0 : IntAlu : D=0xfffffffffffffff0 415000: system.cpu T0 : @_start+10.1 : AND_R_I : and rsp, rsp, t1 : IntAlu : D=0x0000000000000000 470000: system.cpu T0 : @_start+14 : push rax 470000: system.cpu T0 : @_start+14.0 : PUSH_R : st rax, SS:[rsp + 0xfffffffffffffff8] : MemWrite : D=0x0000000000000000 A=0x7fffffffee28 491000: system.cpu T0 : @_start+14.1 : PUSH_R : subi rsp, rsp, 0x8 : IntAlu : D=0x00007fffffffee28 546000: system.cpu T0 : @_start+15 : push rsp 546000: system.cpu T0 : @_start+15.0 : PUSH_R : st rsp, SS:[rsp + 0xfffffffffffffff8] : MemWrite : D=0x00007fffffffee28 A=0x7fffffffee20 567000: system.cpu T0 : @_start+15.1 : PUSH_R : subi rsp, rsp, 0x8 : IntAlu : D=0x00007fffffffee20 622000: system.cpu T0 : @_start+16 : mov r15, 0x40a060 622000: system.cpu T0 : @_start+16.0 : MOV_R_I : limm r8, 0x40a060 : IntAlu : D=0x000000000040a060 732000: system.cpu T0 : @_start+23 : mov rdi, 0x409ff0 732000: system.cpu T0 : @_start+23.0 : MOV_R_I : limm rcx, 0x409ff0 : IntAlu : D=0x0000000000409ff0 842000: system.cpu T0 : @_start+30 : mov rdi, 0x400274 842000: system.cpu T0 : @_start+30.0 : MOV_R_I : limm rdi, 0x400274 : IntAlu : D=0x0000000000400274 952000: system.cpu T0 : @_start+37 : call 0x9846 952000: system.cpu T0 : @_start+37.0 : CALL_NEAR_I : limm t1, 0x9846 : IntAlu : D=0x0000000000009846 952000: system.cpu T0 : @_start+37.1 : CALL_NEAR_I : rdip t7, %ctrl153, : IntAlu : D=0x00000000004001ba 952000: system.cpu T0 : @_start+37.2 : CALL_NEAR_I : st t7, SS:[rsp + 0xfffffffffffffff8] : MemWrite : D=0x00000000004001ba A=0x7fffffffee18 973000: system.cpu T0 : @_start+37.3 : CALL_NEAR_I : subi rsp, rsp, 0x8 : IntAlu : D=0x00007fffffffee18 973000: system.cpu T0 : @_start+37.4 : CALL_NEAR_I : wrip , t7, t1 : IntAlu : 1042000: system.cpu T0 : @__libc_start_main : push r15 1042000: system.cpu T0 : @__libc_start_main.0 : PUSH_R : st r15, SS:[rsp + 0xfffffffffffffff8] : MemWrite : D=0x0000000000000000 A=0x7fffffffee10 1063000: system.cpu T0 : @__libc_start_main.1 : PUSH_R : subi rsp, rsp, 0x8 : IntAlu : D=0x00007fffffffee10 1118000: system.cpu T0 : @__libc_start_main+2 : movsxd rax, rsi 1118000: system.cpu T0 : @__libc_start_main+2.0 : MOVSXD_R_R : sexti rax, rsi, 0x1f : IntAlu : D=0x0000000000000001 1173000: system.cpu T0 : @__libc_start_main+5 : mov r15, r9 1173000: system.cpu T0 : @__libc_start_main+5.0 : MOV_R_R : mov r15, r15, r9 : IntAlu : D=0x0000000000000000 1228000: system.cpu T0 : @__libc_start_main+8 : push r14 In fact, the ``Exec`` flag is actually an agglomeration of multiple debug flags. You can see this, and all of the available debug flags, by running gem5 with the ``--debug-help`` parameter. .. code-block:: sh build/X86/gem5.opt --debug-help :: Base Flags: Activity: None AddrRanges: None Annotate: State machine annotation debugging AnnotateQ: State machine annotation queue debugging AnnotateVerbose: Dump all state machine annotation details BaseXBar: None Branch: None Bridge: None CCRegs: None CMOS: Accesses to CMOS devices Cache: None CachePort: None CacheRepl: None CacheTags: None CacheVerbose: None Checker: None Checkpoint: None ClockDomain: None ... Compound Flags: AnnotateAll: All Annotation flags Annotate, AnnotateQ, AnnotateVerbose CacheAll: None Cache, CachePort, CacheRepl, CacheVerbose, HWPrefetch DiskImageAll: None DiskImageRead, DiskImageWrite ... XBar: None BaseXBar, CoherentXBar, NoncoherentXBar, SnoopFilter XBar: None BaseXBar, CoherentXBar, NoncoherentXBar, SnoopFilter Adding a new debug flag ~~~~~~~~~~~~~~~~~~~~~~~ In the :ref:`previous chapters `, we used a simple ``std::cout`` to print from our SimObject. While it is possible to use the normal C/C++ I/O in gem5, it is highly discouraged. So, we are now going to replace this and use gem5's debugging facilities instead. When creating a new debug flag, we first have to declare it in a SConscript file. Add the following to the SConscript file in the directory with your hello object code (src/learning_gem5/). .. code-block:: python DebugFlag('Hello') This declares a debug flag of "Hello". Now, we can use this in debug statements in our SimObject. By declaring the flag in the SConscript file, a debug header is automatically generated that allows us to use the debug flag. The header file is in the ``debug`` directory and has the same name (and capitalization) as what we declare in the SConscript file. Therefore, we need to include the automatically generated header file in any files where we plan to use the debug flag. In the ``hello_object.cc`` file, we need to include the header file. .. code-block:: c++ #include "debug/Hello.hh" Now that we have included the necessary header file, let's replace the ``std::cout`` call with a debug statement like so. .. code-block:: c++ DPRINTF(Hello, "Created the hello object\n"); ``DPRINTF`` is a C++ macro. The first parameter is a *debug flag* that has been declared in a SConscript file. We can use the flag ``Hello`` since we declared it in the ``src/learning_gem5/SConscript`` file. The rest of the arguments are variable and can be anything you would pass to a ``printf`` statement. Now, if you recompile gem5 and run it with the "Hello" debug flag, you get the following result. .. code-block:: sh build/X86/gem5.opt --debug-flags=Hello configs/learning_gem5/part2/run_hello.py :: gem5 Simulator System. http://gem5.org gem5 is copyrighted software; use the --copyright option for details. gem5 compiled Jan 4 2017 09:40:10 gem5 started Jan 4 2017 09:41:01 gem5 executing on chinook, pid 29078 command line: build/X86/gem5.opt --debug-flags=Hello configs/learning_gem5/part2/run_hello.py Global frequency set at 1000000000000 ticks per second 0: hello: Created the hello object Beginning simulation! info: Entering event queue @ 0. Starting simulation... Exiting @ tick 18446744073709551615 because simulate() limit reached You can find the updated SConcript file :download:`here <../_static/scripts/part2/debugging/SConscript>` and the updated hello object code :download:`here <../_static/scripts/part2/debugging/hello_object.cc>`. Debug output ~~~~~~~~~~~~ For each dynamic ``DPRINTF`` execution, three things are printed to ``stdout``. First, the current tick when the ``DPRINTF`` is executed. Second, the *name of the SimObject* that called ``DPRINTF``. This name is usually the Python variable name from the Python config file. However, the name is whatever the SimObject ``name()`` function returns. Finally, you see whatever format string you passed to the ``DPRINTF`` function. You can control where the debug output goes with the ``--debug-file`` parameter. By default, all of the debugging output is printed to ``stdout``. However, you can redirect the output to any file. The file is stored relative to the main gem5 output directory, not the current working directory. Using functions other than DPRINTF ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ ``DPRINTF`` is the most commonly used debugging function in gem5. However, gem5 provides a number of other functions that are useful in specific circumstances. .. cpp:function:: DPRINTF(Flag, __VA_ARGS__) Takes a flag, and a format string plus any format parameters. This function requires that there is a name() function in the current scope (e.g., called from a SimObject member function). Prints the formatted string only when the **Flag** is enabled. .. cpp:function:: DTRACE(Flag) Returns true if the flag (**Flag**) is enabled, false otherwise. This is useful for executing some code only when a debug flag (**Flag**) is enabled. .. cpp:function:: DDUMP(Flag, data, count) Prints binary data (**data**) of length **count** bytes. This is formatted in hex in a user-readable way. This macro also assumes that the calling scope contains a name() function. .. cpp:function:: DPRINTFS(Flag, SimObject, __VA_ARGS__) Like :cpp:func:`DPRINTF` except takes an extra parameter which is an object that has a name() function, usually a SimObject. This function is useful for using debugging from a private subclass of a SimObject that has a pointer to its owner. .. cpp:function:: DPRINTFR(Flag, __VA_ARGS__) This function outputs debug statements without printing a name. This is useful for using debug statements in object that are not SimObjects that do not have a name() function. .. cpp:function:: DDUMPN(data, count) DPRINTFN(__VA_ARGS__) DPRINTFNR(__VA_ARGS__) These functions are like the previous functions :cpp:func:`DDUMP`, :cpp:func:`DPRINTF`, and :cpp:func:`DPRINTFR` except they do not take a flag as a parameter. Therefore, these statements will *always* print whenever debugging is enabled. All of these functions are only enabled if you compile gem5 in "opt" or "debug" mode. All other modes use empty placeholder macros for the above functions. Therefore, if you want to use debug flags, you must use either "gem5.opt" or "gem5.debug".