ASoC: SOF: trace: fix trace doesn't update issue #248

keyonjie · 2018-11-06T07:41:12Z

We have issues for DMA trace if runtime suspend is turned on:
a. Those logs before suspend will be cleared/overwritten after resume.
b. If we run logger at suspend, logs won't be updated though the ADSP is
running after that.

To fix these issues, this commit change the DMA trace behavior as below:

move init_waitqueue_head() to snd_sof_init_trace(), only
init_waitqueue() at first boot.
add a member host_init_offset to store the last trace offset before
suspend, and calculate the available log size based on it.
add a function hda_dsp_trace_setup_bdl() to setup bdl entries for DMA
trace, when host_init_offset!=0, we divide buffer into 2 BDL entries:
[host_init_offset, buffer_size) and [0, host_init_offset). This make FW
possible to copy new logs to destination from host_init_offset, which
won't overwrite the existed logs before suspend.

With these changes, both issues mentioned above are resolved on APL.

Todo: for SKL- platforms where not using BDL entries, FW to support
non-0 offset need to be implemented for those platforms, please refer
to this:
thesofproject/sof#544

Signed-off-by: Keyon Jie [email protected]

sound/soc/sof/intel/hda.h

sound/soc/sof/sof-priv.h

lgirdwood

Improve the error message so the bug reports are more meaningful.

sound/soc/sof/intel/hda-stream.c

sound/soc/sof/trace.c

plbossart

The code can be enhanced to avoid duplication of _setup_bdl functions, just add an offset as a parameter.

sound/soc/sof/intel/hda-stream.c

sound/soc/sof/intel/hda-trace.c

We clear hstream->opened in hda_dsp_stream_put_cstream(), the redundant clear before that is leading to *_put_cstream() fail and error like 'tag 1 not opened!' reported. Here remove this extra clear to fix the issue. Signed-off-by: Keyon Jie <[email protected]>

Today we init trace wait_queue at each resume, snd_sof_init_trace_ipc(), which will clear the wait_queue entry that is waiting for trace update at suspend, that will lead to sof-logger infinitely waiting for logger tools like sof-logger so no trace updating or refreshing though we are back to resume and playback. Here move this wait_queue initialization to snd_sof_init_trace() which is called at first boot only, keep waiting trace update during S0->S3->S0, and fix logger tools no update issues. Signed-off-by: Keyon Jie <[email protected]>

We have issues for DMA trace if runtime suspend is turned on, those logs before suspend will be cleared/overwritten after resume. To fix the issue, this commit change the DMA trace behavior as below: We add a member trace_init_offset to store the last trace offset beforei suspend, and calculate the available log size based on it. We also extend hda_dsp_stream_setup_bdl() to support non-0 offset, which is needed for trace BDL setup. This make FW possible to copy new logs to destination from trace_init_offset, which won't overwrite the existed logs before suspend. With these changes, the issue mentioned above is resolved on APL. Todo: for SKL- platforms where not using BDL entries, FW to support non-0 offset need to be implemented for those platforms, please refer to this: thesofproject/sof#544 Signed-off-by: Keyon Jie <[email protected]>

keyonjie · 2018-11-07T10:56:16Z

@plbossart @lgirdwood comments addressed and updated, please help review.

plbossart

Keyon, this is an impressive patch and you obviously know what you are doing.

The code is however not quite readable with renamed variables which make comments confusing, I cannot figure out if the BDL handling is correct or not - which is very scary since it's the foundation of all DMA transfers and you have a duplication of an init_waitqueue.
Do you mind respinning the patch to make it more accessible to the rest of us and more maintainable. The trace is complicated enough, anything we can do to make the code simpler is progress.

And last, I wasn't able to figure out if this patch breaks legacy code. If it does then obviously it'd be a problem to merge it in the mainline?

Thanks!

sound/soc/sof/intel/hda.h

sound/soc/sof/intel/hda-stream.c

plbossart · 2018-11-08T15:36:29Z

sound/soc/sof/intel/hda-stream.c

+			is_wrap = true;
+		}
+
+		size += bytes;
 	}


I am unable to determine if the code is correct or not, it's significantly changed from the initial code and I am hesitant to sign-off here. Maybe it's correct, but it's not self-explanatory nor easy to debug/maintain. It'd be easier to deal with logical steps, such as from init_offset to first period start, then all regular periods, then end of buffer alignment, then wrap until last period and again remaining bytes?

@plbossart I've verified that the logic here is correct. quite impressive @keyonjie

But might be easier to follow if you break it up like pierre suggests.

hmm, actually I spent hours to abstract and make it as simple as what it is now, otherwise, it will be inevitable lengthy and low efficiency with those 5 steps Pierre mentioned.

