![[Burning Cog]](../icons/pyromaniac.png){kind=icon}
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:
- S => SVC
- [space] => USR
- A => ABT
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
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
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
Locations:
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:
- Information about the registers at the time of execution
- Relative locations of the PC and LR registers, and other registers that appear to be pointers.
- A backtrace of the C code that was executing at the time (this may not be available where C backtrace cannot be determined)
- A dump of the recently executed code up to this point, including the block of code that is about to be executed.
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>- matches the function pattern in any module, or dynamic area containing code (only the Application space at present).module:<module>:<function-pattern>- matches the function pattern, but only in a specific module.area:<area-name>:<function-pattern>- matches the function pattern in a specific dynamic area.@:<function-pattern>- matches the function pattern in the application space.
A <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.