CODECOMPOSER: Core trace decoding issues on AM64x R5f

Dominic Rath

Part Number: CODECOMPOSER

Dear TI team,

I'm trying to use the CCS core trace feature to analyze some hard-to-catch crashes / bugs. I'm currently on CCS 12.0, but I've seen this issue in previous versions (e.g. CCS 10.x, 11.x that were required for earlier MCU+ SDK versions).

I believe that in the past (AM65x, PDK, TI-RTOS, GCC) this was okay-ish. The function/file/lineno information wasn't always 100% correct, but it was mostly good enough.

I'm pretty sure that since we switched to AM64x (MCU+ SDK, FreeRTOS, ti-cgt-armllvm) the decoded trace information mostly lacks the function/file/lineno information and displays n/a instead.

What's a lot worse though is that it apparently doesn't even correctly decode the executed instructions.

In this case for example the core trace tells me that it executed instruction past the "bx lr" at the end of a function:

313981,0x700A0300,0x0000E7FF,n/a,,n/a,n/a,313980,
313982,0x700A0302,0x00009803,n/a,,n/a,n/a,313981,
313983,0x700A0304,0xF6447168,n/a,,n/a,n/a,313982,
313984,0x700A0308,0xF2C7010A,n/a,,n/a,n/a,313983,
313985,0x700A030C,0x00006809,n/a,,n/a,n/a,313984,
313986,0x700A030E,0x00003118,n/a,,n/a,n/a,313985,
313987,0x700A0310,0xF7FFFBFE,n/a,,n/a,n/a,313986,
313988,0x7009FB10,0x0000B084,n/a,,n/a,n/a,313987,
313989,0x7009FB12,0x00009003,n/a,,n/a,n/a,313988,
313990,0x7009FB14,0x00009102,n/a,,n/a,n/a,313989,
313991,0x7009FB16,0x00009802,n/a,,n/a,n/a,313990,
313992,0x7009FB18,0x00006800,n/a,,n/a,n/a,313991,
313993,0x7009FB1A,0x00009000,n/a,,n/a,n/a,313992,
313994,0x7009FB1C,0x00009800,n/a,,n/a,n/a,313993,
313995,0x7009FB1E,0x00003001,n/a,,n/a,n/a,313994,
313996,0x7009FB20,0x0000B920,n/a,,n/a,n/a,313995,
313997,0x7009FB22,0x0000E7FF,n/a,,n/a,n/a,313996,
313998,0x7009FB24,0x00009803,n/a,,n/a,n/a,313997,
313999,0x7009FB26,0x00006900,n/a,,n/a,n/a,313998,
314000,0x7009FB28,0x00009001,n/a,,n/a,n/a,313999,
314001,0x7009FB2A,0x0000E010,n/a,,n/a,n/a,314000,
314002,0x7009FB4E,0x00009801,n/a,,n/a,n/a,314001,
314003,0x7009FB50,0x00006840,n/a,,n/a,n/a,314002,
314004,0x7009FB52,0x00009902,n/a,,n/a,n/a,314003,
314005,0x7009FB54,0x00006048,n/a,,n/a,n/a,314004,
314006,0x7009FB56,0x00009802,n/a,,n/a,n/a,314005,
314007,0x7009FB58,0x00006841,n/a,,n/a,n/a,314006,
314008,0x7009FB5A,0x00006088,n/a,,n/a,n/a,314007,
314009,0x7009FB5C,0x00009801,n/a,,n/a,n/a,314008,
314010,0x7009FB5E,0x00009902,n/a,,n/a,n/a,314009,
314011,0x7009FB60,0x00006088,n/a,,n/a,n/a,314010,
314012,0x7009FB62,0x00009802,n/a,,n/a,n/a,314011,
314013,0x7009FB64,0x00009901,n/a,,n/a,n/a,314012,
314014,0x7009FB66,0x00006048,n/a,,n/a,n/a,314013,
314015,0x7009FB68,0x00009803,n/a,,n/a,n/a,314014,
314016,0x7009FB6A,0x00009902,n/a,,n/a,n/a,314015,
314017,0x7009FB6C,0x00006108,n/a,,n/a,n/a,314016,
314018,0x7009FB6E,0x00009903,n/a,,n/a,n/a,314017,
314019,0x7009FB70,0x00006808,n/a,,n/a,n/a,314018,
314020,0x7009FB72,0x00003001,n/a,,n/a,n/a,314019,
314021,0x7009FB74,0x00006008,n/a,,n/a,n/a,314020,
314022,0x7009FB76,0x0000B004,n/a,,n/a,n/a,314021,
314023,0x7009FB78,0x00004770,n/a,,n/a,n/a,314022,
314024,0x7009FB7A,0x00000000,n/a,,n/a,n/a,314023,
314025,0x7009FB7C,0x00000000,n/a,,n/a,n/a,314024,
314026,0x7009FB7E,0x00000000,n/a,,n/a,n/a,314025,

