Skip to content

Logger add possibility to make logs output more compact#2905

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

Merged
lgirdwood merged 2 commits into from
May 18, 2020
Merged

Logger add possibility to make logs output more compact #2905

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
6aa98d9
logger: Add option to cutout trace location
ktrzcinx May 4, 2020
e289245
logger: Add option to set timestamp precision
ktrzcinx May 4, 2020
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
56 changes: 39 additions & 17 deletions tools/logger/convert.c
View file
Open in desktop
Original file line numberDiff line numberDiff line change
Expand Up@@ -204,11 +204,19 @@ static double to_usecs(uint64_t time, double clk)
}
Comment thread
ktrzcinx marked this conversation as resolved.
Outdated


static inline void print_table_header(FILE *out_fd)
static inline void print_table_header(FILE *out_fd, int hide_location,
int float_precision)
{
fprintf(out_fd, "%18s %18s %2s %-18s %-29s %s\n",
"TIMESTAMP", "DELTA", "C#", "COMPONENT", "LOCATION",
"CONTENT");
char time_fmt[32];

snprintf(time_fmt, sizeof(time_fmt), "%%%ds %%%ds ",
float_precision + 12, float_precision + 12);
fprintf(out_fd, time_fmt, "TIMESTAMP", "DELTA");
fprintf(out_fd, "%2s %-18s ", "C#", "COMPONENT");
if (!hide_location)
fprintf(out_fd, "%-29s ", "LOCATION");
fprintf(out_fd, "%s\n", "CONTENT");

fflush(out_fd);
}

Expand DownExpand Up@@ -315,11 +323,13 @@ static char *format_file_name(char *file_name_raw, int full_name)
static void print_entry_params(FILE *out_fd,
const struct snd_sof_uids_header *uids_dict,
const struct log_entry_header *dma_log, const struct ldc_entry *entry,
uint64_t last_timestamp, double clock, int use_colors, int raw_output)
uint64_t last_timestamp, double clock, int use_colors, int raw_output,
int hide_location, int float_precision)
{
char ids[TRACE_MAX_IDS_STR];
float dt = to_usecs(dma_log->timestamp - last_timestamp, clock);
struct proc_ldc_entry proc_entry;
static char time_fmt[32];

if (raw_output)
use_colors = 0;
Expand All@@ -335,7 +345,10 @@ static void print_entry_params(FILE *out_fd,
ids[0] = '\0';

if (raw_output) {
const char *entry_fmt = "%s%u %u %s%s%s %.6f %.6f (%s:%u) ";
const char *entry_fmt = "%s%u %u %s%s%s ";

snprintf(time_fmt, sizeof(time_fmt), "%%.%df %%.%df ",
float_precision, float_precision);

fprintf(out_fd, entry_fmt,
entry->header.level == use_colors ?
Expand All@@ -346,14 +359,20 @@ static void print_entry_params(FILE *out_fd,
entry->header.component_class,
dma_log->uid),
raw_output && strlen(ids) ? "-" : "",
ids,
to_usecs(dma_log->timestamp, clock),
dt,
format_file_name(entry->file_name, raw_output),
entry->header.line_idx);
ids);
fprintf(out_fd, time_fmt, to_usecs(dma_log->timestamp, clock),
dt);
if (!hide_location)
fprintf(out_fd, "(%s:%u) ",
format_file_name(entry->file_name, raw_output),
entry->header.line_idx);
} else {
/* timestamp */
fprintf(out_fd, "%s[%16.6f] (%16.6f)%s ",
snprintf(time_fmt, sizeof(time_fmt),
"%%s[%%%d.%df] (%%%d.%df)%%s ",
float_precision + 10, float_precision,
float_precision + 10, float_precision);

@marc-hbmarc-hbSep 15, 2020•
edited
Loading

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

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

With a crazy long precision snprintf can truncate time_fmt. Reported by gcc 9.3 -Werr and fixed in PR 3411#3412 sorry

fprintf(out_fd, time_fmt,
use_colors ? KGRN : "",
to_usecs(dma_log->timestamp, clock), dt,
use_colors ? KNRM : "");
Expand All@@ -371,9 +390,10 @@ static void print_entry_params(FILE *out_fd,
use_colors ? KNRM : "");

/* location */
fprintf(out_fd, "%24s:%-4u ",
format_file_name(entry->file_name, raw_output),
entry->header.line_idx);
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",
Expand DownExpand Up@@ -525,7 +545,8 @@ static int fetch_entry(const struct convert_config *config,
config->uids_dict,
dma_log, &entry, *last_timestamp,
config->clock, config->use_colors,
config->raw_output);
config->raw_output, config->hide_location,
config->float_precision);
*last_timestamp = dma_log->timestamp;

/* set f_ldc file position to the beginning */
Expand DownExpand Up@@ -603,7 +624,8 @@ static int logger_read(const struct convert_config *config,
uint64_t last_timestamp = 0;

if (!config->raw_output)
print_table_header(config->out_fd);
print_table_header(config->out_fd, config->hide_location,
config->float_precision);

if (config->serial_fd >= 0)
/* Wait for CTRL-C */
Expand Down
2 changes: 2 additions & 0 deletions tools/logger/convert.h
View file
Open in desktop
Original file line numberDiff line numberDiff line change
Expand Up@@ -37,6 +37,8 @@ struct convert_config {
int serial_fd;
int raw_output;
int dump_ldc;
int hide_location;
int float_precision;
struct snd_sof_uids_header *uids_dict;
};

Expand Down
18 changes: 17 additions & 1 deletion tools/logger/logger.c
View file
Open in desktop
Original file line numberDiff line numberDiff line change
Expand Up@@ -51,6 +51,10 @@ static void usage(void)
fprintf(stdout, "%s:\t -r\t\t\tLess formatted output for "
"chained log processors\n",
APP_NAME);
fprintf(stdout, "%s:\t -L\t\t\tHide log location in source code\n",
APP_NAME);
fprintf(stdout, "%s:\t -f precision\t\t\tset timestamp precision\n",
APP_NAME);
fprintf(stdout, "%s:\t -d\t\t\tDump ldc information\n", APP_NAME);
exit(0);
}
Expand DownExpand Up@@ -157,8 +161,10 @@ int main(int argc, char *argv[])
config.serial_fd = -EINVAL;
config.raw_output = 0;
config.dump_ldc = 0;
config.hide_location = 0;
config.float_precision = 6;

while ((opt = getopt(argc, argv, "ho:i:l:ps:c:u:tev:rd")) != -1) {
while ((opt = getopt(argc, argv, "ho:i:l:ps:c:u:tev:rdLf:")) != -1) {
switch (opt) {
case 'o':
config.out_file = optarg;
Expand DownExpand Up@@ -199,6 +205,16 @@ int main(int argc, char *argv[])
config.version_fw = 1;
config.version_file = optarg;
break;
case 'L':
config.hide_location = 1;
break;
case 'f':
config.float_precision = atoi(optarg);
if (config.float_precision < 0) {
usage();
return -EINVAL;
}
break;
case 'd':
config.dump_ldc = 1;
break;
Expand Down