Skip to content

Commit

Permalink
[RFC] trace: shorten output and make function and thread optional
Browse files Browse the repository at this point in the history 
This goes a bit in opposite (or complements) the commits [1] and [2]. For
[1] I don't see any strong reason to keep aligned with Arm TF. I think
it is better to have a uniform output within OP-TEE than keeping aligned
with Arm TF and at the same time this save precious space and also makes
it easier to read/find the actual debug message since it aligns up a
bit nicer.

The format now is
<type>/<where> [<thread_id>] [<func:line>] <message>

<type>:
 * D = DEBUG
 * E = ERROR
 * I = INFO
 * F = FLOW

<where>:
 * TA = Trusted Application
 * TC = TEE Core

The CFG_MSG_LONG_PREFIX_THRESHOLD is nice as such, but not very user
friendly when it comes to enable and disable things. I've kept it here,
but I think I would prefer using something like the new CFG_TRACE_...
like propopsed here. In the future we could introduce a "trace psuedo
TA" where one could enable/disable various debug print features. I.e.,
our own little "ftrace psuedo TA".

[1] OP-TEE@f4aa5b1
[2] OP-TEE@2bfab75
  • Loading branch information
@jbech-linaro
jbech-linaro committed Nov 27, 2017
1 parent 947cfee commit 0d3305a
Show file tree
Hide file tree
Showing 4 changed files with 26 additions and 26 deletions.
2 changes: 1 addition & 1 deletion core/arch/arm/kernel/trace_ext.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -31,7 +31,7 @@
#include <kernel/thread.h>
#include <mm/core_mmu.h>

const char trace_ext_prefix[] = "TEE-CORE";
const char trace_ext_prefix[] = "TC";
int trace_level = TRACE_LEVEL;
static unsigned int puts_lock = SPINLOCK_UNLOCK;

Expand Down
38 changes: 18 additions & 20 deletions lib/libutils/ext/trace.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -53,9 +53,8 @@ int trace_get_level(void)

static const char *trace_level_to_string(int level, bool level_ok)
{
static const char lvl_strs[][9] = {
"UNKNOWN:", "ERROR: ", "INFO: ", "DEBUG: ",
"FLOW: " };
static const char lvl_strs[][3] = {
"U/", "E/", "I/", "D/", "F/" };
int l = 0;

if (!level_ok)
Expand All @@ -68,58 +67,57 @@ static const char *trace_level_to_string(int level, bool level_ok)
}

/* Format trace of user ta. Inline with kernel ta */
void trace_printf(const char *function, int line, int level, bool level_ok,
const char *fmt, ...)
void trace_printf(const char __maybe_unused *function, int __maybe_unused line,
int level, bool level_ok, const char *fmt, ...)
{
va_list ap;
char buf[MAX_PRINT_SIZE];
size_t boffs = 0;
int res;
int thread_id;
int __maybe_unused thread_id;

if (level_ok && level > trace_level)
return;

res = snprintk(buf, sizeof(buf), "%s ",
res = snprintk(buf, sizeof(buf), "%s",

This comment has been minimized.

Sign in to view

Copy link
@etienne-lms

etienne-lms Dec 5, 2017

minor: i would rather keep the / here and have lvl_strs as a simple character array.
trace_level_to_string(level, level_ok));
if (res < 0)
return;
boffs += res;

res = snprintk(buf + boffs, sizeof(buf) - boffs, "%s ",
trace_ext_prefix);
if (res < 0)
return;
boffs += res;

#if defined(CFG_TRACE_THREAD_ID)
if (level_ok && !(BIT(level) & CFG_MSG_LONG_PREFIX_MASK))
thread_id = -1;
else
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, "[%02d] ",
thread_id);
if (res < 0)
return;
boffs += res;
}
#endif

res = snprintk(buf + boffs, sizeof(buf) - boffs, "%s:",
trace_ext_prefix);
if (res < 0)
return;
boffs += res;

#if defined(CFG_TRACE_FUNCTION)
if (level_ok && !(BIT(level) & CFG_MSG_LONG_PREFIX_MASK))
function = NULL;

if (function) {
res = snprintk(buf + boffs, sizeof(buf) - boffs, "%s:%d:",
res = snprintk(buf + boffs, sizeof(buf) - boffs, "%s:%d ",
function, line);
if (res < 0)
return;
boffs += res;
}

res = snprintk(buf + boffs, sizeof(buf) - boffs, " ");
if (res < 0)
return;
boffs += res;
#endif

va_start(ap, fmt);
res = vsnprintk(buf + boffs, sizeof(buf) - boffs, fmt, ap);
Expand Down
6 changes: 6 additions & 0 deletions mk/config.mk
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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

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

# If 1, enable debug features in TA memory allocation.
# Debug features include check of buffer overflow, statistics, mark/check heap
# feature.
Expand Down
6 changes: 1 addition & 5 deletions ta/arch/arm/user_ta_header.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -33,11 +33,7 @@

int trace_level = TRACE_LEVEL;

#ifdef TA_LOG_PREFIX
const char trace_ext_prefix[] = TA_LOG_PREFIX;
#else
const char trace_ext_prefix[] = "USER-TA";
#endif
const char trace_ext_prefix[] = "TA";

#ifndef TA_VERSION
#define TA_VERSION "Undefined version"
Expand Down

6 comments on commit 0d3305a

@jenswi-linaro
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I like this.
How about an even more compact format.

When tread info is disabled or if there's no current thread:
<type>/<where> [<func:line>] <message>
else
<type><thread id><where> [<func:line>] <message>

Where <thread id> is a single 0-9 number, more threads than that is unusual

Another thing that relates to this, but doesn't have to be covered in this commit. In fact I haven't even thought it through completely.

When it comes to <func:line>, sometimes it's just what you need in a print and sometimes you'd rather print something else, but together with <func:line> it would be far to much or slightly redundant. So if the was a way to indicate that a certain string is to be used instead of <func:line> or only if <func:line> isn't available I think that could be useful.

@jforissier
Copy link

@jforissier jforissier commented on 0d3305a Dec 5, 2017 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

  • Looks good to me
  • +1 for formatting <thread id> on one digit -- but allow for more because >9 can still happen.
  • Please make sure you're not breaking symbolize.py (I think it should be OK, but needs checking!). The help text of the tool will need updating, at least. The documentation [1] also. Update This does break the script, because there is no column anymore before the stack addresses.
  • What if some users have tools that parse the current format? (any other Linaro team relying on this format?)

[1] https://github.com/OP-TEE/build/blob/master/docs/debug.md#3-abort-dumps-panics

@etienne-lms
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

looks good to me as it simplifies the traces. There is no official definitive trace format so i think it's ok if we break from the current one.

Regarding jens' comment on func/line, it think the xMSG_RAW() is the kind of macro you expect to use for basic, unformatted traces (or very minimal prefixing).

@jforissier
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@jbech-linaro I think it would be good if you would create a PR for this, thanks!

@jbech-linaro
Copy link
Owner Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok, since you seem interested in this, I'll clean it up a bit and send an official PR for it and then we can continue the discussion there.

Please make sure you're not breaking symbolize.py (I think it should be OK, but needs checking!).

I had some issues with that script when trying it when doing the hotp examples. Bascially it seemed like it couldn't find any address at all. So before checking how this affects that script I need to know that I can run it on the current configuration.

@jforissier
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@jbech-linaro sure, you know who to contact for tech support re. symbolize.py ;-)

Please sign in to comment.