OrgACRN
/
sof
mirror of https://github.com/thesofproject/sof.git
1
0
Fork 0
Code Issues Projects Releases Wiki Activity
sof/tools/logger/convert.c

1156 lines
32 KiB
C
Raw Blame History

// SPDX-License-Identifier: BSD-3-Clause
//
// Copyright(c) 2018 Intel Corporation. All rights reserved.
//
// Author: Bartosz Kokoszko <bartoszx.kokoszko@linux.intel.com>
// Artur Kloniecki <arturx.kloniecki@linux.intel.com>
#include <assert.h>
#include <endian.h>
#include <stdbool.h>
#include <stdlib.h>
#include <stdint.h>
#include <string.h>
#include <errno.h>
#include <unistd.h>
#include <math.h>
#include <sof/lib/uuid.h>
#include <time.h>
#include <user/abi_dbg.h>
#include <user/trace.h>
#include "convert.h"
#include "filter.h"
#include "misc.h"
#define CEIL(a, b) ((a+b-1)/b)
#define TRACE_MAX_PARAMS_COUNT 4
#define TRACE_MAX_TEXT_LEN 1024
#define TRACE_MAX_FILENAME_LEN 128
#define TRACE_MAX_IDS_STR 10
#define TRACE_IDS_MASK ((1 << TRACE_ID_LENGTH) - 1)
#define INVALID_TRACE_ID (-1 & TRACE_IDS_MASK)
/** Dictionary entry. This MUST match the start of the linker output
* defined by _DECLARE_LOG_ENTRY().
*/
struct ldc_entry_header {
uint32_t level;
uint32_t component_class;
uint32_t params_num;
uint32_t line_idx;
uint32_t file_name_len;
uint32_t text_len;
};
/** Dictionary entry + unformatted parameters */
struct ldc_entry {
struct ldc_entry_header header;
char *file_name;
char *text;
uint32_t *params;
};
/** Dictionary entry + formatted parameters */
struct proc_ldc_entry {
int subst_mask;
struct ldc_entry_header header;
char *file_name;
char *text;
uintptr_t params[TRACE_MAX_PARAMS_COUNT];
};
#define BAD_PTR_STR "<bad uid ptr 0x%.8x>"
#define UUID_LOWER "%s%s%s<%08x-%04x-%04x-%02x%02x-%02x%02x%02x%02x%02x%02x>%s%s%s"
#define UUID_UPPER "%s%s%s<%08X-%04X-%04X-%02X%02X-%02X%02X%02X%02X%02X%02X>%s%s%s"
static const char *missing = "<missing>";
static int read_entry_from_ldc_file(struct ldc_entry *entry, uint32_t log_entry_address);
char *format_uid_raw(const struct sof_uuid_entry *uid_entry, int use_colors, int name_first,
bool be, bool upper)
{
const struct sof_uuid *uid_val = &uid_entry->id;
uint32_t a = be ? htobe32(uid_val->a) : uid_val->a;
uint16_t b = be ? htobe16(uid_val->b) : uid_val->b;
uint16_t c = be ? htobe16(uid_val->c) : uid_val->c;
char *str;
str = log_asprintf(upper ? UUID_UPPER : UUID_LOWER,
use_colors ? KBLU : "",
name_first ? uid_entry->name : "",
name_first ? " " : "",
a, b, c,
uid_val->d[0], uid_val->d[1], uid_val->d[2],
uid_val->d[3], uid_val->d[4], uid_val->d[5],
uid_val->d[6], uid_val->d[7],
name_first ? "" : " ",
name_first ? "" : uid_entry->name,
use_colors ? KNRM : "");
return str;
}
static const struct sof_uuid_entry *get_uuid_entry(uint32_t uid_ptr)
{
const struct snd_sof_uids_header *uids_dict = global_config->uids_dict;
return (const struct sof_uuid_entry *)
((uint8_t *)uids_dict + uids_dict->data_offset + uid_ptr -
uids_dict->base_address);
}
/*
* Use uids dictionary content, to convert address of uuid `entry` from logger
* memory space to corresponding uuid key address used in firmware trace system
* (with base UUID_ENTRY_ELF_BASE, 0x1FFFA000 as usual). Function get_uuid_entry
* works in oppopsite direction.
*/
uint32_t get_uuid_key(const struct sof_uuid_entry *entry)
{
const struct snd_sof_uids_header *uids_dict = global_config->uids_dict;
/*
* uids_dict->data_offset and uids_dict->base_address are both constants,
* related with given ldc file.
* Uuid address used in firmware, points unusable memory region,
* so its treated as key value.
*/
return (uintptr_t)entry - (uintptr_t)uids_dict -
uids_dict->data_offset + uids_dict->base_address;
}
static const char *format_uid(uint32_t uid_ptr, int use_colors, bool be, bool upper)
{
const struct snd_sof_uids_header *uids_dict = global_config->uids_dict;
const struct sof_uuid_entry *uid_entry;
char *str;
if (uid_ptr < uids_dict->base_address ||
uid_ptr >= uids_dict->base_address + uids_dict->data_length) {
str = calloc(1, strlen(BAD_PTR_STR) + 1 + 6);
if (!str) {
log_err("can't allocate memory\n");
exit(EXIT_FAILURE);
}
sprintf(str, BAD_PTR_STR, uid_ptr);
} else {
uid_entry = get_uuid_entry(uid_ptr);
str = format_uid_raw(uid_entry, use_colors, 1, be, upper);
}
return str;
}
/* fmt should point '%pUx`, return pointer to UUID string or zero */
static const char *asprintf_uuid(const char *fmt, uint32_t uuid_key, bool use_colors, int *fmt_len)
{
const char *fmt_end = fmt + strlen(fmt);
int be, upper;
int len = 4; /* assure full formating, with x */
if (fmt + 2 >= fmt_end || fmt[1] != 'p' || fmt[2] != 'U') {
*fmt_len = 0;
return NULL;
}
/* check 'x' value */
switch (fmt + 3 < fmt_end ? fmt[3] : 0) {
case 'b':
be = 1;
upper = 0;
break;
case 'B':
be = 1;
upper = 1;
break;
case 'l':
be = 0;
upper = 0;
break;
case 'L':
be = 0;
upper = 1;
break;
default:
be = 0;
upper = 0;
--len;
break;
}
*fmt_len = len;
return format_uid(uuid_key, use_colors, be, upper);
}
static const char *asprintf_entry_text(uint32_t entry_address)
{
struct ldc_entry entry;
int ret;
ret = read_entry_from_ldc_file(&entry, entry_address);
if (ret)
return NULL;
free(entry.file_name);
return entry.text;
}
/** printf-like formatting from the binary ldc_entry input to the
* formatted proc_lpc_entry output. Also copies the unmodified
* ldc_entry_header from input to output.
*
* @param[out] pe copy of the header + formatted output
* @param[in] e copy of the dictionary entry where unformatted,
uint32_t params have been inserted.
@param[in] use_colors whether to use ANSI terminal codes
*/
static void process_params(struct proc_ldc_entry *pe,
const struct ldc_entry *e,
int use_colors)
{
char *p = e->text;
const char *t_end = p + strlen(e->text);
int uuid_fmt_len;
int i = 0;
pe->subst_mask = 0;
pe->header = e->header;
pe->file_name = e->file_name;
pe->text = e->text;
/*
* Scan the text for possible replacements. We follow the Linux kernel
* that uses %pUx formats for UUID / GUID printing, where 'x' is
* optional and can be one of 'b', 'B', 'l' (default), and 'L'.
* For decoding log entry text from pointer %pQ is used.
*/
while ((p = strchr(p, '%'))) {
uint32_t raw_param;
if (i >= e->header.params_num) {
/* Don't read e->params[] out of bounds. */
log_err("Too many %% conversion specifiers in '%s'\n",
e->text);
break;
}
raw_param = e->params[i];
/* % can't be the last char */
if (p + 1 >= t_end) {
log_err("Invalid format string\n");
break;
}
/* scan format string */
if (p[1] == '%') {
/* Skip "%%" */
p += 2;
} else if (p[1] == 's') {
/* %s format specifier */
/* check for string printing, because it leads to logger crash */
log_err("String printing is not supported\n");
pe->params[i] = (uintptr_t)log_asprintf("<String @ 0x%08x>", raw_param);
if (!pe->params[i])
abort();
pe->subst_mask |= 1 << i;
++i;
p += 2;
} else if (p + 2 < t_end && p[1] == 'p' && p[2] == 'U') {
/* %pUx format specifier */
/* substitute UUID entry address with formatted string pointer from heap */
pe->params[i] = (uintptr_t)asprintf_uuid(p, raw_param, use_colors,
&uuid_fmt_len);
if (!pe->params[i])
abort();
pe->subst_mask |= 1 << i;
++i;
/* replace uuid formatter with %s */
p[1] = 's';
memmove(&p[2], &p[uuid_fmt_len], (int)(t_end - &p[uuid_fmt_len]) + 1);
p += uuid_fmt_len - 2;
t_end -= uuid_fmt_len - 2;
} else if (p + 2 < t_end && p[1] == 'p' && p[2] == 'Q') {
/* %pQ format specifier */
/* substitute log entry address with formatted entry text */
pe->params[i] = (uintptr_t)asprintf_entry_text(raw_param);
if (pe->params[i])
pe->subst_mask |= 1 << i;
else
pe->params[i] = (uintptr_t)missing;
++i;
/* replace entry formatter with %s */
p[1] = 's';
memmove(&p[2], &p[3], t_end - &p[2]);
p++;
t_end--;
} else {
/* arguments different from %pU and %pQ should be passed without
* modification
*/
pe->params[i] = raw_param;
++i;
p += 2;
}
}
if (i < e->header.params_num)
log_err("Too few %% conversion specifiers in '%s'\n", e->text);
}
static void free_proc_ldc_entry(struct proc_ldc_entry *pe)
{
int i;
for (i = 0; i < TRACE_MAX_PARAMS_COUNT; i++) {
if (pe->subst_mask & (1 << i))
free((void *)pe->params[i]);
pe->params[i] = 0;
}
}
static double to_usecs(uint64_t time)
{
/* trace timestamp uses CPU system clock at default 25MHz ticks */
// TODO: support variable clock rates
return (double)time / global_config->clock;
}
/** Justified timestamp width for printf format string */
static unsigned int timestamp_width(unsigned int precision)
{
/* 64bits yields less than 20 digits precision. As reported by
* gcc 9.3, this avoids a very long precision causing snprintf()
* to truncate time_fmt
*/
assert(precision < 20);
/*
* 12 digits for units is enough for 1M seconds = 11 days which
* should be enough for most test runs.
*
* Add 1 for the comma when there is one.
*/
return 12 + (precision > 0 ? 1 : 0) + precision;
}
static inline void print_table_header(void)
{
FILE *out_fd = global_config->out_fd;
int hide_location = global_config->hide_location;
char date_string[64];
const time_t epoc_secs = time(NULL);
/* See SOF_IPC_TRACE_DMA_PARAMS_EXT in the kernel sources */
struct timespec ktime;
const int gettime_ret = clock_gettime(CLOCK_MONOTONIC, &ktime);
if (gettime_ret) {
log_err("clock_gettime() failed: %s\n",
strerror(errno));
exit(1);
}
if (global_config->time_precision >= 0) {
const unsigned int ts_width = timestamp_width(global_config->time_precision);
fprintf(out_fd, "%*s(us)%*s ", -ts_width, " TIMESTAMP", ts_width, "DELTA");
}
fprintf(out_fd, "%2s %-18s ", "C#", "COMPONENT");
if (!hide_location)
fprintf(out_fd, "%-29s ", "LOCATION");
fprintf(out_fd, "%s", "CONTENT");
if (global_config->time_precision >= 0) {
struct tm *ltime = localtime(&epoc_secs);
/* e.g.: ktime=4263.487s @ 2021-04-27 14:21:13 -0700 PDT */
fprintf(out_fd, "\tktime=%lu.%03lus",
ktime.tv_sec, ktime.tv_nsec / 1000000);
if (ltime && strftime(date_string, sizeof(date_string),
"%F %X %z %Z", ltime))
fprintf(out_fd, " @ %s", date_string);
}
fprintf(out_fd, "\n");
fflush(out_fd);
}
static const char *get_level_color(uint32_t level)
{
switch (level) {
case LOG_LEVEL_CRITICAL:
return KRED;
case LOG_LEVEL_WARNING:
return KYEL;
default:
return KNRM;
}
}
static const char *get_level_name(uint32_t level)
{
switch (level) {
case LOG_LEVEL_CRITICAL:
return "ERROR ";
case LOG_LEVEL_WARNING:
return "WARN ";
case LOG_LEVEL_INFO:
return "INFO ";
case LOG_LEVEL_DEBUG:
return "DEBUG ";
default:
return "UNKNOWN ";
}
}
static const char *get_component_name(uint32_t trace_class, uint32_t uid_ptr)
{
const struct snd_sof_uids_header *uids_dict = global_config->uids_dict;
const struct sof_uuid_entry *uid_entry;
/* if uid_ptr is non-zero, find name in the ldc file */
if (uid_ptr) {
if (uid_ptr < uids_dict->base_address ||
uid_ptr >= uids_dict->base_address +
uids_dict->data_length)
return "<uid?>";
uid_entry = get_uuid_entry(uid_ptr);
return uid_entry->name;
}
/* do not resolve legacy (deprecated) trace class name */
return "unknown";
}
/* remove superfluous leading file path and shrink to last 20 chars */
static char *format_file_name(char *file_name_raw, int full_name)
{
char *name;
int len;
/* most/all string should have "src" */
name = strstr(file_name_raw, "src");
if (!name)
name = file_name_raw;
if (full_name)
return name;
/* keep the last 24 chars */
len = strlen(name);
if (len > 24) {
char *sep_pos = NULL;
name += (len - 24);
sep_pos = strchr(name, '/');
if (!sep_pos)
return name;
while (--sep_pos >= name)
*sep_pos = '.';
}
return name;
}
static int entry_number = 1;
/** Formats and outputs one entry from the trace + the corresponding
* ldc_entry from the dictionary passed as arguments. Expects the log
* variables to have already been copied into the ldc_entry.
*/
static void print_entry_params(const struct log_entry_header *dma_log,
const struct ldc_entry *entry, uint64_t last_timestamp)
{
static uint64_t timestamp_origin;
FILE *out_fd = global_config->out_fd;
int use_colors = global_config->use_colors;
int raw_output = global_config->raw_output;
int hide_location = global_config->hide_location;
int time_precision = global_config->time_precision;
char ids[TRACE_MAX_IDS_STR];
float dt = to_usecs(dma_log->timestamp - last_timestamp);
struct proc_ldc_entry proc_entry;
int ret;
if (raw_output)
use_colors = 0;
/* Something somewhere went wrong */
if (dt > 1000.0 * 1000.0 * 1000.0)
dt = NAN;
if (dma_log->timestamp < last_timestamp) {
fprintf(out_fd,
"\n\t\t --- negative DELTA = %.3f us: wrap, IPC_TRACE, other? ---\n\n",
-to_usecs(last_timestamp - dma_log->timestamp));
entry_number = 1;
}
/* The first entry:
* - is never shown with a relative TIMESTAMP (to itself!?)
* - shows a zero DELTA
*/
if (entry_number == 1) {
entry_number++;
/* Display absolute (and random) timestamps */
timestamp_origin = 0;
dt = 0;
} else if (entry_number == 2) {
entry_number++;
if (global_config->relative_timestamps == 1)
/* Switch to relative timestamps from now on. */
timestamp_origin = last_timestamp;
} /* We don't need the exact entry_number after 3 */
if (dma_log->id_0 != INVALID_TRACE_ID &&
dma_log->id_1 != INVALID_TRACE_ID)
sprintf(ids, "%d.%d", (dma_log->id_0 & TRACE_IDS_MASK),
(dma_log->id_1 & TRACE_IDS_MASK));
else
ids[0] = '\0';
if (raw_output) { /* "raw" means script-friendly (not all hex) */
fprintf(out_fd, "%s%u %u %s%s%s ",
entry->header.level == use_colors ?
(LOG_LEVEL_CRITICAL ? KRED : KNRM) : "",
dma_log->core_id,
entry->header.level,
get_component_name(entry->header.component_class, dma_log->uid),
raw_output && strlen(ids) ? "-" : "",
ids);
if (time_precision >= 0)
fprintf(out_fd, "%.*f %.*f ",
time_precision, to_usecs(dma_log->timestamp - timestamp_origin),
time_precision, dt);
if (!hide_location)
fprintf(out_fd, "(%s:%u) ",
format_file_name(entry->file_name, raw_output),
entry->header.line_idx);
} else {
if (time_precision >= 0) {
const unsigned int ts_width = timestamp_width(time_precision);
fprintf(out_fd, "%s[%*.*f] (%*.*f)%s ",
use_colors ? KGRN : "",
ts_width, time_precision,
to_usecs(dma_log->timestamp - timestamp_origin),
ts_width, time_precision, dt,
use_colors ? KNRM : "");
}
/* core id */
fprintf(out_fd, "c%d ", dma_log->core_id);
/* component name and id */
fprintf(out_fd, "%s%-12s %-5s%s ",
use_colors ? KYEL : "",
get_component_name(entry->header.component_class, dma_log->uid),
ids,
use_colors ? KNRM : "");
/* location */
if (!hide_location)
fprintf(out_fd, "%24s:%-4u ",
format_file_name(entry->file_name, raw_output),
entry->header.line_idx);
/* level name */
fprintf(out_fd, "%s%s",
use_colors ? get_level_color(entry->header.level) : "",
get_level_name(entry->header.level));
}
/* Minimal, printf-like formatting */
process_params(&proc_entry, entry, use_colors);
switch (proc_entry.header.params_num) {
case 0:
ret = fprintf(out_fd, "%s", proc_entry.text);
break;
case 1:
ret = fprintf(out_fd, proc_entry.text, proc_entry.params[0]);
break;
case 2:
ret = fprintf(out_fd, proc_entry.text, proc_entry.params[0], proc_entry.params[1]);
break;
case 3:
ret = fprintf(out_fd, proc_entry.text, proc_entry.params[0], proc_entry.params[1],
proc_entry.params[2]);
break;
case 4:
ret = fprintf(out_fd, proc_entry.text, proc_entry.params[0], proc_entry.params[1],
proc_entry.params[2], proc_entry.params[3]);
break;
default:
log_err("Unsupported number of arguments for '%s'", proc_entry.text);
ret = 0; /* don't log ferror */
break;
}
free_proc_ldc_entry(&proc_entry);
/* log format text comes from ldc file (may be invalid), so error check is needed here */
if (ret < 0)
log_err("trace fprintf failed for '%s', %d '%s'",
proc_entry.text, ferror(out_fd), strerror(ferror(out_fd)));
fprintf(out_fd, "%s\n", use_colors ? KNRM : "");
fflush(out_fd);
}
static int read_entry_from_ldc_file(struct ldc_entry *entry, uint32_t log_entry_address)
{
uint32_t base_address = global_config->logs_header->base_address;
uint32_t data_offset = global_config->logs_header->data_offset;
int ret;
/* evaluate entry offset in input file */
uint32_t entry_offset = (log_entry_address - base_address) + data_offset;
entry->file_name = NULL;
entry->text = NULL;
entry->params = NULL;
/* set file position to beginning of processed entry */
ret = fseek(global_config->ldc_fd, entry_offset, SEEK_SET);
if (ret) {
log_err("Failed to seek to entry header for offset 0x%x in dictionary.\n",
entry_offset);
ret = -errno;
goto out;
}
/* fetching elf header params */
ret = fread(&entry->header, sizeof(entry->header), 1, global_config->ldc_fd);
if (ret != 1) {
log_err("Failed to read entry header for offset 0x%x in dictionary.\n",
entry_offset);
ret = -1;
goto out;
}
if (entry->header.file_name_len > TRACE_MAX_FILENAME_LEN) {
log_err("Invalid filename length %d or ldc file does not match firmware\n",
entry->header.file_name_len);
ret = -EINVAL;
goto out;
}
entry->file_name = (char *)malloc(entry->header.file_name_len + 1);
if (!entry->file_name) {
log_err("can't allocate %d byte for entry.file_name\n",
entry->header.file_name_len);
ret = -ENOMEM;
goto out;
}
ret = fread(entry->file_name, sizeof(char), entry->header.file_name_len,
global_config->ldc_fd);
entry->file_name[entry->header.file_name_len] = '\0';
if (ret != entry->header.file_name_len) {
log_err("Failed to read source filename for offset 0x%x in dictionary.\n",
entry_offset);
ret = -1;
goto out;
}
/* fetching text */
if (entry->header.text_len > TRACE_MAX_TEXT_LEN) {
log_err("Invalid text length.\n");
ret = -EINVAL;
goto out;
}
entry->text = (char *)malloc(entry->header.text_len + 1);
if (!entry->text) {
log_err("can't allocate %d byte for entry.text\n", entry->header.text_len);
ret = -ENOMEM;
goto out;
}
ret = fread(entry->text, sizeof(char), entry->header.text_len, global_config->ldc_fd);
if (ret != entry->header.text_len) {
log_err("Failed to read log message at offset 0x%x from dictionary.\n",
entry_offset);
ret = -1;
goto out;
}
entry->text[entry->header.text_len] = '\0';
return 0;
out:
free(entry->text);
entry->text = NULL;
free(entry->file_name);
entry->file_name = NULL;
return ret;
}
/** Gets the dictionary entry matching the log entry argument, reads
* from the log the variable number of arguments needed by this entry
* and passes everything to print_entry_params() to finish processing
* this log entry. So not just "fetch" but everything else after it too.
*
* @param[in] dma_log protocol header from any trace (not just from the
* "DMA" trace)
* @param[in,out] last_timestamp timestamp found for this entry
*/
static int fetch_entry(const struct log_entry_header *dma_log, uint64_t *last_timestamp)
{
struct ldc_entry entry;
int ret;
ret = read_entry_from_ldc_file(&entry, dma_log->log_entry_address);
if (ret < 0) {
log_err("read_entry_from_ldc_file(0x%x) returned %d\n",
dma_log->log_entry_address, ret);
goto out;
}
/* fetching entry params from dma dump */
if (entry.header.params_num > TRACE_MAX_PARAMS_COUNT) {
log_err("Invalid number of parameters.\n");
ret = -EINVAL;
goto out;
}
entry.params = (uint32_t *)malloc(sizeof(uint32_t) * entry.header.params_num);
if (!entry.params) {
log_err("can't allocate %d byte for entry.params\n",
(int)(sizeof(uint32_t) * entry.header.params_num));
ret = -ENOMEM;
goto out;
}
if (global_config->serial_fd < 0) {
ret = fread(entry.params, sizeof(uint32_t), entry.header.params_num,
global_config->in_fd);
if (ret != entry.header.params_num) {
fprintf(global_config->out_fd,
"warn: failed to fread() %d params from the log for %s:%d\n",
entry.header.params_num,
entry.file_name, entry.header.line_idx);
ret = ferror(global_config->in_fd) ? -1 : 0;
if (feof(global_config->in_fd))
fprintf(global_config->out_fd,
"warn: log's End Of File. Device suspend?\n");
goto out;
}
} else { /* serial */
size_t size = sizeof(uint32_t) * entry.header.params_num;
uint8_t *n;
/* Repeatedly read() how much we still miss until we got
* enough for the number of params needed by this
* particular statement.
*/
for (n = (uint8_t *)entry.params; size; n += ret, size -= ret) {
ret = read(global_config->serial_fd, n, size);
if (ret < 0) {
ret = -errno;
log_err("Failed to fread %d params from serial: %s\n",
entry.header.params_num, strerror(errno));
goto out;
}
if (ret != size)
log_err("Partial read of %u bytes of %zu, reading more\n",
ret, size);
}
} /* serial */
/* printing entry content */
print_entry_params(dma_log, &entry, *last_timestamp);
*last_timestamp = dma_log->timestamp;
/* set f_ldc file position to the beginning */
rewind(global_config->ldc_fd);
ret = 0;
out:
/* free alocated memory */
free(entry.params);
free(entry.text);
free(entry.file_name);
return ret;
}
static int serial_read(uint64_t *last_timestamp)
{
struct log_entry_header dma_log;
size_t len;
uint8_t *n;
int ret;
for (len = 0, n = (uint8_t *)&dma_log; len < sizeof(dma_log); n += sizeof(uint32_t)) {
ret = read(global_config->serial_fd, n, sizeof(*n) * sizeof(uint32_t));
if (ret < 0)
return -errno;
/* In the beginning we read 1 spurious byte */
if (ret < sizeof(*n) * sizeof(uint32_t))
n -= sizeof(uint32_t);
else
len += ret;
}
/* Skip all trace_point() values, although this test isn't 100% reliable */
while ((dma_log.log_entry_address < global_config->logs_header->base_address) ||
dma_log.log_entry_address > global_config->logs_header->base_address +
global_config->logs_header->data_length) {
/*
* 8 characters and a '\n' come from the serial port, append a
* '\0'
*/
char s[10];
uint8_t *c;
size_t len;
c = (uint8_t *)&dma_log;
memcpy(s, c, sizeof(s) - 1);
s[sizeof(s) - 1] = '\0';
fprintf(global_config->out_fd, "Trace point %s", s);
memmove(&dma_log, c + 9, sizeof(dma_log) - 9);
c = (uint8_t *)(&dma_log + 1) - 9;
for (len = 9; len; len -= ret, c += ret) {
ret = read(global_config->serial_fd, c, len);
if (ret < 0)
return ret;
}
}
/* fetching entry from elf dump and complete processing this log
* line
*/
return fetch_entry(&dma_log, last_timestamp);
}
/** Main logger loop */
static int logger_read(void)
{
struct log_entry_header dma_log;
int ret = 0;
uint64_t last_timestamp = 0;
bool ldc_address_OK = false;
unsigned int skipped_dwords = 0;
if (!global_config->raw_output)
print_table_header();
if (global_config->serial_fd >= 0)
/* Wait for CTRL-C */
for (;;) {
ret = serial_read(&last_timestamp);
if (ret < 0)
return ret;
}
/* One iteration per log statement */
while (!ferror(global_config->in_fd)) {
/* getting entry parameters from dma dump */
ret = fread(&dma_log, sizeof(dma_log), 1, global_config->in_fd);
if (ret != 1) {
/*
* use ferror (not errno) to check fread fail -
* see https://www.gnu.org/software/gnulib/manual/html_node/fread.html
*/
ret = -ferror(global_config->in_fd);
if (ret) {
log_err("in %s(), fread(..., %s) failed: %s(%d)\n",
__func__, global_config->in_file,
strerror(-ret), ret);
break;
}
/* for trace mode, try to reopen */
if (global_config->trace) {
fprintf(global_config->out_fd,
"\n ---- %s; %s -----\n\n",
"Re-opening trace input file",
"device suspend?");
if (freopen(NULL, "rb", global_config->in_fd)) {
entry_number = 1;
continue;
} else {
log_err("in %s(), freopen(..., %s) failed: %s(%d)\n",
__func__, global_config->in_file,
strerror(errno), errno);
ret = -errno;
break;
}
} else {
/* EOF */
if (!feof(global_config->in_fd))
log_err("file '%s' is unaligned with trace entry size (%zu)\n",
global_config->in_file, sizeof(dma_log));
break;
}
}
/* checking if received trace address is located in
* entry section in elf file.
*/
if (dma_log.log_entry_address < global_config->logs_header->base_address ||
dma_log.log_entry_address > global_config->logs_header->base_address +
global_config->logs_header->data_length) {
/* Finding uninitialized and incomplete log statements in the
* mailbox ring buffer is routine. Take note in both cases but
* report errors only for the DMA trace.
*/
if (global_config->trace && ldc_address_OK) {
log_err("log_entry_address %#10x is not in dictionary range!\n",
dma_log.log_entry_address);
fprintf(global_config->out_fd,
"warn: Seeking forward 4 bytes at a time until re-synchronize.\n");
}
ldc_address_OK = false;
/* When the address is not correct, move forward by one DWORD (not
* entire struct dma_log)
*/
ret = fseek(global_config->in_fd, -(sizeof(dma_log) - sizeof(uint32_t)),
SEEK_CUR);
if (ret) {
log_err("fetch_entry() failed on seek, aborting\n");
ret = -errno;
break;
}
skipped_dwords++;
continue;
} else if (!ldc_address_OK) {
/* Just found a valid address (again) */
/* At this point, skipped_dwords can be == 0
* only when we just started to run.
*/
if (skipped_dwords != 0) {
fprintf(global_config->out_fd,
"\nFound valid LDC address after skipping %zu bytes (one line uses %zu + 0 to 16 bytes)\n",
sizeof(uint32_t) * skipped_dwords, sizeof(dma_log));
}
ldc_address_OK = true;
skipped_dwords = 0;
}
/* fetching entry from dictionary, read the number of
* arguments needed and finish the entire processing of
* this log line.
*/
ret = fetch_entry(&dma_log, &last_timestamp);
if (ret) {
log_err("fetch_entry() failed with: %d, aborting\n", ret);
break;
}
} /* next log entry */
/* End of (etrace) file */
fprintf(global_config->out_fd,
"Skipped %zu bytes after the last statement",
sizeof(uint32_t) * skipped_dwords);
if (!global_config->trace &&
/* maximum 4 arguments supported */
skipped_dwords < sizeof(dma_log) + 4 * sizeof(uint32_t))
fprintf(global_config->out_fd,
". Potential mailbox wrap, check the start of the output for later logs");
fprintf(global_config->out_fd, ".\n");
return ret;
}
/** Compare the dictionary checksum in the firmware image (through
* /sys/kernel/debug/sof/fw_version) with the checksum in the .ldc file.
* @return 0 when the checksums match
*/
static int verify_ldc_checksum(const uint32_t ldc_sum)
{
struct sof_ipc_fw_version ver;
int count;
/* here fw verification should be exploited */
count = fread(&ver, sizeof(ver), 1, global_config->version_fd);
if (!count) {
log_err("Error while reading %s.\n", global_config->version_file);
return -ferror(global_config->version_fd);
}
/* compare source hash value from version file and ldc file */
if (ver.src_hash != ldc_sum) {
log_err("src hash value from version file (0x%x) differ from src hash version saved in dictionary (0x%x).\n",
ver.src_hash, ldc_sum);
return -EINVAL;
}
return 0;
}
static int dump_ldc_info(void)
{
struct snd_sof_uids_header *uids_dict = global_config->uids_dict;
ssize_t remaining = uids_dict->data_length;
const struct sof_uuid_entry *uid_ptr;
FILE *out_fd = global_config->out_fd;
uintptr_t uid_addr;
int cnt = 0;
char *name;
fprintf(out_fd, "logger ABI Version is\t%d:%d:%d\n",
SOF_ABI_VERSION_MAJOR(SOF_ABI_DBG_VERSION),
SOF_ABI_VERSION_MINOR(SOF_ABI_DBG_VERSION),
SOF_ABI_VERSION_PATCH(SOF_ABI_DBG_VERSION));
fprintf(out_fd, "ldc_file ABI Version is\t%d:%d:%d\n",
SOF_ABI_VERSION_MAJOR(global_config->logs_header->version.abi_version),
SOF_ABI_VERSION_MINOR(global_config->logs_header->version.abi_version),
SOF_ABI_VERSION_PATCH(global_config->logs_header->version.abi_version));
fprintf(out_fd, "ldc_file src checksum\t\t0x%08x\n",
global_config->logs_header->version.src_hash);
if (global_config->version_fd) {
struct sof_ipc_fw_version ver;
if (fread(&ver, sizeof(ver), 1, global_config->version_fd) == 1)
fprintf(out_fd, "Loaded FW expects checksum\t0x%08x\n",
ver.src_hash);
}
fprintf(out_fd, "\n");
fprintf(out_fd, "Components uuid dictionary size:\t%zd bytes\n",
remaining);
fprintf(out_fd, "Components uuid base address: \t0x%x\n",
uids_dict->base_address);
fprintf(out_fd, "Components uuid entries:\n");
fprintf(out_fd, "\t%10s %38s %s\n", "ADDRESS", "UUID", "NAME");
uid_ptr = (const struct sof_uuid_entry *)
((uintptr_t)uids_dict + uids_dict->data_offset);
while (remaining > 0) {
name = format_uid_raw(&uid_ptr[cnt], 0, 0, false, false);
uid_addr = get_uuid_key(&uid_ptr[cnt]);
fprintf(out_fd, "\t%p %s\n", (void *)uid_addr, name ? name : missing);
if (name) {
free(name);
name = NULL;
}
remaining -= sizeof(struct sof_uuid_entry);
++cnt;
}
fprintf(out_fd, "\t-------------------------------------------------- cnt: %d\n",
cnt);
return 0;
}
int convert(void)
{
struct snd_sof_logs_header * const logs_hdr = malloc(sizeof(*logs_hdr));
struct snd_sof_uids_header uids_hdr;
int count, ret = 0;
/* const pointer initialized at build time */
if (!global_config)
abort();
if (!logs_hdr)
abort();
/* just a shorter alias */
struct convert_config * const config = global_config;
config->logs_header = logs_hdr;
count = fread(logs_hdr, sizeof(*logs_hdr), 1, config->ldc_fd);
if (!count) {
log_err("Error while reading %s.\n", config->ldc_file);
return -ferror(config->ldc_fd);
}
if (strncmp((char *)logs_hdr->sig, SND_SOF_LOGS_SIG, SND_SOF_LOGS_SIG_SIZE)) {
log_err("Invalid ldc file signature.\n");
return -EINVAL;
}
if (global_config->version_fw && /* -n option */
!global_config->dump_ldc) {
ret = verify_ldc_checksum(logs_hdr->version.src_hash);
if (ret)
return ret;
}
/* default logger and ldc_file abi verification */
if (SOF_ABI_VERSION_INCOMPATIBLE(SOF_ABI_DBG_VERSION,
logs_hdr->version.abi_version)) {
log_err("abi version in %s file does not coincide with abi version used by logger.\n",
config->ldc_file);
log_err("logger ABI Version is %d:%d:%d\n",
SOF_ABI_VERSION_MAJOR(SOF_ABI_DBG_VERSION),
SOF_ABI_VERSION_MINOR(SOF_ABI_DBG_VERSION),
SOF_ABI_VERSION_PATCH(SOF_ABI_DBG_VERSION));
log_err("ldc_file ABI Version is %d:%d:%d\n",
SOF_ABI_VERSION_MAJOR(logs_hdr->version.abi_version),
SOF_ABI_VERSION_MINOR(logs_hdr->version.abi_version),
SOF_ABI_VERSION_PATCH(logs_hdr->version.abi_version));
return -EINVAL;
}
/* read uuid section header */
ret = fseek(config->ldc_fd, logs_hdr->data_offset + logs_hdr->data_length, SEEK_SET);
if (ret) {
log_err("Error while seeking to uuids header from %s.\n", config->ldc_file);
return -errno;
}
count = fread(&uids_hdr, sizeof(uids_hdr), 1, config->ldc_fd);
if (!count) {
log_err("Error while reading uuids header from %s.\n", config->ldc_file);
return -ferror(config->ldc_fd);
}
if (strncmp((char *)uids_hdr.sig, SND_SOF_UIDS_SIG,
SND_SOF_UIDS_SIG_SIZE)) {
log_err("invalid uuid section signature.\n");
return -EINVAL;
}
config->uids_dict = calloc(1, sizeof(uids_hdr) + uids_hdr.data_length);
if (!config->uids_dict) {
log_err("failed to alloc memory for uuids.\n");
return -ENOMEM;
}
memcpy(config->uids_dict, &uids_hdr, sizeof(uids_hdr));
count = fread(config->uids_dict + 1, uids_hdr.data_length, 1,
config->ldc_fd);
if (!count) {
log_err("failed to read uuid section data.\n");
ret = -ferror(config->ldc_fd);
goto out;
}
if (config->dump_ldc) {
ret = dump_ldc_info();
goto out;
}
if (config->filter_config) {
ret = filter_update_firmware();
if (ret) {
log_err("failed to apply trace filter, %d.\n", ret);
goto out;
}
}
ret = logger_read();
out:
free(config->uids_dict);
return ret;
}
Reference in New Issue View Git Blame Copy Permalink