Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

zephyr: sof-logger #4503

Merged
merged 6 commits into from
Jul 26, 2021
Merged

zephyr: sof-logger #4503

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
45df060
zephyr_ll.c: declare missing ll_tr trace context
marc-hb Jul 6, 2021
a985f95
cavs/platform.c: don't guard trace initialization with #ifdef ZEPHYR
marc-hb Jul 6, 2021
f787e5d
ipc3/handler.c: re-enable DMA trace for Zephyr
marc-hb Jul 6, 2021
98b55c8
trace: add 'atomic' argument to mtrace_dict_entry()
marc-hb Jul 16, 2021
c8f178f
trace: move CONFIG_TRACEM implementation up a couple levels
marc-hb Jul 16, 2021
5ea6e5b
trace: add _log_nodict() and enable DMA trace for Zephyr
marc-hb Jul 16, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
73 changes: 62 additions & 11 deletions src/include/sof/trace/trace.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -97,6 +97,9 @@ struct trace_filter {

#if CONFIG_TRACE

#include <stdarg.h>
#include <user/trace.h> /* LOG_LEVEL_... */

/*
* trace_event macro definition
*
Expand All @@ -116,6 +119,7 @@ struct trace_filter {
* image size. This way more elaborate log messages are possible and encouraged,
* for better debugging experience, without worrying about runtime performance.
*/

/* Map the different trace_xxxx_with_ids(... ) levels to the
* _trace_event_with_ids(level_xxxx, ...) macro shared across log
* levels.
Expand Down Expand Up @@ -143,10 +147,13 @@ void trace_off(void);
void trace_init(struct sof *sof);

/* All tracing macros in this file end up calling these functions in the end. */
typedef void (*log_func_t)(bool send_atomic, const void *log_entry, const struct tr_ctx *ctx,
uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, va_list args);

void trace_log_filtered(bool send_atomic, const void *log_entry, const struct tr_ctx *ctx,
uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, ...);
uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, va_list args);
void trace_log_unfiltered(bool send_atomic, const void *log_entry, const struct tr_ctx *ctx,
uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, ...);
uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, va_list args);
struct sof_ipc_trace_filter_elem *trace_filter_fill(struct sof_ipc_trace_filter_elem *elem,
struct sof_ipc_trace_filter_elem *end,
struct trace_filter *filter);
Expand All @@ -158,6 +165,20 @@ int trace_filter_update(const struct trace_filter *elem);
#define _trace_event_atomic_with_ids(lvl, class, ctx, id_1, id_2, format, ...) \
_log_message(trace_log_filtered, true, lvl, class, ctx, id_1, id_2, format, ##__VA_ARGS__)

/**
* Appends one SOF dictionary entry and log statement to the ring buffer
* implementing the 'etrace' in shared memory.
*
* @param atomic_context Take the trace->lock if false.
* @param log_entry_pointer dictionary index produced by the
* _DECLARE_LOG_ENTRY macro.
* @param n_args number of va_args
*/
void mtrace_dict_entry(bool atomic_context, uint32_t log_entry_pointer, int n_args, ...);

/** Posts a fully prepared log header + log entry */
void mtrace_event(const char *complete_packet, uint32_t length);

/** The start of this linker output MUST match the 'ldc_entry_header'
* struct defined in the logger program running in user space.
*/
Expand All @@ -183,6 +204,24 @@ int trace_filter_update(const struct trace_filter *elem);
format \
}

#ifdef CONFIG_TRACEM /* Send everything to shared memory too */
# ifdef __ZEPHYR__
/* We don't use Zephyr's dictionary yet so there's not enough space for
* DEBUG messages
*/
# define MTRACE_DUPLICATION_LEVEL LOG_LEVEL_INFO
# else
# define MTRACE_DUPLICATION_LEVEL LOG_LEVEL_DEBUG
# endif
#else /* copy only ERRORS */
# define MTRACE_DUPLICATION_LEVEL LOG_LEVEL_ERROR
#endif /* CONFIG_TRACEM */

/* This function is _not_ passed the format string to save space */
void _log_sofdict(log_func_t sofdict_logf, bool atomic, const void *log_entry,
const struct tr_ctx *ctx, const uint32_t lvl,
uint32_t id_1, uint32_t id_2, int arg_count, ...);

/* _log_message() */

#ifdef CONFIG_LIBRARY
Expand Down Expand Up @@ -222,7 +261,8 @@ _thrown_from_macro_BASE_LOG_in_trace_h

