Trace improvments #2011

jbech-linaro · 2017-12-15T08:35:06Z

So this is a continuation of what we have discussed here. I've kept commit message etc the same, I'm going to update then we have agreed on the output and when I'm about to squash it. I've also fixed the symbolize.py script, but I couldn't see that there was any need to update the documentation about it(?).

jbech-linaro · 2017-12-15T08:36:09Z

mk/config.mk

@@ -61,6 +61,12 @@ CFG_TEE_TA_LOG_LEVEL ?= 1
 # CFG_TEE_TA_LOG_LEVEL. Otherwise, they are not output at all
 CFG_TEE_CORE_TA_TRACE ?= y

+# When "y", the current thread will be shown
+CFG_TRACE_THREAD_ID ?= y


I removed this in the review commit moving thread id, if we decide to keep that format, then this should also be removed.

jforissier · 2017-12-15T08:37:52Z

About doc updates: there are a number of places where we show examples of trace outputs, including here: https://github.com/OP-TEE/build/blob/master/docs/debug.md#3-abort-dumps-panics.

jbech-linaro · 2017-12-15T08:48:07Z

lib/libutils/ext/trace.c

@@ -92,34 +91,31 @@ void trace_printf(const char *function, int line, int level, bool level_ok,
 		thread_id = trace_ext_get_thread_id();

 	if (thread_id >= 0) {
-		res = snprintk(buf + boffs, sizeof(buf) - boffs, "[0x%x] ",
+		res = snprintk(buf + boffs, sizeof(buf) - boffs, "%d",


So, this is the change going from my initial proposal:
<type>/<where> [<thread_id>] [<func:line>] <message>
to
<type><thread_id><where> [<func:line>] <message>

I don't really like baking the thread_id into the print. Even though it save a few characters, it makes the OP-TEE debug messages too dynamic. I.e., we get something like this

D0TC gic_it_set_cpu_mask:270 cpu_mask: 0x0 D0TC gic_it_set_prio:283 prio: writing 0x1 to 0x11d00428 D0TC context_init:101 0 reader detected ITC Initialized D0TC init_primary_helper:853 Primary CPU switching to normal world boot ITC Dynamic shared memory is enabled D0TC core_mmu_alloc_l2:249 L2 table used: 4/4 D0TC tee_ta_init_pseudo_ta_session:292 Lookup pseudo TA 484d4143-2d53-4841-3120-4a6f636b6542 D0TC tee_ta_init_user_ta_session:636 Lookup user TA 484d4143-2d53-4841-3120-4a6f636b6542 (REE) D0TC ta_load:316 ELF load address 0x101000 DTA register_shared_key:147 Got shared key 12345678901234567890 (20 bytes). E0TC E0TC TA panicked with code 0x0 E0TC Status of TA 484d4143-2d53-4841-3120-4a6f636b6542 (0xe07ba50) (active) E0TC arch: arm load address: 0x101000 ctx-idr: 1 E0TC stack: 0x100000 4096 E0TC region 0: va 0x100000 pa 0xe31d000 size 0x1000 flags rw- E0TC region 1: va 0x101000 pa 0xe300000 size 0xf000 flags r-x E0TC region 2: va 0x110000 pa 0xe30f000 size 0x3000 flags r-- E0TC region 3: va 0x113000 pa 0xe312000 size 0xb000 flags rw- E0TC region 4: va 0 pa 0 size 0 flags --- E0TC region 5: va 0 pa 0 size 0 flags --- E0TC region 6: va 0 pa 0 size 0 flags --- E0TC region 7: va 0 pa 0 size 0 flags --- E0TC Call stack: E0TC 0x001044a8 E0TC 0x0010ba0d E0TC 0x00101397 E0TC 0x00101545 E0TC 0x0010441b E0TC 0x00104477 D0TC user_ta_enter:452 tee_user_ta_enter: TA panicked with code 0x0 D0TC tee_ta_invoke_command:649 Error: ffff3024 of 3 D0TC tee_ta_close_session:402 tee_ta_close_session(0xe07be98) D0TC tee_ta_close_session:421 Destroy session D0TC tee_ta_close_session:447 Destroy TA ctx

compared to this in the initial patch

D/TC [00] gic_it_set_cpu_mask:270 cpu_mask: 0x0 D/TC [00] gic_it_set_prio:283 prio: writing 0x1 to 0x11d00428 D/TC [00] context_init:101 0 reader detected I/TC Initialized D/TC [00] init_primary_helper:853 Primary CPU switching to normal world boot I/TC Dynamic shared memory is enabled D/TC [00] core_mmu_alloc_l2:249 L2 table used: 4/4 D/TC [00] tee_ta_init_pseudo_ta_session:292 Lookup pseudo TA 484d4143-2d53-4841-3120-4a6f636b6542 D/TC [00] tee_ta_init_user_ta_session:636 Lookup user TA 484d4143-2d53-4841-3120-4a6f636b6542 (REE) D/TC [00] ta_load:316 ELF load address 0x101000 D/TA register_shared_key:147 Got shared key 12345678901234567890 (20 bytes). E/TC [00] E/TC [00] TA panicked with code 0x0 E/TC [00] Status of TA 484d4143-2d53-4841-3120-4a6f636b6542 (0xe07ba50) (active) E/TC [00] arch: arm load address: 0x101000 ctx-idr: 1 E/TC [00] stack: 0x100000 4096 E/TC [00] region 0: va 0x100000 pa 0xe31d000 size 0x1000 flags rw- E/TC [00] region 1: va 0x101000 pa 0xe300000 size 0xf000 flags r-x E/TC [00] region 2: va 0x110000 pa 0xe30f000 size 0x3000 flags r-- E/TC [00] region 3: va 0x113000 pa 0xe312000 size 0xb000 flags rw- E/TC [00] region 4: va 0 pa 0 size 0 flags --- E/TC [00] region 5: va 0 pa 0 size 0 flags --- E/TC [00] region 6: va 0 pa 0 size 0 flags --- E/TC [00] region 7: va 0 pa 0 size 0 flags --- E/TC [00] Call stack: E/TC [00] 0x001044a8 E/TC [00] 0x0010ba11 E/TC [00] 0x00101397 E/TC [00] 0x00101545 E/TC [00] 0x0010441b E/TC [00] 0x00104477 D/TC [00] user_ta_enter:452 tee_user_ta_enter: TA panicked with code 0x0 D/TC [00] tee_ta_invoke_command:649 Error: ffff3024 of 3 D/TC [00] tee_ta_close_session:402 tee_ta_close_session(0xe07be98) D/TC [00] tee_ta_close_session:421 Destroy session D/TC [00] tee_ta_close_session:447 Destroy TA ctx

I would like to go with the latter, since I think that make OP-TEE debug messages more distinct (and it also make regexp grep less complicated whenever that is needed, symbolize.py, HAB-test etc). I.e, I want to remove/revert the [review]: Move thread ID patch again.

My proposal was to print a / when thread ID wasn't available to keep the positions constant with or without thread id available. Also only one digit is needed for the thread ID.
I think it's pretty useless to be able to not print the thread ID if it's available as that's important debug information.
If I'd have to chose between knowing loglevel + trace_ext_prefix versus thread ID the choice would be easy.

I think the thread id is easier to catch from the 2nd format: E/TC [<thread-id>] ...

So, what about something in-between our proposals?
E/TC:0
or
E/TC 0

That reduces it quite a bit but still keeps the original patch "prefix". This way the regexp in symbolize doesn't have to care about the number of characters for thread_id's and the same when searching for patterns from our test environment.

Sure, but I don't see the problem with updating the regexp.
By the way, what do you propose to print when thread ID isn't available?

One character doesn't take into account more than 10 cores (D02 has 16).

So, can we decide whether we shall have a single or two digits? My initial proposal was two, but I've hearing back and forth. Shall we say two digits again then?

In that case it'd look like this

D/TC:00 init_canaries:171 watch *0xe085dfc D/TC:00 init_canaries:173 #Stack canaries for stack_thread[0] with top at 0xe087e38 D/TC:00 init_canaries:173 watch *0xe087e3c D/TC:00 init_canaries:173 #Stack canaries for stack_thread[1] with top at 0xe089e78 D/TC:00 init_canaries:173 watch *0xe089e7c I/TC: OP-TEE version: 2.6.0-99-gea475ccd-dev #5 Fri Dec 15 10:53:26 UTC 2017 arm D/TC:00 tee_ta_register_ta_store:608 Registering TA store: 'REE' (priority 10) D/TC:00 mobj_mapped_shm_init:579 Shared memory address range: e300000, 10300000 D/TC:00 gic_it_set_cpu_mask:266 cpu_mask: writing 0xff to 0x11d00828 D/TC:00 gic_it_set_cpu_mask:270 cpu_mask: 0x0 D/TC:00 gic_it_set_prio:283 prio: writing 0x1 to 0x11d00428 D/TC:00 context_init:101 0 reader detected I/TC: Initialized D/TC:00 init_primary_helper:853 Primary CPU switching to normal world boot I/TC: Dynamic shared memory is enabled

The number of cores is not directly connected to the number of threads.
Since this is a hard coded number we could use one or two digits depending on the number of configured threads.

Ok, everyone happy with that (I think it's overkill, but ...)? I'll add some ifdefs in the code and sort it out.

jbech-linaro · 2017-12-15T08:52:11Z

About doc updates: there are a number of places where we show examples of trace outputs, including here: https://github.com/OP-TEE/build/blob/master/docs/debug.md#3-abort-dumps-panics.

Ah, yes of course, I didn't think about the output examples, I was just looking at the text itself, I'll fix.

jenswi-linaro · 2017-12-15T08:50:25Z

lib/libutils/ext/trace.c

-	static const char lvl_strs[][9] = {
-		"UNKNOWN:", "ERROR:  ", "INFO:   ", "DEBUG:  ",
-		"FLOW:   " };
+	static const char lvl_strs[][2] = {


This could be an array of chars instead of an array of strings if "MESSAGE:" below was exchanged for 'M'

jenswi-linaro · 2017-12-15T08:59:49Z

lib/libutils/ext/trace.c

@@ -92,34 +91,31 @@ void trace_printf(const char *function, int line, int level, bool level_ok,
 		thread_id = trace_ext_get_thread_id();

 	if (thread_id >= 0) {
-		res = snprintk(buf + boffs, sizeof(buf) - boffs, "[0x%x] ",
+		res = snprintk(buf + boffs, sizeof(buf) - boffs, "%d",


My proposal was to print a / when thread ID wasn't available to keep the positions constant with or without thread id available. Also only one digit is needed for the thread ID.
I think it's pretty useless to be able to not print the thread ID if it's available as that's important debug information.
If I'd have to chose between knowing loglevel + trace_ext_prefix versus thread ID the choice would be easy.

etienne-lms · 2017-12-15T09:18:46Z

scripts/symbolize.py

+# function trace_level_to_string(...), i.e., this is the UEIDF below, then we
+# have the thread ID and either TA or TC, finally we have the actual address. A
+# line typically look like this:
+# E0TC  0x1234abcd


What if one get dozen of thread. I thought about the big multi-core presented at last connect.

Use two digits (and // when no thread id)?

etienne-lms · 2017-12-15T09:19:18Z

mk/config.mk

+CFG_TRACE_THREAD_ID ?= y
+
+# When "y", the function and line will be shown
+CFG_TRACE_FUNCTION ?= y


Should one really want to remove such info from the traces? The xMSG_RAW() is used when func/line is useless.

What do you mean Etienne? For the first question, yes I often want to remove that function and line. Are you saying that we can get rid of func:line in some other way when building or am I misunderstanding you here?

CFG_MSG_LONG_PREFIX_MASK = 0

https://github.com/OP-TEE/optee_os/blob/master/mk/config.mk#L73-L78

Right, that was the one I was referring to in my first patch in this serie in the commit message that works but it's not very user friendly (I wrote CFG_MSG_LONG_PREFIX_THRESHOLD, which I can't even find in the code now, but it was that mask I had in mind). Even after reading that comment a couple of times I find it hard to follow. I guess each bit represents long message (bit=1) for this bit field |0:none|1:error|2:info|3:debug|4:flow|? So the 0x1a (0b11010) means, long on flow, debug and error? But sure, it does the job, so I can live with the bit field (to remember ...MASK = 0 is easy).

etienne-lms · 2017-12-15T09:22:06Z

lib/libutils/ext/trace.c

@@ -92,34 +91,31 @@ void trace_printf(const char *function, int line, int level, bool level_ok,
 		thread_id = trace_ext_get_thread_id();

 	if (thread_id >= 0) {
-		res = snprintk(buf + boffs, sizeof(buf) - boffs, "[0x%x] ",
+		res = snprintk(buf + boffs, sizeof(buf) - boffs, "%d",


I think the thread id is easier to catch from the 2nd format: E/TC [<thread-id>] ...

jbech-linaro · 2017-12-15T11:18:20Z

Pushed a commit putting the prefix in the way that I think (?) that we agreed upon. Now I need to update symbolize and fix the other comments too.

jbech-linaro · 2017-12-15T11:44:24Z

lib/libutils/ext/trace.c

+		boffs += res;
+	} else {
+		/* If there is no thread ID, then fill in with blanks */
+		res = snprintk(buf + boffs, sizeof(buf) - boffs, "   ");


This will also needs an update to "line up".

jenswi-linaro · 2017-12-15T12:00:04Z

lib/libutils/ext/trace.c

+		boffs += res;
+	} else {
+		/* If there is no thread ID, then fill in with blanks */
+		res = snprintk(buf + boffs, sizeof(buf) - boffs, "   ");


The thread id printing could be simplified (and correct with regards to the number of blanks) with a helper function like this:

static int print_thread_id(char *buf, size_t bs, int thread_id) { #if CFG_NUM_THREADS > 9 int num_thread_digits = 2; #else int num_thread_digits = 1; #endif if (thread_id >= 0) return snprintk(buf, bs, "%0*d", num_thread_digits, thread_id); else return snprintk(buf, bs, "%*s", num_thread_digits, ""); }

jbech-linaro · 2017-12-15T12:32:19Z

I think I've fixed all issue in this git, so if people are happy with it, I'll squash it to two patches (and cleanup the commit message). Next is to update the stuff in build.git.

jenswi-linaro · 2017-12-15T13:02:59Z

Reviewed-by: Jens Wiklander <jens.wiklander@linaro.org>

etienne-lms

some minor comments, Reviewed-by Etienne Carriere <etienne.carriere@linaro.org> even if not addressed.

etienne-lms · 2017-12-15T12:55:02Z

lib/libutils/ext/trace.c

-		"UNKNOWN:", "ERROR:  ", "INFO:   ", "DEBUG:  ",
-		"FLOW:   " };
+	static const char lvl_strs[] = {
+		'U', 'E', 'I', 'D', 'F' };


minor: fits in 1 line.
Or for clarity use an explicit:

static const char lvl_strs[] = { [0] = 'U', [TRACE_ERROR] = 'E', [TRACE_INFO] = 'I', [TRACE_DEBUG] = 'D', [TRACE_FLOW] = 'F', };

etienne-lms · 2017-12-15T13:10:47Z

scripts/symbolize.py

+
+# This gets the address from lines looking like this:
+# E/TC:0  0x001044a8
+STACK_ADDR_RE = re.compile(r'[UEIDF]/T[AC]:.*(?P<addr>0x[0-9a-f]+)')


Add M to [UEIDF]

The new format for traces are: <type>/<where>:<thread_id> [<func:line>] <message> <type>: D = DEBUG E = ERROR I = INFO F = FLOW <where>: TA = Trusted Application TC = TEE Core I.e, it outputs messages like this: D/TC:00 ta_load:316 ELF load address 0x101000 etc Thread ID will either take a single or two digits depending on the number of threads in use. Signed-off-by: Joakim Bech <joakim.bech@linaro.org> Reviewed-by: Jens Wiklander <jens.wiklander@linaro.org> Reviewed-by: Etienne Carriere <etienne.carriere@linaro.org>

Update the regular expression finding the call stack addresses to match the new trace format. Signed-off-by: Joakim Bech <joakim.bech@linaro.org> Reviewed-by: Jens Wiklander <jens.wiklander@linaro.org> Reviewed-by: Etienne Carriere <etienne.carriere@linaro.org>

jbech-linaro · 2017-12-15T14:13:16Z

Squashed, rebased and tag(s) applied (should be) ready for merge! Thanks!
(related OP-TEE/build#220)

jbech-linaro commented Dec 15, 2017

View reviewed changes

jenswi-linaro reviewed Dec 15, 2017

View reviewed changes

etienne-lms reviewed Dec 15, 2017

View reviewed changes

jbech-linaro commented Dec 15, 2017

View reviewed changes

jenswi-linaro reviewed Dec 15, 2017

View reviewed changes

etienne-lms reviewed Dec 15, 2017

View reviewed changes

jbech-linaro added 2 commits December 15, 2017 14:28

jbech-linaro force-pushed the trace_improvments branch from c7e5017 to 63fd32b Compare December 15, 2017 13:42

jbech-linaro mentioned this pull request Dec 15, 2017

docs: update debug.md to match the new trace output OP-TEE/build#220

Merged

jforissier merged commit a2b984b into OP-TEE:master Dec 15, 2017

jbech-linaro deleted the trace_improvments branch December 15, 2017 14:51

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Trace improvments #2011

Trace improvments #2011

jbech-linaro commented Dec 15, 2017

jbech-linaro Dec 15, 2017 •

edited

Loading

jforissier commented Dec 15, 2017

jbech-linaro Dec 15, 2017 •

edited

Loading

jenswi-linaro Dec 15, 2017

etienne-lms Dec 15, 2017

jbech-linaro Dec 15, 2017

jenswi-linaro Dec 15, 2017

jforissier Dec 15, 2017

jbech-linaro Dec 15, 2017 •

edited

Loading

jbech-linaro Dec 15, 2017

jenswi-linaro Dec 15, 2017

jbech-linaro Dec 15, 2017

jbech-linaro commented Dec 15, 2017

jenswi-linaro Dec 15, 2017

jenswi-linaro Dec 15, 2017

etienne-lms Dec 15, 2017

jenswi-linaro Dec 15, 2017

etienne-lms Dec 15, 2017

jbech-linaro Dec 15, 2017

jforissier Dec 15, 2017 •

edited

Loading

jbech-linaro Dec 15, 2017

etienne-lms Dec 15, 2017

jbech-linaro commented Dec 15, 2017

jbech-linaro Dec 15, 2017

jenswi-linaro Dec 15, 2017

jbech-linaro commented Dec 15, 2017

jenswi-linaro commented Dec 15, 2017

etienne-lms left a comment

etienne-lms Dec 15, 2017

etienne-lms Dec 15, 2017

jbech-linaro commented Dec 15, 2017

Trace improvments #2011

Trace improvments #2011

Conversation

jbech-linaro commented Dec 15, 2017

jbech-linaro Dec 15, 2017 • edited Loading

Choose a reason for hiding this comment

jforissier commented Dec 15, 2017

jbech-linaro Dec 15, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jbech-linaro Dec 15, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jbech-linaro commented Dec 15, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jforissier Dec 15, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jbech-linaro commented Dec 15, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jbech-linaro commented Dec 15, 2017

jenswi-linaro commented Dec 15, 2017

etienne-lms left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jbech-linaro commented Dec 15, 2017

jbech-linaro Dec 15, 2017 •

edited

Loading

jbech-linaro Dec 15, 2017 •

edited

Loading

jbech-linaro Dec 15, 2017 •

edited

Loading

jforissier Dec 15, 2017 •

edited

Loading