Skip to content

Logger add possibility to make logs output more compact - #2905

Merged
lgirdwood merged 2 commits into
thesofproject:masterfrom
ktrzcinx:logger-path
May 18, 2020
Merged

Logger add possibility to make logs output more compact#2905
lgirdwood merged 2 commits into
thesofproject:masterfrom
ktrzcinx:logger-path

Conversation

@ktrzcinx

@ktrzcinxktrzcinx commented May 4, 2020•
edited
Loading

Copy link
Copy Markdown
Member

Add option to set timestamp precision and second one to cutout trace location

Original output:

$ ./sof-logger -l sof-cnl.ldc -i dma_trace_1.bin
TIMESTAMP DELTA C# COMPONENT LOCATION CONTENT
[ 497588.489583] ( 497588.500000) c0 DMA .../intel/cavs/hda-dma.c:407 hda-dmac: 4 channel 6 -> get
[ 497816.250000] ( 227.760422) c0 DMA .../intel/cavs/hda-dma.c:589 hda-dmac: 4 channel 6 -> config
[ 497899.270833] ( 83.020836) c0 DMA .../intel/cavs/hda-dma.c:464 hda-dmac: 4 channel 6 -> start
[ 497913.906250] ( 14.635417) c0 DMA .../intel/cavs/hda-dma.c:329 hda-dmac: 4 channel 6 -> enable
[ 498012.083333] ( 98.177086) c0 SA src/lib/agent.c:56 perf sys_load peak plat 25185 cpu 73998
[ 498029.322917] ( 17.239584) c0 SCHEDULE_LL ./schedule/ll_schedule.c:178 perf ll_work peak plat 468 cpu 2266
[ 498062.968750] ( 33.645832) c0 SCHEDULE_LL ./schedule/ll_schedule.c:304 task add 0x9e0c0080 dma-trace-task <2b972272-c5b1-4b7e-926f-0fc5cb4c4690>

With flag -L:

$ ../../../build/logger/sof-logger -l sof-cnl.ldc -i dma_trace_1.bin -L
TIMESTAMP DELTA C# COMPONENT CONTENT
[ 497588.489583] ( 497588.500000) c0 DMA hda-dmac: 4 channel 6 -> get
[ 497816.250000] ( 227.760422) c0 DMA hda-dmac: 4 channel 6 -> config
[ 497899.270833] ( 83.020836) c0 DMA hda-dmac: 4 channel 6 -> start
[ 497913.906250] ( 14.635417) c0 DMA hda-dmac: 4 channel 6 -> enable
[ 498012.083333] ( 98.177086) c0 SA perf sys_load peak plat 25185 cpu 73998
[ 498029.322917] ( 17.239584) c0 SCHEDULE_LL perf ll_work peak plat 468 cpu 2266
[ 498062.968750] ( 33.645832) c0 SCHEDULE_LL task add 0x9e0c0080 dma-trace-task <2b972272-c5b1-4b7e-926f-0fc5cb4c4690>

With flag -L -f0:

$ ../../../build/logger/sof-logger -l sof-cnl.ldc -i dma_trace_1.bin -L -f0
TIMESTAMP DELTA C# COMPONENT CONTENT
[ 497588] ( 497588) c0 DMA hda-dmac: 4 channel 6 -> get
[ 497816] ( 228) c0 DMA hda-dmac: 4 channel 6 -> config
[ 497899] ( 83) c0 DMA hda-dmac: 4 channel 6 -> start
[ 497914] ( 15) c0 DMA hda-dmac: 4 channel 6 -> enable
[ 498012] ( 98) c0 SA perf sys_load peak plat 25185 cpu 73998
[ 498029] ( 17) c0 SCHEDULE_LL perf ll_work peak plat 468 cpu 2266
[ 498063] ( 34) c0 SCHEDULE_LL task add 0x9e0c0080 dma-trace-task <2b972272-c5b1-4b7e-926f-0fc5cb4c4690>
[ 498077] ( 14) c0 SCHEDULE_LL task params pri 4 flags 0 start 500000 period 500000
[ 498093] ( 16) c0 SCHEDULE_LL num_tasks 2 total_num_tasks 2
[ 532524] ( 34431) c0 IPC ipc: hdr 0x30010000 tx (76) > rx (28)
[ 532537] ( 13) c0 IPC ipc: pipe 1 comp 0 -> new (type 1)
[ 532568] ( 31) c0 COMP comp new host <8b9d100c-6d78-418f-90a3-e0e805d0852b> type 1 pipe_id 1 id 0