You may have spent hours but I have no way of knowing if it works or not.
How many times have we faced issues with corner cases in this sort of code?
Please.

So, shall I try add more comments with logic analyzing?

The ask is to find a way to make things self-explanatory with all corner cases handled. You can do this with simple code or comments, your choice.

plbossart · 2018-11-08T15:39:40Z

sound/soc/sof/trace.c

 		return buffer_size - pos;
 	else
-		return sdev->host_offset - pos;
+		return host_offset - pos;
 }


I don't like copy/paste code with different comments, can this be a helper function?

hmm, make sense, let me refine it.

sound/soc/sof/trace.c

plbossart · 2018-11-08T15:46:33Z

sound/soc/sof/trace.c

+	 * send offset to FW to require copying new logs
+	 * start from new offset if possible.
+	 */
+	params.buffer.offset = sdev->trace_init_offset;


I am now officially confused. I understand trace_init_offset and the offset to be used on resume. Now you are using it as a dynamic value that's passed to firmware, not sure I get what you are trying to do.

This is used to cover that case on SKL- platforms where we don't have host DMA, as I mentioned in the PR commit message:

Todo: for SKL- platforms where not using BDL entries, FW to support
non-0 offset need to be implemented for those platforms, please refer
to this:
thesofproject/sof#544

Then let's be clear: I will not merge a hardware-agnostic kernel patch that will only work with SKL+ firmware. Our team has the charter to deal with legacy platforms so the firmware changes need to happen first.

hmm, this was the biggest concern from me when writing this patch, let me raise #544 and try if we can speed up the implementation in FW side.

Something is wrong with your references, torvalds#544 does not refer to any firmware issues

sorry, it should be thesofproject/sof#544.
by the way, @plbossart , just synced with @ranj063 , we actually haven't enable PM on SKL- platforms yet, so init_offset there are always 0, we this PR won't impact the current behaviors on those platforms.

plbossart · 2018-11-08T15:47:14Z

sound/soc/sof/trace.c

@@ -236,6 +256,8 @@ int snd_sof_init_trace(struct snd_sof_dev *sdev)

 	init_waitqueue_head(&sdev->trace_sleep);

+	init_waitqueue_head(&sdev->trace_sleep);


why are we initializing the waitqueue twice?

sorry, this is refining error with 'patch am', will fix it, thanks.

plbossart · 2018-11-08T15:48:20Z

sound/soc/sof/trace.c

