Add new mtrace_printf() and use it for DMA init error handling and demoting banner to INFO level #4389

marc-hb · 2021-06-23T03:00:35Z

5 commits, per-commit review is recommended.

This is a re-submission/recycling of 85% of the earlier "restore early tracing" PR previously reviewed in #4334: everything except the actual and final restoration of early tracing which is currently failing on BDW and BYT which I have no time to debug right now. Maybe later.

src/trace/dma-trace.c

paulstelian97 · 2021-06-23T08:15:37Z

CC @iuliana-prodan The commit "timer.h: add platform_safe_get_time(timer) and use it in trace.c" is potentially interesting after the discussions yesterday.

src/include/sof/drivers/timer.h

iuliana-prodan · 2021-06-23T08:20:10Z

CC @iuliana-prodan The commit "timer.h: add platform_safe_get_time(timer) and use it in trace.c" is potentially interesting after the discussions yesterday.

@paulstelian97 I was writing my review/questions while you were writing this :)

paulstelian97

Other than existing comments this looks good. I'll wait for those to be resolved before approve though.

marc-hb · 2021-06-25T06:23:25Z

If a SOF_MEM_ZONE_SYS_SHARED allocation fails you'll get a panic, no need to check

Thanks @lyakh , very useful. I changed the comment and... tried to use panics, which cost me 1+ day because of bug #1346 :-(

To avoid this happening again I'm adding some panic.c comments and a workaround suggestion in #4401

Done

lgirdwood

Looks good, just one question on whether we want a new timer API or just make the current one safe.

lgirdwood · 2021-06-27T19:29:15Z

src/include/sof/drivers/timer.h

Would it not be better to make the default version safe ? (and return time 0 to indicate no timer running)

Maybe, I don't know. You tell me. So far I've been spending at least 80% of my time trying to fix issues fairly distant from my actual objectives so this time I tried to minimize the changes but maybe I shouldn't have?

There is a variety of platform_timer_get(timer) implementations. Some implementations don't even look at their timer argument: so these platforms would then lose even more timestamps for no real reason.

At least one platform performs an assert(timer), maybe because it was considered valuable not to keep running with broken timers? Tracing is still useful without timestamps but I wouldn't be so sure about other areas: I can easily imagine some threads stuck forever.

Considering such "diversity" I chose not to open that can of worms and to change only the area in this PR. As of now the new "safe" function is meant to be used only in areas with tricky boot dependencies; like tracing.

(and return time 0 to indicate no timer running)

As explained in the comment, I'm not returning zero but on small value on purpose: because zero looks like something is wrong.

0 looks perfectly fine to me. Look at dmesg soon after a system boot - the first messages are marked with time 0. Looks much more logical than any random "small value" to me.

This non-zero value is useful to make the difference with platform_timer_get(timer) returning zero (for good or bad reasons). When everyone and everything returns zero including buggy code (but not just), then there's no way to tell where it came from.

marc-hb · 2021-06-27T21:19:25Z

I just pushed v3 5c9f2e8 that adds mtrace_printf() for Zephyr too, I had forgotten to extract that from my stack or other WIP.

EDIT: https://sof-ci.01.org/sofpr/PR4389/build9504/devicetest is suspiciously all green

lyakh

a couple of minor suggestions, should be good after that

lyakh · 2021-06-28T06:21:34Z

src/include/sof/drivers/timer.h

0 looks perfectly fine to me. Look at dmesg soon after a system boot - the first messages are marked with time 0. Looks much more logical than any random "small value" to me.

src/trace/trace.c

lyakh · 2021-06-28T06:40:23Z

src/trace/trace.c

why (void *)? the first argument of put_header() is of type uint32_t *

Because packet is a char []. I'll make the first argument of put_header() a void *, that requires no other change anywhere, not even in the put_header() code.

lyakh · 2021-06-28T06:54:03Z

src/trace/dma-trace.c

why is this needed? It's true, that memory cannot be freed, but the allocated buffer is still there and it's valid... Any specific need for this change? dma_trace_initialized() would return false without it too anyway?

dma_trace_initialized() would return false without it too anyway?

Yes but some part of the code not using dma_trace_initialized() would not and would crash. So this is safer and costs practically nothing.

lyakh · 2021-06-28T06:55:24Z

src/trace/dma-trace.c

it's NULL here, why not just print a meaningful description like "not available" or something?

src/trace/dma-trace.c

marc-hb

Thanks for the very thorough review! I will apply all the other, unanswered suggestions.

marc-hb · 2021-06-28T07:10:54Z

src/include/sof/drivers/timer.h

This non-zero value is useful to make the difference with platform_timer_get(timer) returning zero (for good or bad reasons). When everyone and everything returns zero including buggy code (but not just), then there's no way to tell where it came from.

marc-hb · 2021-06-28T07:12:45Z

src/trace/dma-trace.c

dma_trace_initialized() would return false without it too anyway?

Yes but some part of the code not using dma_trace_initialized() would not and would crash. So this is safer and costs practically nothing.

marc-hb · 2021-06-28T07:26:32Z

src/trace/trace.c

Because packet is a char []. I'll make the first argument of put_header() a void *, that requires no other change anywhere, not even in the put_header() code.