lgirdwood
lgirdwood reviewed May 7, 2020
View reviewed changes

@lgirdwoodlgirdwood left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Can you give before/after examples in the commit messages. Thanks.

@ktrzcinx

ktrzcinx commented May 8, 2020

Copy link
Copy Markdown
MemberAuthor

@lgirdwood updated

@lgirdwood

lgirdwood commented May 8, 2020

Copy link
Copy Markdown
Member

@ktrzcinx the updates look good, but I mean paste the before/after into the commit message not the PR message. This way it's obvious for anyone reading the git logs as the current messages are vague.

@ktrzcinx

ktrzcinx commented May 8, 2020

Copy link
Copy Markdown
MemberAuthor

@lgirdwood updated

dbaluta
dbaluta reviewed May 8, 2020
View reviewed changes
Comment threadtools/logger/convert.c Outdated
@ktrzcinx
logger: Add option to cutout trace location
6aa98d9
It allows to make logs output more compact, it change:
$ ./sof-logger -l sof-cnl.ldc -i dma_trace_1.bin
TIMESTAMP DELTA C# COMPONENT LOCATION CONTENT
[ 497588.489583] ( 497588.500000) c0 DMA .../intel/cavs/hda-dma.c:407 hda-dmac: 4 channel 6 -> get
to:
$ ./sof-logger -l sof-cnl.ldc -i dma_trace_1.bin -L
TIMESTAMP DELTA C# COMPONENT CONTENT
[ 497588.489583] ( 497588.500000) c0 DMA hda-dmac: 4 channel 6 -> get
Signed-off-by: Karol Trzcinski <karolx.trzcinski@linux.intel.com>
@ktrzcinx
logger: Add option to set timestamp precision
e289245
Shorten timestamp makes logger output more compact, it change:
$ ./sof-logger -l sof-cnl.ldc -i dma_trace_1.bin
TIMESTAMP DELTA C# COMPONENT LOCATION CONTENT
[ 497588.489583] ( 497588.500000) c0 DMA .../intel/cavs/hda-dma.c:407 hda-dmac: 4 channel 6 -> get
to:
$ sof-logger -l sof-cnl.ldc -i dma_trace_1.bin -f0
TIMESTAMP DELTA C# COMPONENT LOCATION CONTENT
[ 497588] ( 497588) c0 DMA .../intel/cavs/hda-dma.c:407 hda-dmac: 4 channel 6 -> get
Signed-off-by: Karol Trzcinski <karolx.trzcinski@linux.intel.com>
lgirdwood
lgirdwood approved these changes May 13, 2020
View reviewed changes

@lgirdwoodlgirdwood left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

@ktrzcinx thank you, GH doesn't render it nicely but this should look fine with git

@lgirdwood

lgirdwood commented May 13, 2020

Copy link
Copy Markdown
Member

@ktrzcinx can you double check CI, it looks like the build has failed ? Seems unrelated to this ?

@ktrzcinx

ktrzcinx commented May 13, 2020

Copy link
Copy Markdown
MemberAuthor
Exception ValueError occurred at 'signal.py':47
signal only works in main thread

and

May 10 22:34:30 jf-apl-up2-nocodec-1 kernel: [ 970.716052] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x80010000 size 216

So nothing related with logger, especially when I added functionality is disabled in CI tests (need to pass extra flags)

@lgirdwood
lgirdwood merged commit d7b535e into thesofproject:masterMay 18, 2020
marc-hb
marc-hb reviewed Sep 15, 2020
View reviewed changes
Comment threadtools/logger/convert.c
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

Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@dbalutadbalutadbaluta left review comments
@marc-hbmarc-hbmarc-hb left review comments
@lgirdwoodlgirdwoodlgirdwood approved these changes
@mmaka1mmaka1mmaka1 approved these changes
@akloniexakloniexAwaiting requested review from akloniex
@bkokoszxbkokoszxAwaiting requested review from bkokoszx
@xiulipanxiulipanAwaiting requested review from xiulipan

Assignees

No one assigned

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

5 participants

@ktrzcinx@lgirdwood@dbaluta@mmaka1@marc-hb