/** _log_message is where the memory-saving dictionary magic described
* above happens: the "format" string argument is moved to a special
* linker section and replaced by a &log_entry pointer to it.
* linker section and replaced by a &log_entry pointer to it. This must
* be a macro for the source location to be meaningful.
*/
#define _log_message(log_func, atomic, lvl, comp_class, ctx, id_1, id_2, format, ...) \
do { \
Expand All @@ -233,9 +273,25 @@ do { \
META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__), \
BASE_LOG_ASSERT_FAIL_MSG \
); \
log_func(atomic, &log_entry, ctx, lvl, id_1, id_2, \
META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__), ##__VA_ARGS__); \
_log_sofdict(log_func, atomic, &log_entry, ctx, lvl, id_1, id_2, \
META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__), ##__VA_ARGS__); \
_log_nodict(atomic, META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__), \
lvl, format, ##__VA_ARGS__); \
} while (0)

#ifdef __ZEPHYR__
/* Just like XTOS, only the most urgent messages go to limited
* shared memory.
*/
#define _log_nodict(atomic, arg_count, lvl, format, ...) \
do { \
if ((lvl) <= MTRACE_DUPLICATION_LEVEL) \
printk("%llu " format "\n", platform_timer_get(NULL), \
##__VA_ARGS__); \
} while (0)
#else
#define _log_nodict(atomic, n_args, lvl, format, ...)
#endif

#endif /* CONFIG_LIBRARY */

Expand Down Expand Up @@ -431,16 +487,11 @@ struct tr_ctx {
too_many_mtrace_printf_arguments); \
_DECLARE_LOG_ENTRY(log_level, format_str, _TRACE_INV_CLASS, \
META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__)); \
mtrace_dict_entry((uint32_t)&log_entry, \
mtrace_dict_entry(true, (uint32_t)&log_entry, \
META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__), \
##__VA_ARGS__); \
} while (0)

/** Adds log_header prefix and appends arguments before sending */
void mtrace_dict_entry(uint32_t log_entry_pointer, int n_args, ...);

/** Posts a fully prepared log header + log entry */
void mtrace_event(const char *complete_packet, uint32_t length);

#else

Expand Down
4 changes: 2 additions & 2 deletions src/ipc/ipc3/handler.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -729,7 +729,7 @@ static int ipc_glb_pm_message(uint32_t header)
/*
* Debug IPC Operations.
*/
#if CONFIG_SUECREEK || defined __ZEPHYR__
#if CONFIG_SUECREEK
static int ipc_dma_trace_config(uint32_t header)
{
return 0;
Expand Down Expand Up @@ -799,7 +799,7 @@ static int ipc_dma_trace_config(uint32_t header)
error:
return err;
}
#endif /* CONFIG_SUECREEK || defined __ZEPHYR__ */
#endif /* CONFIG_SUECREEK */

static int ipc_trace_filter_update(uint32_t header)
{
Expand Down
3 changes: 1 addition & 2 deletions src/platform/intel/cavs/platform.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -505,7 +505,6 @@ int platform_init(struct sof *sof)
if (ret < 0)
return ret;

#ifndef __ZEPHYR__
#if CONFIG_DW_SPI
/* initialize the SPI slave */
trace_point(TRACE_BOOT_PLATFORM_SPI);
Expand All @@ -530,7 +529,7 @@ int platform_init(struct sof *sof)

/* show heap status */
heap_trace_all(1);
#endif /* __ZEPHYR__ */

return 0;
}

Expand Down
6 changes: 6 additions & 0 deletions src/schedule/zephyr_ll.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,12 @@

#include <kernel.h>

/* 1547fe68-de0c-11eb-8461-3158a1294853 */
DECLARE_SOF_UUID("zll-schedule", zll_sched_uuid, 0x1547fe68, 0xde0c, 0x11eb,
0x84, 0x61, 0x31, 0x58, 0xa1, 0x29, 0x48, 0x53);

DECLARE_TR_CTX(ll_tr, SOF_UUID(zll_sched_uuid), LOG_LEVEL_INFO);
Copy link
Contributor

Choose a reason for hiding this comment

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

Can you, please, rename ll_tr to something else, maybe zll_tr.
In i.MX case, we don't want to use zephyr_ll since this is limited to TIMER_DOMAIN (see here) and we are using DMA_DOMAIN.
We want, for now, to keep using ll_schedule.

