Trace output

Example instruction trace output

This is an example from inside the Obey module with the debug options for 'traceregionfunc', 'traceswiargs' and 'trace'.

S[||                      :  381fd38: PUSH    {r1, r2, r3, r4}
S[|||                     :  381fd3c: ADR     r0, &0381FC7C             ; -> "Obey$Dir"
S[|||                     :  381fd40: ADD     r1, sp, #&10              ; R13 = &04107b84
S[|||                     :  381fd44: MOV     r2, #0
S[|||                     :  381fd48: MOV     r3, #0
S[|||                     :  381fd4c: MOV     r4, #0
S[|||                     :  381fd50: SWI     XOS_SetVarVal
S[|||                     :  381fd50: SWI     XOS_SetVarVal
S[|||                     :           => r0  = &0381fc7c   58850428  pointer to string var
S[|||                     :                    "Obey$Dir"
S[|||                     :              r1  = &04107b94   68189076  pointer to value
S[|||                     :                    "$.python3.!SharedLibs"
S[|||                     :              r2  = &00000000          0  size
S[|||                     :              r3  = &00000000          0  context
S[|||                     :              r4  = &00000000          0  var_type
S[|||                     :           <= r3  = &04109884   68196484  context_out
S[|||                     :                    "Obey$Dir"
S[|||                     :              r4  = &00000000          0  var_type_out
S[|||                     :  381fd54: POP     {r1, r2, r3, r4}
S[||                      :  381fd58: ADD     sp, sp, #&400             ; R13 = &04107b94

^ ^^^^^^^^^^^^^^^^^^^^^^^   ^^^^^^^^  ^^^^^^^ ^^^^^^^^^^^^^^^^^^          ^^^^^^^^^^^
M            SL                PC      INST           ARG                    STATE

M - The mode currently executing:

SL - The stack level, which increases the bars as there are is more on the stack. As data is taken off the stack, the bars will reduce.

PC - The execution address being considered in this log system.

INST - The mnemonic for the instruction, which might be slightly different from the standard RISC OS format which ARM used to use. In the example the STMFD and LDMFD instructions are represented by PUSH and POP.

ARG - Parameters for the instruction.

STATE - the state of the registers before the instruction was executed. The state is decoded before we run the instruction, and only considers the source registers in the instruction. Instructions like ADR are decoded into either a string or a representation of the block being referenced. If a decimal constant is used, this will be displayed, and a character value if there is one.

In the middle of the execution there is a SWI instruction, which is listed twice. The first is the disassembly as the instruction is about to be executed, and then this is repeated when it is executed, together with the registers for the SWI. In this case, the registers are understood in the trace, and only those which are needed are listed. In SWIs for which the registers are not known, all the registers will be listed.

The registers are listed in the hex and decimal formats, and given a description. These descriptions are taken from the SWI definitions supplied with OSLib. If the contents of the register can be decoded, a following line will describe the value. In the example the value of r0 is a pointer to a string, so the string is shown.

Exception information

If an exception occurs, the output will report the exception data into the trace. For example:

 [|||                     :  85023d0: MOV     r1, #0
 [|||                     :  85023d4: STR     r1, [r0, #8]              ; R1 = &00000000, R0 = &5776843c
==== Begin exception report ====
Exception triggered: Exception 'Data Abort'
  r0  = &5776843c, r1  = &00000000, r2  = &57768434, r3  = &00000000
  r4  = &041094b4, r5  = &08555874, r6  = &00008d88, r7  = &00008be8
  r8  = &085022fc, r9  = &00008be8, r10 = &57768654, r11 = &000143d8
  r12 = &000143d8, sp  = &5b8718f0, lr  = &084063d4, pc  = &085023dc
  CPSR= &20000010 : USR-32 ARM fi ae qvCzn
==== End exception report ====

In this case, because the 'trace' option was enabled, the full disassembly of each instruction showed what the registers were when the STR happened - which then caused the data abort, and all the registers were reported.

In the register dump the CPSR is shown both as a value and broken down into the various flags. The mode, the instruction format, the interrupt mask, the execution flags, and the condition flags, are all shown. For the flags, a lower case letter indicates an unset flag, and a capital indicates a set flag.

When the processor is in a privileged mode, the SPSR value is also included in the dump.

If the 'trace' option is not enabled, and therefore we are not stepping every instruction, the preceding disassembly won't be present in the trace output, but the exception report will still be generated if any other debug is enabled. If the 'block level' tracing has been triggered (which happens for the option 'traceregionfunc', which shows the function names as code is entered), the exception report will then list the code in the blocks that were executed recently:

==== Begin exception report ====
Exception triggered: Exception 'Data Abort'
  r0  = &5779bcea, r1  = &00000000, r2  = &5779bce2, r3  = &00000000
  r4  = &041094b4, r5  = &08555874, r6  = &00008d88, r7  = &00008be8
  r8  = &085022fc, r9  = &00008be8, r10 = &5779bf02, r11 = &000143d8
  r12 = &000143d8, sp  = &5b8a519e, lr  = &084063d4, pc  = &085023d8
  CPSR= &20000010 : USR-32 ARM fi ae qvCzn
Recently executed code:
    ---- Block &0840701c, 3 instructions ----
     840701c: LDRB    r1, [r1, #&c]
     8407020: TST     r1, #&f                   ; #15
     8407024: BNE     &08407070
    ---- Block &08502364, 23 instructions ----
     8502364: STR     r1, [r11, #&2c]
     8502368: LDR     r1, [r11, #&10]
     850236c: STR     r1, [r11, #&18]
     8502370: STR     r1, [r11, #&1c]
     8502374: LDR     sp, [r11, #4]
     8502378: SUB     sp, sp, #8
     850237c: STR     sp, [r12, #&5c]
     8502380: SUB     sp, sp, #&1000
     8502384: ADD     r10, sp, #&200
     8502388: STR     r10, [r12, #&58]
     850238c: SUB     sp, sp, #8
     8502390: LDR     r4, &08502704             ; = &00001800
     8502394: LDR     r4, [r7, r4]
     8502398: TEQ     r4, #0
     850239c: LDRNE   r4, [r4]
     85023a0: MOVEQ   r4, #&1000                ; #4096
     85023a4: CMP     r4, #&1000                ; #4096
     85023a8: MOVLT   r4, #&1000                ; #4096
     85023ac: SUB     r0, sp, r4
     85023b0: ADD     r10, r0, #&218
     85023b4: SUBS    r2, r0, #8
     85023b8: MOVMI   r0, #0
     85023bc: BMI     &08502724                 ; -> Function: __exit_with_error_num
    ---- Block &085023c0, 4 instructions ----
     85023c0: STR     r2, [r11, #8]
     85023c4: CMP     r2, r1
     85023c8: MOVLO   r0, #0
     85023cc: BLO     &08502724                 ; -> Function: __exit_with_error_num
    ---- Block &085023d0, 12 instructions ----
     85023d0: MOV     r1, #0
     85023d4: STR     r1, [r0, #8]
     85023d8: STR     r1, [r0, #4]
     85023dc: STR     r1, [r0, #&10]
     85023e0: STR     r1, [r0, #&14]
     85023e4: LDR     r1, &08502A48             ; = &f60690ff
     85023e8: STR     r1, [r0]
     85023ec: STR     r4, [r0, #&c]
     85023f0: MOV     r4, r12
     85023f4: ADR     r0, &08502750             ; -> [&0081a43f, &75646f4d, &4320656c, &416c6c61]
     85023f8: MOV     r1, r0
     85023fc: MOV     r12, #&2b                 ; #43  = '+'
==== End exception report ====

The elided section (...) is just for this documentation to reduce the length of the dump; there are other blocks in that location.

In this dump the code leading up to the failure is shown, and the block that is shown last is known to contain the instruction that failed - not all of that block may have been executed.

Function and region entry

With the 'traceregionfunc' option, the trace will detect entry to functions and produce a report before beginning execution. Here's an example from the SOManager and a command is executed:

S[|                       :  381fec0: SWIVC   XOS_CLI
S[|                       :  381fec0: SWI     XOS_CLI
S[|                       :           => r0  = &0700a990  117483920  pointer to string command
S[|                       :                    "SOMRun $.sizes"
S[|                       :  7003670: {DA 'Module area', module 'SOManager': Entry Command SOMRun}
S[||                      :  7003670: MOV     r2, #4
S[||                      :  7003674: B       &0700367C
S[||                      :  700367c: {DA 'Module area', module 'SOManager'}
S[||                      :  700367c: PUSH    {r0, r10, r11, lr}
S[|||                     :  7003680: MOV     r10, sp, LSR #20          ; R13 = &04107f30
S[|||                     :  7003684: MOV     r10, r10, LSL #20         ; R10 = &00000041
S[|||                     :  7003688: LDMIA   r10, {r4, r5}             ; R10 = &04100000
S[|||                     :  700368c: MOV     r3, r12                   ; R12 = &070021cc
S[|||                     :  7003690: LDR     r12, [r12]                ; R12 = &070021cc
S[|||                     :  7003694: LDMIB   r12, {r11, r12}           ; R12 = &07009228
S[|||                     :  7003698: STMIA   r10, {r11, r12}           ; R10 = &04100000
S[|||                     :  700369c: ADD     r10, r10, #&21c           ; R10 = &04100000
S[|||                     :  70036a0: MOV     r11, #0
S[|||                     :  70036a4: BL      &0700609C                 ; -> Function: module_command
S[|||                     :  700609c: {DA 'Module area', module 'SOManager': Function module_command}
S[|||                     : Function: module_command
S[|||                     :   r0  = &070021dc, r1  = &00000001, r2  = &00000004, r3  = &070021cc
S[|||                     :   r4  = &00000000, r5  = &00000000, r6  = &00000000, r7  = &00000000
S[|||                     :   r8  = &00000000, r9  = &00000000, r10 = &0410021c, r11 = &00000000
S[|||                     :   r12 = &0000003c, sp  = &04107f30, lr  = &070036a8, pc  = &0700609c
S[|||                     :   CPSR= &60000013 : SVC-32 ARM fi ae qvCZn
S[|||                     :   SPSR= &00000000 : USR-26 ARM fi ae qvczn
S[|||                     :  700609c: MOV     r12, sp                   ; Function: module_command  ; R13 = &04107f30
S[|||                     :  70060a0: PUSH    {r4, r5, r6, r7, r8, r11, r12, lr, pc}

The first instruction listed is the caller (a part of the Obey module), which issues a SWIVC instruction. We then get the SWI details (from 'traceswiregs'), and the SWI is listed without the condition code, because we're actually running the SWI now. The code then enters the SOManager module, at the entry point for the command 'SOMRun', for which the entry is described with {braces}. The SVC stack has been updated by the SWI call, so an extra bar is added.

We then continue into the CMHG veneer for the C module command. After we push more registers on to the stack, the stack level gains another bar. These levels help to indicate how nested we are, and allow skimming forward to find where the return from a routine happens.

We reach the branch (BL) to the actual code, which has a comment saying what the function would be - if the instruction had been conditional we would still know what it didn't do.

The function is recognised, and the {braces} show that we've entered a new region. It then explicitly dumps the function name, and the current registers. Because we're in SVC mode the SPSR is also included, BUT we're in the middle of execution - and there's a problem with the current model that we cannot get the SPSR whilst the system is executing, so the value is 0 (oh well).

Finally we get to the function prologue which moves sp to r12. This instruction is annotated to say that this is the first instruction of the function, and what the R13 value is.

Block repetition

Where possible the disassembly will attempt to elide repetition of instruction blocks. The decoding of all the parameters and disassembly can be very expensive, and the log can fill to hundreds of megabytes. After a number of executions of the same block (currently configured as 16, but this is changeable), the trace will stop reporting the individual instructions until a new block is executed. The additional executions of the addresses are listed just as a 'REPEAT' of the range. The number of executions is listed.

 [||||||||                :  8406eac: MOVLS   r12, r12, LSL #1          ; R12 = &0004a000
 [||||||||                :  8406eb0: CMP     r12, r5, lsr #1           ; R12 = &00094000, R5 = &07902248
 [||||||||                :  8406eb4: BLS     &08406EAC
 [||||||||                :  8406eac: MOVLS   r12, r12, LSL #1          ; R12 = &00094000
 [||||||||                :  8406eb0: CMP     r12, r5, lsr #1           ; R12 = &00128000, R5 = &07902248
 [||||||||                :  8406eb4: BLS     &08406EAC
 [||||||||                :  8406eac: MOVLS   r12, r12, LSL #1          ; R12 = &00128000
 [||||||||                :  8406eb0: CMP     r12, r5, lsr #1           ; R12 = &00250000, R5 = &07902248
 [||||||||                :  8406eb4: BLS     &08406EAC
 [||||||||                :  8406eb8: REPEAT  &08406eac - &08406eb4  5 times


Watchpoints are configurable, and can trap reads and writes of specific addresses in memory. Here is an example:

S[|||||||||||||||         :  3810efc: LDMDB   r1!, {r3, r4, r12, lr}    ; R1 = &0700c910
S[|||||||||||||||         :  3810f00: STMDB   r0!, {r3, r4, r12, lr}    ; R0 = &0840bb90
S[|||||||||||||||         :  3810f00: <WATCH> WRITE [&0840bb80] = &00000001  (word)
S[|||||||||||||||         :             r0  = &0840bb90, r1  = &0700c900, r2  = &00000b58, r3  = &00000001
S[|||||||||||||||         :             r4  = &0000006a, r5  = &0840b018, r6  = &00007d18, r7  = &00000d18
S[|||||||||||||||         :             r8  = &ffffffff, r9  = &00000001, r10 = &0410021c, r11 = &04107e08
S[|||||||||||||||         :             r12 = &80000f94, sp  = &04107df4, lr  = &000010c4, pc  = &03810f00
S[|||||||||||||||         :             CPSR= &20000013 : SVC-32 ARM fi ae qvCzn
S[|||||||||||||||         :             SPSR= &00000000 : USR-26 ARM fi ae qvczn

The address &840bb80 has a watchpoint present, and the STMDB instruction causes a write to that address. The value that is being written is displayed, together with the size of the access (in this case a word write). The registers are also included at this point as this may help in diagnosing what is going on. Watchpoints don't need to have block or even instruction level debugging enabled, so if the 'trace' option had not been enabled, the preceding instructions would not be shown, and the PC and registers would hopefully help to narrow the issue.


Tracepoints are configurable, and can trap the execution of specific addresses in memory. Here is an example (without a stack indication, for clarity):

 7002f58: <TRACE> CObey:Fortify_Deallocate
            r0  = &07008c00, r1  = &00000001, r2  = &07001c2c, r3  = &00000191
            r4  = &07008c00, r5  = &00000001, r6  = &07009c00, r7  = &00000000
            r8  = &00000000, r9  = &07009c28, r10 = &07008e20, r11 = &07009ba8
            r12 = &0700213c, sp  = &07009b80, lr  = &07001c10, pc  = &07002f58
            CPSR= &20000010 : USR-32 ARM fi ae qvCzn
            pc is DA 'Module area', module 'CObey': Function Fortify_Deallocate+&0
            lr is DA 'Module area', module 'CObey': Function close_obey+&dc
          C backtrace:
             7002f58 function close_obey
                     Arg1: &07008c00   117476352    [&070073e0, &037d917c, &000002a8, &a7a7a7a7]
                     Arg2: &00000001           1    
             7001f74 function process_lines
                     Arg1: &07008c00   117476352    [&070073e0, &037d917c, &000002a8, &a7a7a7a7]
             700251c function exit_handlerC
                     Arg1: &07008c00   117476352    [&070073e0, &037d917c, &000002a8, &a7a7a7a7]
          Recently executed code:
            ---- Block &07006608, 2 instructions ----
             7006608: {DA 'Module area', module 'CObey'}
             7006608: MOV     r12, lr
             700660c: SWI     XOS_ChangeEnvironment
            ---- Block &07006610, 1 instructions ----
             7006610: BVS     &0700663C
            ---- Block &07006614, 11 instructions ----
             7006614: LDR     lr, [sp]
             7006618: TEQ     lr, #0
             700661c: STRNE   r1, [lr]
             7006620: LDR     lr, [sp, #4]
             7006624: TEQ     lr, #0
             7006628: STRNE   r2, [lr]
             700662c: LDR     lr, [sp, #8]
             7006630: TEQ     lr, #0
             7006634: STRNE   r3, [lr]
             7006638: MOV     r0, #0
             700663c: MOV     pc, r12
            ---- Block &0700213c, 1 instructions ----
             700213c: LDMDB   r11, {r11, sp, pc}
            ---- Block &07001bf4, 2 instructions ----
             7001bf4: TEQ     r5, #0
             7001bf8: BEQ     &07001C10
            ---- Block &07001bfc, 1 instructions ----
             7001bfc: MOV     r0, r4
            ---- Block &07001c00, 4 instructions ----
             7001c00: ADR     r1, &07001C11
             7001c04: MOV     r2, #&91                  ; #145
             7001c08: ADD     r2, r2, #&100
             7001c0c: BL      &07005BB0
            ---- Block &07005bb0, 2 instructions ----
             7005bb0: TEQ     r0, #0
             7005bb4: MOVEQ   pc, lr
            ---- Block &07005bb8, 4 instructions ----
             7005bb8: MOV     r3, r2
             7005bbc: MOV     r2, r1
             7005bc0: MOV     r1, #1
             7005bc4: B       &07002F58                 ; -> Function: Fortify_Deallocate
            ---- Block &07002f58, 16 instructions ----
            Function: Fortify_Deallocate
             7002f58: MOV     r12, sp                   ; Function: Fortify_Deallocate
             7002f5c: PUSH    {r0, r1, r2, r3, r4, r5, r6, r7, r8, r9, r11, r12, lr, pc}
             7002f60: SUB     r11, r12, #4
             7002f64: MOV     r9, r0
             7002f68: MOV     r5, r2
             7002f6c: MOV     r4, r3
             7002f70: AND     r7, r1, #&ff
             7002f74: SUB     r6, r0, #&50
             7002f78: MOV     r8, r6
             7002f7c: LDR     r0, &07002A44             ; = &0700717c
             7002f80: LDR     r12, [r10, #-&218]
             7002f84: ADD     r0, r12, r0
             7002f88: LDRB    r0, [r0, #&1c]
             7002f8c: TEQ     r0, #0
             7002f90: MOV     r0, r6
             7002f94: BEQ     &07002FEC

The tracepoint was configured with the string module:CObey:Fortify_Deallocate. When the first instruction of the function (as recognised by its function signature) is about to be executed, the above report is issued. This includes:

The tracepoints themselves are a comma-separated list of either addresses of specification strings which describe the functions that should be trapped. The following specifications are supported:

<function-pattern> may be either a function name as given in a function signature, or a * wildcarded version of such a function name. For example, the specification Fortify_* would match all functions which start with the string Fortify_, in any module or the application space.