This is a part of the disassembly (return somewhere in vTaskPlaceOnEventList from a previous branch-and-link, a call to vListInsert and that function's execution):

700a02d0 <vTaskPlaceOnEventList>:
...
700a0300: ff e7        	b	0x700a0302 <vTaskPlaceOnEventList+0x32> @ imm = #-2
700a0302: 03 98        	ldr	r0, [sp, #12]
700a0304: 44 f6 68 71  	movw	r1, #20328
700a0308: c7 f2 0a 01  	movt	r1, #28682
700a030c: 09 68        	ldr	r1, [r1]
700a030e: 18 31        	adds	r1, #24
700a0310: ff f7 fe fb  	bl	0x7009fb10 <vListInsert> @ imm = #-2052

7009fb10 <vListInsert>:
7009fb10: 84 b0        	sub	sp, #16
7009fb12: 03 90        	str	r0, [sp, #12]
7009fb14: 02 91        	str	r1, [sp, #8]
7009fb16: 02 98        	ldr	r0, [sp, #8]
7009fb18: 00 68        	ldr	r0, [r0]
7009fb1a: 00 90        	str	r0, [sp]
7009fb1c: 00 98        	ldr	r0, [sp]
7009fb1e: 01 30        	adds	r0, #1
7009fb20: 20 b9        	cbnz	r0, 0x7009fb2c <vListInsert+0x1c> @ imm = #8
7009fb22: ff e7        	b	0x7009fb24 <vListInsert+0x14> @ imm = #-2
7009fb24: 03 98        	ldr	r0, [sp, #12]
7009fb26: 00 69        	ldr	r0, [r0, #16]
7009fb28: 01 90        	str	r0, [sp, #4]
7009fb2a: 10 e0        	b	0x7009fb4e <vListInsert+0x3e> @ imm = #32
7009fb2c: 03 98        	ldr	r0, [sp, #12]
7009fb2e: 08 30        	adds	r0, #8
7009fb30: 01 90        	str	r0, [sp, #4]
7009fb32: ff e7        	b	0x7009fb34 <vListInsert+0x24> @ imm = #-2
7009fb34: 01 98        	ldr	r0, [sp, #4]
7009fb36: 40 68        	ldr	r0, [r0, #4]
7009fb38: 00 68        	ldr	r0, [r0]
7009fb3a: 00 99        	ldr	r1, [sp]
7009fb3c: 88 42        	cmp	r0, r1
7009fb3e: 05 d8        	bhi	0x7009fb4c <vListInsert+0x3c> @ imm = #10
7009fb40: ff e7        	b	0x7009fb42 <vListInsert+0x32> @ imm = #-2
7009fb42: ff e7        	b	0x7009fb44 <vListInsert+0x34> @ imm = #-2
7009fb44: 01 98        	ldr	r0, [sp, #4]
7009fb46: 40 68        	ldr	r0, [r0, #4]
7009fb48: 01 90        	str	r0, [sp, #4]
7009fb4a: f3 e7        	b	0x7009fb34 <vListInsert+0x24> @ imm = #-26
7009fb4c: ff e7        	b	0x7009fb4e <vListInsert+0x3e> @ imm = #-2
7009fb4e: 01 98        	ldr	r0, [sp, #4]
7009fb50: 40 68        	ldr	r0, [r0, #4]
7009fb52: 02 99        	ldr	r1, [sp, #8]
7009fb54: 48 60        	str	r0, [r1, #4]
7009fb56: 02 98        	ldr	r0, [sp, #8]
7009fb58: 41 68        	ldr	r1, [r0, #4]
7009fb5a: 88 60        	str	r0, [r1, #8]
7009fb5c: 01 98        	ldr	r0, [sp, #4]
7009fb5e: 02 99        	ldr	r1, [sp, #8]
7009fb60: 88 60        	str	r0, [r1, #8]
7009fb62: 02 98        	ldr	r0, [sp, #8]
7009fb64: 01 99        	ldr	r1, [sp, #4]
7009fb66: 48 60        	str	r0, [r1, #4]
7009fb68: 03 98        	ldr	r0, [sp, #12]
7009fb6a: 02 99        	ldr	r1, [sp, #8]
7009fb6c: 08 61        	str	r0, [r1, #16]
7009fb6e: 03 99        	ldr	r1, [sp, #12]
7009fb70: 08 68        	ldr	r0, [r1]
7009fb72: 01 30        	adds	r0, #1
7009fb74: 08 60        	str	r0, [r1]
7009fb76: 04 b0        	add	sp, #16
7009fb78: 70 47        	bx	lr
7009fb7a: 00 00        	movs	r0, r0
7009fb7c: 00 00        	movs	r0, r0
7009fb7e: 00 00        	movs	r0, r0

I believe (one of) the reason(s) trace decoding fails more often now than in the past is that a lot of MCU+ SDK code is now compiled as Thumb code, whereas before it was mostly/all ARM code.

I've dumped the ETB content and decoded it using OpenCSD:

Idx:65211; ID:10; OCSD_GEN_TRC_ELEM_ADDR_NACC( 0x700a0300 )
Idx:65211; ID:10; OCSD_GEN_TRC_ELEM_ADDR_UNKNOWN()
Idx:65212; ID:10; [0xbc ];	P_HDR : Atom P-header.; EEEEEEEEEEEEEEE
Idx:65213; ID:10; [0xbc ];	P_HDR : Atom P-header.; EEEEEEEEEEEEEEE
Idx:65214; ID:10; [0x90 ];	P_HDR : Atom P-header.; EEEE
Idx:65216; ID:10; [0x15 ];	BRANCH_ADDRESS : Branch address.; Addr=0x700A0314 ~[0x14]; 
Idx:65217; ID:10; [0xbc ];	P_HDR : Atom P-header.; EEEEEEEEEEEEEEE
Idx:65217; ID:10; OCSD_GEN_TRC_ELEM_ADDR_NACC( 0x700a0314 )

Starting at address 0x700a0300 the code executed 49 instructions until it returned to address 0x700a0314, with no instructions "not executed" (which would be denoted as a 'N' instead of an 'E', e.g. "Atom P-header.; EEEN")::

7 instructions within vTaskPlaceOnEventList until the branch to vListInsert
9 instructions from 0x7009fb10 to 0x7009fb20, at which point a conditional branch is taken
- the core trace pretends that execution continued after that with instruction 7009fb24, which I believe is wrong
10 instructions from 0x7009fb2c to 0x7009fb3e, at which point a conditional branch is taken
23 instructions from 0x7009fb4c to 0x7009fb78, at which point the function returns via "bx lr"
- the core trace pretends that after the "bx lr" execution continued execution at address 0x7009fb7a to 0x7009fb84

The core trace also decodes 49 instructions starting at 0x700a0300 until it resumes at 0x700a0314, but it apparently ignores all the conditional branches and "takes" only the unconditional branches.

I'm pretty sure that core trace fails to decode the conditional thumb mode branches.
I'm only guessing that the inability to decode function/file/line started with the switch to cgt-arm-llvm.
Are these known issues? Are there fixes for this otherwise very helpful feature planned?

Best Regards,

Dominic

over 2 years ago

0 Tushar Thakur over 2 years ago

TI__Mastermind 49358 points

Hi Dominic,

Thanks for your query and sorry for delayed response. I have taken your inputs and looking into it. Please except some delays in answering your query. Thanks for your patience.

Thanks & regards,

Tushar Thakur

0 Ki over 2 years ago

TI__Guru**** 464431 points

Hello Dominic,

Dominic Rath said:
I'm currently on CCS 12.0

I'm assuming you are using TVT to visualize and export the trace data to a *.csv file. TVT has had several issues in the past with properly associating correct file/function/line information. I believe some if these issues have been resolved in the current latest CCS version (CCS 12.2.0). Could you give that version a try and see if that helps?

Thanks

0 Dominic Rath over 2 years ago in reply to Ki

Mastermind 7450 points

Hello Ki,

I've got to admit that I have no idea what "TVT" is. I'm using the "Tools -> Code Analysis -> Core Trace" feature. That opens a view "Core Trace" where I can configure the trace and then start it. Once the target stops the trace data is downloaded from the AM64x ETB and displayed in a table. That table was lacking the file/function/line information. From that view I can save the data as .tdf, .csv or .sqlite3. I usually save the data to .csv as soon as possible because the viewer in CCS doesn't seem to be able to handle the 60k-200k lines of trace.

The file/function/line issue appears to be a lot better with CCS 12.2, but it still fails on some addresses where addr2line gives correct results. For example it only shows n/a for all the __aeabi_uldivmod and so on stuff from the compiler support library. I've got a Python script that I run on the CSV files output by CCS/Core Trace that passes every address through addr2line, and that gets me almost complete file/function/line information, so this isn't as much of a problem for met.

The issue with trace addresses being decoded that can't possibly be correct persists though:

Here's some part from the traced execution (this time with CCS 12.2.0):

231325	0x7009D5D0	0xF64040F8	vTaskExitCritical	4364	tasks.c	FreeRTOS-Kernel	231324
231326	0x7009D5D4	0xF2C7000A	vTaskExitCritical	4364	tasks.c	FreeRTOS-Kernel	231325
231327	0x7009D5D8	0x00006800	vTaskExitCritical	4364	tasks.c	FreeRTOS-Kernel	231326
231328	0x7009D5DA	0x0000B168	vTaskExitCritical	4364	tasks.c	FreeRTOS-Kernel	231327
231329	0x7009D5DC	0xF64040B0	vTaskExitCritical	4366	tasks.c	FreeRTOS-Kernel	231328
231330	0x7009D5E0	0xF2C7000A	vTaskExitCritical	4366	tasks.c	FreeRTOS-Kernel	231329
231331	0x7009D5E4	0x00006801	vTaskExitCritical	4366	tasks.c	FreeRTOS-Kernel	231330
231332	0x7009D5E6	0x00006D49	vTaskExitCritical	4366	tasks.c	FreeRTOS-Kernel	231331
231333	0x7009D5E8	0x0000B131	vTaskExitCritical	4366	tasks.c	FreeRTOS-Kernel	231332
231334	0x7009D5EA	0x00006801	vTaskExitCritical	4368	tasks.c	FreeRTOS-Kernel	231333
231335	0x7009D5EC	0x00006D4A	vTaskExitCritical	4368	tasks.c	FreeRTOS-Kernel	231334
231336	0x7009D5EE	0x00003A01	vTaskExitCritical	4368	tasks.c	FreeRTOS-Kernel	231335
231337	0x7009D5F0	0x0000654A	vTaskExitCritical	4368	tasks.c	FreeRTOS-Kernel	231336
231338	0x7009D5F2	0x00006800	vTaskExitCritical	4370	tasks.c	FreeRTOS-Kernel	231337
231339	0x7009D5F4	0x00006D40	vTaskExitCritical	4370	tasks.c	FreeRTOS-Kernel	231338
231340	0x7009D5F6	0x0000B100	vTaskExitCritical	4370	tasks.c	FreeRTOS-Kernel	231339
231341	0x7009D5F8	0x00004770	vTaskExitCritical	4388	tasks.c	FreeRTOS-Kernel	231340
231342	0x7009D5FA	0x0000B662	vTaskExitCritical	4372	tasks.c	FreeRTOS-Kernel	231341
231343	0x7009D5FC	0x00004770	vTaskExitCritical	4388	tasks.c	FreeRTOS-Kernel	231342
231344	0x7009D5FE	0x00000000	n/a		n/a	n/a	231343

This is the corresponding disassembly:

7009d5d0 <vTaskExitCritical>:
7009d5d0: 40 f6 f8 40  	movw	r0, #3320
7009d5d4: c7 f2 0a 00  	movt	r0, #28682
7009d5d8: 00 68        	ldr	r0, [r0]
7009d5da: 68 b1        	cbz	r0, 0x7009d5f8 <vTaskExitCritical+0x28> @ imm = #26
7009d5dc: 40 f6 b0 40  	movw	r0, #3248
7009d5e0: c7 f2 0a 00  	movt	r0, #28682
7009d5e4: 01 68        	ldr	r1, [r0]
7009d5e6: 49 6d        	ldr	r1, [r1, #84]
7009d5e8: 31 b1        	cbz	r1, 0x7009d5f8 <vTaskExitCritical+0x28> @ imm = #12
7009d5ea: 01 68        	ldr	r1, [r0]
7009d5ec: 4a 6d        	ldr	r2, [r1, #84]
7009d5ee: 01 3a        	subs	r2, #1
7009d5f0: 4a 65        	str	r2, [r1, #84]
7009d5f2: 00 68        	ldr	r0, [r0]
7009d5f4: 40 6d        	ldr	r0, [r0, #84]
7009d5f6: 00 b1        	cbz	r0, 0x7009d5fa <vTaskExitCritical+0x2a> @ imm = #0
7009d5f8: 70 47        	bx	lr
7009d5fa: 62 b6        	cpsie i
7009d5fc: 70 47        	bx	lr
7009d5fe: 00 00        	movs	r0, r0

I believe it's obvious that the code couldn't possibly execute addresses 7009d5f8, 7009d5fa, 7009d5fc and 7009d5fe in that order. As I explained in my initial post I've manually decoded all the trace data before (which is a very tedious and time consuming process that I didn't repeat this time), and the raw trace data appeared to be correct and matched the binary. It's just that the "core trace" (or whatever the backend for that is) made mistakes in decoding the trace data when it comes to Thumb-2 conditional branches.

Best Regards,

Dominic

0 Ki over 2 years ago in reply to Dominic Rath

TI__Guru**** 464431 points

Dominic Rath said:
I've got to admit that I have no idea what "TVT" is. I'm using the "Tools -> Code Analysis -> Core Trace" feature.

Yes that would be TVT (Trace Visualization Toolkit):

https://software-dl.ti.com/ccs/esd/documents/users_guide/ccs_debug-main.html#trace-visualization-toolkit

Dominic Rath said:
The file/function/line issue appears to be a lot better with CCS 12.2, but it still fails on some addresses where addr2line gives correct results.

Good to hear 12.2.0 is better. That is my impression also. Note that while several issues were fixed, the bug filed for this issue is still open, indicating that not all the issues are resolved. Hence there are still some outstanding issues which you observed.

Dominic Rath said:
For example it only shows n/a for all the __aeabi_uldivmod and so on stuff from the compiler support library.

content from the compiler support library may have issues depending on how much debug symbol information was in the library that was linked in. TVT would relies on available debug symbols for the executable.

Dominic Rath said:
and the raw trace data appeared to be correct and matched the binary. It's just that the "core trace" (or whatever the backend for that is) made mistakes in decoding the trace data when it comes to Thumb-2 conditional branches.

So the raw data is correct but it is just the values displayed in the Trace viewer and the data exported to a csv file? Yes that would be an issue with TVT in the decoding of the data and how it filled in the gaps for the collected discontinuities. I will need further investigation from the TVT engineers.

Any chance you can also provide the raw data? You can send via private E2E conversation.

Thanks

0 Dominic Rath over 2 years ago in reply to Ki

Mastermind 7450 points

Hello Ki,

sorry it took me a while to get back to this.

Ki said:
Good to hear 12.2.0 is better. That is my impression also. Note that while several issues were fixed, the bug filed for this issue is still open, indicating that not all the issues are resolved. Hence there are still some outstanding issues which you observed.

Unfortunately "better" appears to be a long way from "good". I guess it depends on how exactly the code was compiled, but in my latest trace the TVT mostly failed to identify file/line/function. The attached archives contains two files:

"nested_interrupts_r5fss0-0\Debug\core_trace_until_crash.csv": CSV as exported by TVT, matches what is displayed in the IDE Core Trace View

"nested_interrupts_r5fss0-0\Debug\core_trace_until_crash-annotated.csv": post-processed by my own script that runs every executed address through addr2line

Ki said:
So the raw data is correct but it is just the values displayed in the Trace viewer and the data exported to a csv file? Yes that would be an issue with TVT in the decoding of the data and how it filled in the gaps for the collected discontinuities. I will need further investigation from the TVT engineers.

Any chance you can also provide the raw data? You can send via private E2E conversation.

The attached archive contains the example application that I've created for another thread here on E2E plus CSV's mentioned above and the following files:

"nested_interrupts_r5fss0-0\Debug\core_trace_until_crash_raw_tbr.bin": raw content from TBR that I've manually read using Scripting Console

"nested_interrupts_r5fss0-0\Debug\nested_interrupts_r5fss0-0.txt": disassembled binary

"nested_interrupts_r5fss0-0\Debug\core_trace_until_crash_OpenCSD.txt": OpenCSD output after processing raw TBR content

If you look at line 305132 in the CSV (either the "original" CSV or my "annotated" CSV) and compare the following lines with the disassembly you can easily see that TVT output can't possibly be correct.

Let me know if you have any further questions regarding the test case or any of my files.

Regards,

Dominic

nested_interrupts_r5fss0-0-trace.zip

0 Ki over 2 years ago in reply to Dominic Rath

TI__Guru**** 464431 points

Thank you for providing the files. I will send them to the CCS trace engineers for analysis.

0 Ki over 2 years ago in reply to Dominic Rath

TI__Guru**** 464431 points

Dominic Rath said:
"nested_interrupts_r5fss0-0\Debug\core_trace_until_crash.csv": CSV as exported by TVT, matches what is displayed in the IDE Core Trace View

Did you export a *.tdf file also? I don't see it in the directory. That file would be very helpful also.

Code Composer Studio™︎

Code Composer Studio forum

CODECOMPOSER: Core trace decoding issues on AM64x R5f