IPC fixes -- for snd_pcm_period_elapse() invoking by keyonjie · Pull Request #849 · thesofproject/linux

keyonjie · 2019-04-19T17:43:07Z

Our IPC implementation in SOF requires sending IPCs serially, that is,
we should not send a new IPC before we get ack(or time out) from FW.

OTOH, snd_pcm_period_elapsed() will do trigger stop(IPC Tx to Firmware)
at PCM draining done, that means, we should not invoke the function
before IRQ_HANDLED is returned.

Unfortunately, We invoke snd_pcm_period_elapsed() in interrupt thread
before IRQ_HANDLED is returned, this fact leads to possible ipc time out
at stopping PCMs, especially when the draining done happens right after
period boundary.

Here we introduce a task to call this snd_pcm_elapsed(), to make sure it
will not be actually run before the IPC IRQ is handled. The stress test
shows that it fixes this kind of ipc time out issue.

plbossart

see comments below, the clarity of the explanations isn't up to par and needs to be improved.

plbossart · 2019-04-19T18:05:03Z

s/elapsed/period_elapsed/ in this patch please.

ranj063 · 2019-04-19T21:53:15Z

@plbossart @keyonjie I understand the rationale for scheduling period_elapsed_work for later but I feel like we might be missing something fundamental in the way we deal with shared IRQ. But the change feels OK for now.

I'll work with @lyakh after he's back from vacation to dig deeper.

xiulipan

Fix looks good to change snd_pcm_period_elapsed from sync to async. That will help to make sure IPC thread is not blocking.

But indeed need to refine the comment and commit to give a more convince explanation about why need to use a task for snd_pcm_period_elapsed

And it fix #808

[ 73.081644] sof-audio-acpi 80860F28:01: pcm: trigger stream 0 dir 0 cmd 0
[ 73.081668] sof-audio-acpi 80860F28:01: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 73.082610] sof-audio-acpi 80860F28:01: ipc tx succeeded: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 73.082650] sof-audio-acpi 80860F28:01: pcm: free stream 0 dir 0
[ 73.082664] sof-audio-acpi 80860F28:01: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 73.082790] sof-audio-acpi 80860F28:01: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 73.082883] sof-audio-acpi 80860F28:01: pcm: close stream 0 dir 0
[ 73.330420] sof-audio-acpi 80860F28:01: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 73.330442] sof-audio-acpi 80860F28:01: ipc rx done: 0x90020000: GLB_TRACE_MSG

ranj063 · 2019-04-20T01:32:20Z

@plbossart @keyonjie the more I look into this code, the more confusing it is to me. When the stream interrupt handler arrives, it already defers processing by waking up the threaded interrupt handler( hda_dsp_stream_threaded_handler). The whole idea of a threaded interrupt handler is to be able to do the processing while the interrupts themselves are not disabled.

So when the hda_dsp_stream_threaded_handler calls snd_pcm_period_elapse() which in turn sends an IPC to the DSP and waits for a reply, the interrupts are not disabled. So this doesn't seem to explain why this would cause a timeout at all?

Please correct me if I am wrong.

ranj063 · 2019-04-20T02:04:43Z

I did a bit of reading on the topic and the threaded handler does disable interrupts until it is done processing. Sorry about the confusion.

RanderWang · 2019-04-22T05:27:21Z

Actually snd_pcm_period_elapsed is a complex function and one principle in Linux kernel development: never make interrupt function too complex.

keqiaozhang · 2019-04-22T05:59:51Z

I have verified #849 + #850 on GLK and WHL, simultaneous playback/capturing can pass 1K iterations without errors on both platforms.

plbossart · 2019-04-22T15:02:22Z

@keyonjie I don't see any updated code and I will be unavailable tomorrow morning, so this PR will be delayed mechanically until mid-week...

keyonjie · 2019-04-23T01:10:56Z

@plbossart updated now.

plbossart

cosmetic fixes needed

keyonjie · 2019-04-23T02:56:25Z

@plbossart thanks, one more update done today.

RanderWang

LGTM

plbossart

please fix what can be seen as a typo. it's period_elapsed.

plbossart · 2019-04-23T10:43:33Z

period_elapsed

please fix what can be seen as a typo. it's period_elapsed.

OK, done.

plbossart

Thanks @keyonjie for making this PR really shiny.
I will wait for the build results and need a 2nd approver before merging.

…rrupt context The IPC implementation in SOF requires sending IPCs serially: we should not send a new IPC command to the firmware before we get an ACK (or time out) from firmware, and the IRQ processing is complete. snd_pcm_period_elapsed() can be called in interrupt context before IRQ_HANDLED is returned. When the PCM is done draining, a STOP IPC will then be sent, which breaks the expectation that IPCs are handled serially and leads to IPC timeouts. This patch adds a workqueue to defer the call to snd_pcm_elapsed() after the IRQ is handled. Signed-off-by: Keyon Jie <yang.jie@linux.intel.com>

Switch to a wrapper function which schedules the actual call of snd_pcm_period_elapsed after the current IPC is completed. Signed-off-by: Keyon Jie <yang.jie@linux.intel.com>