-		sdev->host_offset = posn->host_offset;
+	if (sdev->dtrace_is_enabled &&
+	    sdev->trace_offset != posn->host_offset) {
+		sdev->trace_offset = posn->host_offset;
 		wake_up(&sdev->trace_sleep);


The code is becoming unreadable. Please keep the initial definition of host_offset and init_host_offset, the introduction of 'trace' makes things difficult to follow.

I agree with Liam that 'trace' is better than 'host' here, as it is member of sdev, but only used for trace(not for other streams).

then change the dma_trace_posn structure to use trace_offset... It makes no sense to use different fields in different structures when it's the same concept.

the dma_trace_posn struct is replied from FW, looks host_offset better there. the sdev is only used in driver, so they have actually different standpoint, can we just keep this?

I don't understand your reply. Why would the same concept be named differently if this is firmware or driver?

sound/soc/sof/intel/hda-stream.c

ranj063 · 2018-11-09T05:39:18Z

sound/soc/sof/intel/hda-stream.c

+ *			     init_offset
+ *				 |
+ * |------|...........|---------S-------|------|........|--------|-------|
+ *  bdl[n] bdl[n+j]    bdl[e-1] | bdl[0] bdl[1] bdl[m]   bdl[n-2] bdl[n-1]


@keyonjie this is so difficult to follow. If I understand it correctly there are only 2 cases:
if init_offset ==0,there are bufsize/periodbytes (+1 in case it is not evenly divisible) periods
else there are 2 periods (or entries as you call it) right?

I am confused with n,m,j and e in the above diagram.

@ranj063 the 2nd case what you mentioned can be more complicated, there can be > 2 periods there.
What the comment I wrote here is aim to abstract all possible cases to this common one.

You can ignore n, m, j, e here, though they are useful when writing code in logic that Pierre mentioned:

from init_offset to first period start: bdl[0]

then all regular periods, bdl[m]

then end of buffer alignment, bdl[n-1] ---- We have n items before buffer end;

then wrap until last period, bdl[e-2]

and again remaining bytes, bdl[e-1]. ---- We have e items in total.

@keyonjie Yes, I understand the logic and ther is not doubt it is correct.

If I may make a suggestion: can we treat the case of a non-zero init_offset as 2 separate buffers,
then we end up with just as many bld entries except that the partial segments will be only at the end of the 2 buffer areas. For example:
Case 1: init_offset = 0
num of period_bytes size bdl entries = 5
num of partial bdl entries = 1

init_offset = 0
|
|------|------|------|------|------|---|

Case 2: init_offset = 16
num of period_bytes size bdl entries = 4
num of partial bdl entries = 2

init_offset = 16

|------|------|----|------|------|-----|

So the partial fragments are at the end of the 2 areas ( 0 - init_offset -1, init_offset - bufsize).

But with the current case there will be 3 partial entries.

Anyway, this is only to improve maintainability. I am fine if the code is merged as is too.

@keyonjie Yes, I understand the logic and ther is not doubt it is correct.

If I may make a suggestion: can we treat the case of a non-zero init_offset as 2 separate buffers,
then we end up with just as many bld entries except that the partial segments will be only at the end of the 2 buffer areas. For example:
Case 1: init_offset = 0
num of period_bytes size bdl entries = 5
num of partial bdl entries = 1

init_offset = 0
|
|------|------|------|------|------|---|

Case 2: init_offset = 16
num of period_bytes size bdl entries = 4
num of partial bdl entries = 2

init_offset = 16

|------|------|----|------|------|-----|

So the partial fragments are at the end of the 2 areas ( 0 - init_offset -1, init_offset - bufsize).

But with the current case there will be 3 partial entries.

Sorry I don't catch you here, there will be only 2 partial entries in your sample.

Anyway, this is only to improve maintainability. I am fine if the code is merged as is too.

@keyonjie what I meant was just break up the stream->bufsize into 2 and then assign bdl entries individually for [init_offset, buf_size) and then [0, init_offset -1). This way the logic will be a lot easier to follow. Let me take a swipe at it today and send you a patch

@ranj063 the init_offset may be used for normal audio stream also, so we still need assign bdl entries for periods when init_offset!=0.

sound/soc/sof/intel/hda-stream.c

plbossart · 2018-11-09T16:25:41Z

sound/soc/sof/intel/hda.h

@@ -442,14 +448,15 @@ void hda_dsp_stream_free(struct snd_sof_dev *sdev);
 int hda_dsp_stream_hw_params(struct snd_sof_dev *sdev,
 			     struct hdac_ext_stream *stream,
 			     struct snd_dma_buffer *dmab,
-			     struct snd_pcm_hw_params *params);
+			     struct snd_pcm_hw_params *params,
+			     enum sof_hda_tream_type stream_type);


and typo here as well

thanks, will change.

keyonjie · 2018-11-14T03:04:02Z

Let me close this long conversation PR, split and create new PRs.

keyonjie · 2018-11-20T01:16:00Z

update the status of logger issues:
after #287 merged, issue #271 and thesofproject/sof#526 are fixed, @ranj063 please backport it to cros branch.
after manually applied #287 and #237, thesofproject/sof#401 is already fixed on my observation.

