michaelh/zephyr
1
0
Fork 0
Code Releases Activity

logging: backend_adsp: lock the output

Browse source 
Adds a lock around the output to prevent corruption, and sets the buffer
size of the output to size of the output buffer. This fixes the
corrupted log output as process() may be called from multiple contexts
from different CPUs. A background log processing thread may race against
the panic ISR log context also calling process() on an SMP system.

Additionally sets the buffer size to 80 such that the cavs trace_out.c
functionality and lock are useful for more than one character at a time
greatly reducing the chances of garbled output in a printk and log race
but does not entirely prevent it. CONFIG_LOG_PRINTK=y should be used
to avoid all races.

Signed-off-by: Tom Burdick <thomas.burdick@intel.com>
This commit is contained in:
Tom Burdick 2022-04-05 14:40:55 -05:00 • committed by Anas Nashif
commit 02503c37c3
1 changed files with 32 additions and 5 deletions
Download patch file Download diff file Expand all files Collapse all files

37
subsys/logging/log_backend_adsp.c
View file

@ -10,6 +10,18 @@
#include <logging/log_output.h>
#include <logging/log_backend_std.h>
/*
* A lock is needed as log_process() and log_panic() have no internal locks
* to prevent concurrency. Meaning if log_process is called after
* log_panic was called previously, log_process may happen from another
* CPU and calling context than the log processing thread running in
* the background. On an SMP system this is a race.
*
* This caused a race on the output trace such that the logging output
* was garbled and useless.
*/
static struct k_spinlock lock;
static uint32_t log_format_current = CONFIG_LOG_BACKEND_ADSP_OUTPUT_DEFAULT;
void intel_adsp_trace_out(int8_t *str, size_t len);
@ -20,12 +32,18 @@ static int char_out(uint8_t *data, size_t length, void *ctx)
return length;
}
/* Trace output goes in 64 byte chunks with a 4-byte header, no point
* in buffering more than 60 bytes at a time
*/
static uint8_t log_buf[60];
LOG_OUTPUT_DEFINE(log_output_adsp, char_out, log_buf, 1);
/**
* 80 bytes seems to catch most sensibly sized log message lines
* in one go letting the trace out call output whole complete
* lines. This avoids the overhead of a spin lock in the trace_out
* more often as well as avoiding entwined characters from printk if
* LOG_PRINTK=n.
*/
#define LOG_BUF_SIZE 80
static uint8_t log_buf[LOG_BUF_SIZE];
LOG_OUTPUT_DEFINE(log_output_adsp, char_out, log_buf, sizeof(log_buf));
static uint32_t format_flags(void)
{
@ -42,9 +60,14 @@ static inline void put(const struct log_backend *const backend,
{
log_backend_std_put(&log_output_adsp, format_flags(), msg);
}
static void panic(struct log_backend const *const backend)
{
k_spinlock_key_t key = k_spin_lock(&lock);
log_backend_std_panic(&log_output_adsp);
k_spin_unlock(&lock, key);
}
static inline void dropped(const struct log_backend *const backend,
@ -76,7 +99,11 @@ static void process(const struct log_backend *const backend,
{
log_format_func_t log_output_func = log_format_func_t_get(log_format_current);
k_spinlock_key_t key = k_spin_lock(&lock);
log_output_func(&log_output_adsp, &msg->log, format_flags());
k_spin_unlock(&lock, key);
}
static int format_set(const struct log_backend *const backend, uint32_t log_type)