xiulipan · 2019-04-24T04:19:59Z

LGTM
@keqiaozhang @DarrenxWang @stevyan
This will influence BYT mostly. Please try to stress test on BYT if it is possible.

keyonjie requested review from RanderWang, juimonen, plbossart, ranj063 and xiulipan April 19, 2019 17:52

keyonjie mentioned this pull request Apr 19, 2019

SKL+ ipc timeout fix series #845

Closed

plbossart requested changes Apr 19, 2019

View reviewed changes

xiulipan suggested changes Apr 19, 2019

View reviewed changes

ranj063 previously approved these changes Apr 20, 2019

View reviewed changes

RanderWang reviewed Apr 22, 2019

View reviewed changes

Comment thread sound/soc/sof/pcm.c Outdated

keqiaozhang mentioned this pull request Apr 22, 2019

IPC fixes -- interrupt handler #850

Merged

keyonjie dismissed ranj063’s stale review via 9952af7 April 23, 2019 01:10

keyonjie force-pushed the ipc_elapse_fix branch from 79dfeda to 9952af7 Compare April 23, 2019 01:10

plbossart requested changes Apr 23, 2019

View reviewed changes

Comment thread sound/soc/sof/pcm.c Outdated

Comment thread sound/soc/sof/pcm.c Outdated

Comment thread sound/soc/sof/sof-priv.h Outdated

Comment thread sound/soc/sof/pcm.c Outdated

Comment thread sound/soc/sof/intel/hda-stream.c Outdated

Comment thread sound/soc/sof/ipc.c Outdated

keyonjie force-pushed the ipc_elapse_fix branch from 9952af7 to e13f182 Compare April 23, 2019 02:56

RanderWang previously approved these changes Apr 23, 2019

View reviewed changes

plbossart requested changes Apr 23, 2019

View reviewed changes

keyonjie dismissed RanderWang’s stale review via 980dd95 April 24, 2019 00:49

keyonjie force-pushed the ipc_elapse_fix branch from e13f182 to 980dd95 Compare April 24, 2019 00:49

plbossart previously approved these changes Apr 24, 2019

View reviewed changes

keyonjie dismissed plbossart’s stale review via 72733a1 April 24, 2019 01:07

keyonjie force-pushed the ipc_elapse_fix branch from 980dd95 to 72733a1 Compare April 24, 2019 01:07

keyonjie added 3 commits April 24, 2019 09:11

ASoC: SOF: Intel: use snd_sof_pcm_period_elapsed

9f6f3fa

Switch to a wrapper function which schedules the actual call of snd_pcm_period_elapsed after the current IPC is completed. Signed-off-by: Keyon Jie <yang.jie@linux.intel.com>

ASoC: SOF: ipc: use snd_sof_pcm_period_elapsed

72733a1

Switch to a wrapper function which schedules the actual call of snd_pcm_period_elapsed after the current IPC is completed. Signed-off-by: Keyon Jie <yang.jie@linux.intel.com>

ranj063 approved these changes Apr 24, 2019

View reviewed changes

xiulipan approved these changes Apr 24, 2019

View reviewed changes

plbossart merged commit f7e9d4a into thesofproject:topic/sof-dev Apr 25, 2019

stevyan mentioned this pull request Apr 26, 2019

[Regression][BYT][rt5651]: 'ipc timed out for 0x60050000' after aplay music at the 2nd time #873

Closed

xiulipan mentioned this pull request May 7, 2019

[BYT][ipc position update feature]IPC timed out when stop playback #808

Closed

plbossart mentioned this pull request Sep 6, 2019

ASoC: SOF: cancel period_elapsed_work during pcm close #1185

Closed

Conversation

keyonjie commented Apr 19, 2019

Uh oh!

plbossart left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

plbossart Apr 19, 2019

Choose a reason for hiding this comment

Uh oh!

Uh oh!

ranj063 commented Apr 19, 2019

Uh oh!

xiulipan left a comment

Choose a reason for hiding this comment

Uh oh!

ranj063 commented Apr 20, 2019

Uh oh!

ranj063 commented Apr 20, 2019

Uh oh!

Uh oh!

RanderWang commented Apr 22, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

keqiaozhang commented Apr 22, 2019

Uh oh!

plbossart commented Apr 22, 2019

Uh oh!

keyonjie commented Apr 23, 2019

Uh oh!

plbossart left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

keyonjie commented Apr 23, 2019

Uh oh!

RanderWang left a comment

Choose a reason for hiding this comment

Uh oh!

plbossart left a comment

Choose a reason for hiding this comment

Uh oh!

plbossart Apr 23, 2019

Choose a reason for hiding this comment

Uh oh!

keyonjie Apr 24, 2019

Choose a reason for hiding this comment

Uh oh!

plbossart left a comment

Choose a reason for hiding this comment

Uh oh!

xiulipan commented Apr 24, 2019

Uh oh!

Reviewers

Uh oh!

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants

RanderWang commented Apr 22, 2019 •

edited

Loading