The left logger issue is: the trace log before suspend will be cleared after resume, this is known limitation in our current design, the issue is not so urgent and no complaint about it yet, the bdl refining part in this PR(#248) can fix that, I will refine and send new PR for it.

…e_event_gen_test_exit() When test_gen_kprobe_cmd() failed after kprobe_event_gen_cmd_end(), it will goto delete, which will call kprobe_event_delete() and release the corresponding resource. However, the trace_array in gen_kretprobe_test will point to the invalid resource. Set gen_kretprobe_test to NULL after called kprobe_event_delete() to prevent null-ptr-deref. BUG: kernel NULL pointer dereference, address: 0000000000000070 PGD 0 P4D 0 Oops: 0000 [#1] SMP PTI CPU: 0 PID: 246 Comm: modprobe Tainted: G W 6.1.0-rc1-00174-g9522dc5c87da-dirty #248 Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.15.0-0-g2dd4b9b3f840-prebuilt.qemu.org 04/01/2014 RIP: 0010:__ftrace_set_clr_event_nolock+0x53/0x1b0 Code: e8 82 26 fc ff 49 8b 1e c7 44 24 0c ea ff ff ff 49 39 de 0f 84 3c 01 00 00 c7 44 24 18 00 00 00 00 e8 61 26 fc ff 48 8b 6b 10 <44> 8b 65 70 4c 8b 6d 18 41 f7 c4 00 02 00 00 75 2f RSP: 0018:ffffc9000159fe00 EFLAGS: 00010293 RAX: 0000000000000000 RBX: ffff88810971d268 RCX: 0000000000000000 RDX: ffff8881080be600 RSI: ffffffff811b48ff RDI: ffff88810971d058 RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 R10: ffffc9000159fe58 R11: 0000000000000001 R12: ffffffffa0001064 R13: ffffffffa000106c R14: ffff88810971d238 R15: 0000000000000000 FS: 00007f89eeff6540(0000) GS:ffff88813b600000(0000) knlGS:0000000000000000 CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 CR2: 0000000000000070 CR3: 000000010599e004 CR4: 0000000000330ef0 DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 Call Trace: <TASK> __ftrace_set_clr_event+0x3e/0x60 trace_array_set_clr_event+0x35/0x50 ? 0xffffffffa0000000 kprobe_event_gen_test_exit+0xcd/0x10b [kprobe_event_gen_test] __x64_sys_delete_module+0x206/0x380 ? lockdep_hardirqs_on_prepare+0xd8/0x190 ? syscall_enter_from_user_mode+0x1c/0x50 do_syscall_64+0x3f/0x90 entry_SYSCALL_64_after_hwframe+0x63/0xcd RIP: 0033:0x7f89eeb061b7 Link: https://lore.kernel.org/all/[email protected]/ Fixes: 6483624 ("tracing: Add kprobe event command generation test module") Signed-off-by: Shang XiaoJing <[email protected]> Cc: [email protected] Acked-by: Masami Hiramatsu (Google) <[email protected]> Signed-off-by: Masami Hiramatsu (Google) <[email protected]>

keyonjie requested review from plbossart, ranj063 and lgirdwood November 6, 2018 07:41

keyonjie mentioned this pull request Nov 6, 2018

Speaker-test hangs on close if rmbox -t open then dsp panic thesofproject/sof#401

Closed

keyonjie force-pushed the trace_fix branch from e95b724 to aa4cf3e Compare November 6, 2018 09:39

lgirdwood requested changes Nov 6, 2018

View reviewed changes

sound/soc/sof/intel/hda.h Outdated Show resolved Hide resolved

sound/soc/sof/sof-priv.h Outdated Show resolved Hide resolved

keyonjie force-pushed the trace_fix branch from aa4cf3e to 17e7587 Compare November 6, 2018 14:46

lgirdwood requested changes Nov 6, 2018

View reviewed changes

sound/soc/sof/intel/hda-stream.c Outdated Show resolved Hide resolved

ranj063 reviewed Nov 6, 2018

View reviewed changes

sound/soc/sof/trace.c Outdated Show resolved Hide resolved

plbossart requested changes Nov 6, 2018

View reviewed changes

sound/soc/sof/intel/hda-stream.c Outdated Show resolved Hide resolved

sound/soc/sof/intel/hda-stream.c Outdated Show resolved Hide resolved

sound/soc/sof/intel/hda-trace.c Show resolved Hide resolved

keyonjie added 2 commits November 7, 2018 13:40

keyonjie force-pushed the trace_fix branch from 17e7587 to 250896b Compare November 7, 2018 10:50

keyonjie force-pushed the trace_fix branch from 250896b to 593520e Compare November 7, 2018 10:54

lgirdwood approved these changes Nov 7, 2018

View reviewed changes

keyonjie mentioned this pull request Nov 8, 2018

verbose tracing doesn't refresh thesofproject/sof#526

Closed

plbossart requested changes Nov 8, 2018

View reviewed changes

ranj063 reviewed Nov 9, 2018

View reviewed changes

sound/soc/sof/intel/hda-stream.c Show resolved Hide resolved

ranj063 reviewed Nov 9, 2018

View reviewed changes

sound/soc/sof/intel/hda-stream.c Show resolved Hide resolved

plbossart reviewed Nov 9, 2018

View reviewed changes

keyonjie closed this Nov 14, 2018

keyonjie mentioned this pull request Mar 6, 2019

[RFC] remove using 'offset' field in host ring buffer #693

Merged

kv2019i mentioned this pull request Apr 2, 2019

Driver support for firmware recovery #452

Closed

		@@ -236,6 +256,8 @@ int snd_sof_init_trace(struct snd_sof_dev *sdev)

		init_waitqueue_head(&sdev->trace_sleep);

		init_waitqueue_head(&sdev->trace_sleep);

ASoC: SOF: trace: fix trace doesn't update issue #248

ASoC: SOF: trace: fix trace doesn't update issue #248

Uh oh!

Conversation

keyonjie commented Nov 6, 2018

Uh oh!

Uh oh!

Uh oh!

lgirdwood left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

plbossart left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

keyonjie commented Nov 7, 2018

Uh oh!

plbossart left a comment

Choose a reason for hiding this comment

Uh oh!

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!

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!

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!

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!

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!

ranj063 Nov 9, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ranj063 Nov 9, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

ranj063 Nov 9, 2018 •

edited

Loading

ranj063 Nov 9, 2018 •

edited

Loading