Zephyr's printk does not work like Linuxs printk Signed-off-by: Marc Herbert <marc.herbert@intel.com>

Found by chance while looking for something else. This makes no difference right now because we checked the "length" in the line immediately before but let's do the right thing anyway, at the very least it's more readable. Signed-off-by: Marc Herbert <marc.herbert@intel.com>

Returns a small constant instead of crashing platform_timer_get() when timer is NULL. This is required to restore early tracing before sof->timer is initialized. Signed-off-by: Marc Herbert <marc.herbert@intel.com>

Direct access to mbox shared memory logging when DMA tracing is either not initialized yet or disabled or found broken for any reason. Signed-off-by: Marc Herbert <marc.herbert@intel.com>

Replace some tr_err() too. Signed-off-by: Marc Herbert <marc.herbert@intel.com>

... down from ERROR. It was never an error, this was a hack to be duplicated to both trace and etrace. This will make it easier to search for actual errors. Also make the banners slightly different between etrace and trace thanks to new SHM: and DMA: prefixes. This makes identification of log files easier. Signed-off-by: Marc Herbert <marc.herbert@intel.com>

marc-hb

https://sof-ci.01.org/sofpr/PR4389/build9518/devicetest and everything else for that commit is green.

src/trace/dma-trace.c

marc-hb · 2021-07-03T06:45:54Z

The addition of mtrace_printf() broke !CONFIG_TRACE, fixed in #4447

marc-hb marked this pull request as ready for review June 23, 2021 03:46

marc-hb requested review from akloniex, dbaluta, lbetlej, lgirdwood, mmaka1 and plbossart as code owners June 23, 2021 03:46

marc-hb mentioned this pull request Jun 23, 2021

Restore early tracing #4334

Closed

marc-hb requested review from kv2019i and paulstelian97 June 23, 2021 03:49

lyakh previously requested changes Jun 23, 2021

View reviewed changes

src/trace/dma-trace.c Outdated Show resolved Hide resolved

src/trace/dma-trace.c Outdated Show resolved Hide resolved

iuliana-prodan reviewed Jun 23, 2021

View reviewed changes

src/include/sof/drivers/timer.h Outdated Show resolved Hide resolved

paulstelian97 reviewed Jun 24, 2021

View reviewed changes

marc-hb force-pushed the mtrace-printf branch from 2b16fd4 to fedc96b Compare June 25, 2021 06:04

paulstelian97 approved these changes Jun 25, 2021

View reviewed changes

lgirdwood reviewed Jun 27, 2021

View reviewed changes

marc-hb force-pushed the mtrace-printf branch from fedc96b to 5c9f2e8 Compare June 27, 2021 20:54

lyakh requested changes Jun 28, 2021

View reviewed changes

marc-hb commented Jun 28, 2021

View reviewed changes

marc-hb mentioned this pull request Jun 28, 2021

[Query] How can I use sof-logger with Zephyr .ri image? #4420

Closed

marc-hb added 5 commits June 28, 2021 23:42

check patch: turn off printk warnings

4f9ad88

Zephyr's printk does not work like Linuxs printk Signed-off-by: Marc Herbert <marc.herbert@intel.com>

timer.h: add platform_safe_get_time(timer) and use it in trace.c

930b813

Returns a small constant instead of crashing platform_timer_get() when timer is NULL. This is required to restore early tracing before sof->timer is initialized. Signed-off-by: Marc Herbert <marc.herbert@intel.com>

trace.c: add mtrace_printf() low-level shortcut

c9c177b

Direct access to mbox shared memory logging when DMA tracing is either not initialized yet or disabled or found broken for any reason. Signed-off-by: Marc Herbert <marc.herbert@intel.com>

dma-trace.c: use new mtrace_printf() to add some error handling

3bb5060

Replace some tr_err() too. Signed-off-by: Marc Herbert <marc.herbert@intel.com>

marc-hb force-pushed the mtrace-printf branch from 5c9f2e8 to 8d26d43 Compare June 28, 2021 23:43

marc-hb commented Jun 29, 2021

View reviewed changes

src/trace/dma-trace.c Outdated Show resolved Hide resolved

lgirdwood approved these changes Jun 29, 2021

View reviewed changes

lgirdwood merged commit 02c21c2 into thesofproject:main Jun 29, 2021

marc-hb deleted the mtrace-printf branch June 29, 2021 23:19

Add new mtrace_printf() and use it for DMA init error handling and demoting banner to INFO level #4389

Add new mtrace_printf() and use it for DMA init error handling and demoting banner to INFO level #4389

Uh oh!

Conversation

marc-hb commented Jun 23, 2021

Uh oh!

Uh oh!

Uh oh!

paulstelian97 commented Jun 23, 2021

Uh oh!

Uh oh!

iuliana-prodan commented Jun 23, 2021

Uh oh!

paulstelian97 left a comment

Choose a reason for hiding this comment

Uh oh!

marc-hb commented Jun 25, 2021

Uh oh!

lgirdwood left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

marc-hb commented Jun 27, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

lyakh left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

marc-hb left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

marc-hb left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

marc-hb commented Jul 3, 2021

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

marc-hb commented Jun 27, 2021 •

edited

Loading