Therefore, when compiling this, for i.MX, I get: zephyr_ll.c:22: multiple definition of ll_tr;

Copy link
Collaborator Author

@marc-hb marc-hb Jul 21, 2021 •
edited
Loading

Choose a reason for hiding this comment

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

I'd like to help but you're asking me to fix a problem with a configuration that is currently not possible in this branch, probably only on your branch. With this branch there is AFAIK no way to compile ll_schedule.c in Zephyr. After a fair amount of time spent realizing this I tried this naive:

--- a/zephyr/CMakeLists.txt
+++ b/zephyr/CMakeLists.txt
@@ -479,6 +479,7 @@ zephyr_library_sources(
 	${SOF_SRC_PATH}/schedule/schedule.c
 	${SOF_SRC_PATH}/schedule/dma_single_chan_domain.c
 	${SOF_SRC_PATH}/schedule/dma_multi_chan_domain.c
+	${SOF_SRC_PATH}/schedule/ll_schedule.c
 	${SOF_SRC_PATH}/schedule/zephyr_ll.c
 	${SOF_SRC_PATH}/schedule/zephyr.c

... but that does not work because:

sof/src/schedule/zephyr_ll.c:418: multiple definition of `zephyr_ll_task_init'; 
modules/sof/libmodules_sof.a(ll_schedule.c.obj):sof/src/schedule/ll_schedule.c:464: first defined here

sof/src/schedule/zephyr_ll.c:447: multiple definition of `zephyr_ll_scheduler_init';
 modules/sof/libmodules_sof.a(ll_schedule.c.obj):sof/src/schedule/ll_schedule.c:624: first defined here

In other words @lyakh in PR #4377 made zephyr_ll.c and ll_schedule.c somehow mutually exclusive even before this PR does with ll_tr.

Copy link
Collaborator Author

@marc-hb marc-hb Jul 21, 2021 •
edited
Loading

Choose a reason for hiding this comment

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

Forgot this: a simple rename and declaration of DECLARE_TR_CTX(Zll_tr,... in zephyr_ll.c is not possible because ll_tr is used in at least 5 different C files, some shared across both Zephyr and non-Zephyr.

Maybe I can figure out something else but I need to reproduce your problem first, so if you have a way to compile both zephyr_ll.c and ll_schedule.c together please submit it first.

Copy link
Member

Choose a reason for hiding this comment

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

@iuliana-prodan @dbaluta so DMA domain is becoming problematic as it does not scale well to multiple low latency streams (it's simple and great when there is a smaller number of streams though) or when the codec is driving the clocks.
I think we need to improve the DMA driven domain as follows.

Today we have

  1. Zephyr LL gets its LL system tick from the timer. This runs in IRQ context and is non preemtable.
  2. LL system tick wakes up high priority LL thread.
  3. LL thread executes pipeline work.

We need to make one change to support DMA domain here and make it synchronous. Step 1 should also be able to be

  1. Zephyr LL gets its LL system tick from the DMA IRQ. This runs in IRQ context and is non preemtable.

This means we keep the DMA based time domain and we can also scale all LL streams to this time domain.

Fwiw, this is how things worked on OMAP4, the topology would tell FW which DMA channel was to be used as time domain. If the DMA channel stopped then FW had to then use the DMA channel from the next running stream. PR #4471 is allowing the trigger(start|stops) to be synchronised and this would mean that DMA IRQs could also be synchronised.

Copy link
Collaborator Author

@marc-hb marc-hb Jul 21, 2021 •
edited
Loading

Choose a reason for hiding this comment

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

@iuliana-prodan can you please:

  • File a new issue about the longer term DMA domain discussion and solutions so @lgirdwood 's words of wisdom above do not get lost, buried deep down in this unrelated pull request
  • Share a (hopefully simple) draft PR showing how you compile zephyr_ll.c and ll_schedule.c together so I can reproduce the problem specific to your branch. It does not matter to me if that draft never gets merged, I just need a way to reproduce your problem if you would like me to solve it.

Copy link
Contributor

Choose a reason for hiding this comment

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

@lgirdwood @marc-hb I've created a pull request with my fixes for i.MX with Zephyr -see #4524
Now we can run successfully playback and record scenarios with Zephyr.

@lgirdwood until we can extend ll_zephyr with DMA_IRQ (I've created a feature request for this - #4523) we'll be using ll_schedule. Hope it's ok with you.

@marc-hb using my pull request (#4524) and enabling dma-trace you'll run into zephyr_ll.c:22: multiple definition of ll_tr;
That's because in commit 1 I'm adding ll_schedule to be compiled for Zephyr and the zephyr_ll is added mandatory for all platforms - see here.

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

As explained in #4524 and #4525 it's not possible to compile-test any CONFIG_IMX yet but if I understood this issue correctly the latest version should be compatible with your branch, please test it.

Copy link
Collaborator

Choose a reason for hiding this comment

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

@iuliana-prodan I commented in your PR - maybe you shouldn't include both ll_zephyr.c and ll_schedule.c in your builds?

Copy link
Contributor

Choose a reason for hiding this comment

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

Thanks, @lyakh.
I've replied to you in my PR.
Please let me know if you agree with my proposed solution - from here, and I can make the changes and update that PR.


/* per-scheduler data */
struct zephyr_ll {
struct list_item tasks; /* list of ll tasks */
Expand Down
88 changes: 50 additions & 38 deletions src/trace/trace.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -92,6 +92,7 @@ static void put_header(void *dst, const struct sof_uuid_entry *uid,

}

#ifndef __ZEPHYR__
/** Ring buffer for the mailbox trace */
void mtrace_event(const char *data, uint32_t length)
{
Expand All @@ -110,6 +111,7 @@ void mtrace_event(const char *data, uint32_t length)
dcache_writeback_region(t + trace->pos, length);
trace->pos += length;
}
#endif /* __ZEPHYR__ */

#if CONFIG_TRACE_FILTERING_VERBOSITY
/**
Expand Down Expand Up @@ -222,21 +224,15 @@ static bool trace_filter_flood(uint32_t log_level, uint32_t entry, uint64_t mess

/** Implementation shared and invoked by both adaptive filtering and
* not. Serializes events into trace messages and passes them to
* dtrace_event() or to mtrace_event() or to both depending on the log
* lvl and the Kconfiguration.
* dtrace_event()
*/
static void vatrace_log(bool send_atomic, uint32_t log_entry, const struct tr_ctx *ctx,
uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, va_list vargs)
static void dma_trace_log(bool send_atomic, uint32_t log_entry, const struct tr_ctx *ctx,
uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, va_list vargs)
{
uint32_t data[MESSAGE_SIZE_DWORDS(_TRACE_EVENT_MAX_ARGUMENT_COUNT)];
const int message_size = MESSAGE_SIZE(arg_count);
int i;

#if CONFIG_TRACEM
unsigned long flags;
struct trace *trace = trace_get();
#endif /* CONFIG TRACEM */

/* fill log content. arg_count is in the dictionary. */
put_header(data, ctx->uuid_p, id_1, id_2, log_entry,
platform_safe_get_time(timer_get()));
Expand All @@ -250,42 +246,25 @@ static void vatrace_log(bool send_atomic, uint32_t log_entry, const struct tr_ct
else
dtrace_event((const char *)data, message_size);

#if CONFIG_TRACEM
/* send event by mail box too. */
if (send_atomic) {
mtrace_event((const char *)data, MESSAGE_SIZE(arg_count));
} else {
spin_lock_irq(&trace->lock, flags);
mtrace_event((const char *)data, MESSAGE_SIZE(arg_count));
spin_unlock_irq(&trace->lock, flags);
}
#else
/* send event by mail box if level is LOG_LEVEL_CRITICAL. */
if (lvl == LOG_LEVEL_CRITICAL)
mtrace_event((const char *)data, MESSAGE_SIZE(arg_count));
#endif /* CONFIG_TRACEM */
}

void trace_log_unfiltered(bool send_atomic, const void *log_entry, const struct tr_ctx *ctx,
uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, ...)
uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, va_list vl)
{
struct trace *trace = trace_get();
va_list vl;

if (!trace->enable) {
return;
}

va_start(vl, arg_count);
vatrace_log(send_atomic, (uint32_t)log_entry, ctx, lvl, id_1, id_2, arg_count, vl);
va_end(vl);
dma_trace_log(send_atomic, (uint32_t)log_entry, ctx, lvl, id_1, id_2, arg_count, vl);
}

void trace_log_filtered(bool send_atomic, const void *log_entry, const struct tr_ctx *ctx,
uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, ...)
uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, va_list vl)
{
struct trace *trace = trace_get();
va_list vl;

#if CONFIG_TRACE_FILTERING_ADAPTIVE
uint64_t current_ts;
#endif /* CONFIG_TRACE_FILTERING_ADAPTIVE */
Expand All @@ -310,9 +289,7 @@ void trace_log_filtered(bool send_atomic, const void *log_entry, const struct tr
}
#endif /* CONFIG_TRACE_FILTERING_ADAPTIVE */

va_start(vl, arg_count);
vatrace_log(send_atomic, (uint32_t)log_entry, ctx, lvl, id_1, id_2, arg_count, vl);
va_end(vl);
dma_trace_log(send_atomic, (uint32_t)log_entry, ctx, lvl, id_1, id_2, arg_count, vl);
}

struct sof_ipc_trace_filter_elem *trace_filter_fill(struct sof_ipc_trace_filter_elem *elem,
Expand Down Expand Up @@ -532,9 +509,9 @@ void trace_init(struct sof *sof)
dma_trace_init_early(sof);
}

void mtrace_dict_entry(uint32_t dict_entry_address, int n_args, ...)
static void mtrace_dict_entry_vl(bool atomic_context, uint32_t dict_entry_address,
int n_args, va_list ap)
{
va_list ap;
int i;
char packet[MESSAGE_SIZE(_TRACE_EVENT_MAX_ARGUMENT_COUNT)];
uint32_t *args = (uint32_t *)&packet[MESSAGE_SIZE(0)];
Expand All @@ -543,10 +520,45 @@ void mtrace_dict_entry(uint32_t dict_entry_address, int n_args, ...)
put_header(packet, dt_tr.uuid_p, _TRACE_INV_ID, _TRACE_INV_ID,
dict_entry_address, tstamp);

va_start(ap, n_args);
for (i = 0; i < n_args; i++)
for (i = 0; i < MIN(n_args, _TRACE_EVENT_MAX_ARGUMENT_COUNT); i++)
args[i] = va_arg(ap, uint32_t);

if (atomic_context) {
mtrace_event(packet, MESSAGE_SIZE(n_args));
} else {
struct trace * const trace = trace_get();
uint32_t saved_flags;

spin_lock_irq(&trace->lock, saved_flags);
mtrace_event(packet, MESSAGE_SIZE(n_args));
spin_unlock_irq(&trace->lock, saved_flags);
}
}

void mtrace_dict_entry(bool atomic_context, uint32_t dict_entry_address, int n_args, ...)
{
va_list ap;

va_start(ap, n_args);
mtrace_dict_entry_vl(atomic_context, dict_entry_address, n_args, ap);
va_end(ap);
}

mtrace_event(packet, MESSAGE_SIZE(n_args));
void _log_sofdict(log_func_t sofdict_logf, bool atomic, const void *log_entry,
const struct tr_ctx *ctx, const uint32_t lvl,
uint32_t id_1, uint32_t id_2, int arg_count, ...)
{
va_list ap;

#ifndef __ZEPHYR__ /* for Zephyr see _log_nodict() in trace.h */
if (lvl <= MTRACE_DUPLICATION_LEVEL) {
va_start(ap, arg_count);
mtrace_dict_entry_vl(atomic, (uint32_t)log_entry, arg_count, ap);
va_end(ap);
}
#endif

va_start(ap, arg_count);
sofdict_logf(atomic, log_entry, ctx, lvl, id_1, id_2, arg_count, ap);
va_end(ap);
}
10 changes: 9 additions & 1 deletion test/cmocka/src/common_mocks.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -101,7 +101,8 @@ void WEAK __panic(uint32_t p, char *filename, uint32_t linenum)
}

void WEAK trace_log_filtered(bool send_atomic, const void *log_entry, const struct tr_ctx *ctx,
uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, ...)
uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count,
va_list args)
{
(void) send_atomic;
(void) log_entry;
Expand All @@ -110,6 +111,13 @@ void WEAK trace_log_filtered(bool send_atomic, const void *log_entry, const stru
(void) id_1;
(void) id_2;
(void) arg_count;
(void) args;
}

void WEAK _log_sofdict(log_func_t sofdict_logf, bool atomic, const void *log_entry,
const struct tr_ctx *ctx, const uint32_t lvl,
uint32_t id_1, uint32_t id_2, int arg_count, ...)
{
}

void WEAK trace_flush_dma_to_mbox(void)
Expand Down
Loading