[alsa-devel] Question about sound device release timing
Hi Takashi-san, Mark
I noticed snd_soc_dapm_stream_event() is called strange timing if I unbind sound device during playing
> aplay xxx.wav & > echo xxxx > /sys/bus/platform/drivers/xxx/unbind ... > Unable to handle kernel paging request at virtual address dead000000000220 > Mem abort info: (snip) > PC is at soc_dapm_dai_stream_event.isra.14+0x20/0xd0 > LR is at snd_soc_dapm_stream_event+0x74/0xa8 (snip) > [<ffff000008715610>] soc_dapm_dai_stream_event.isra.14+0x20/0xd0 > [<ffff00000871989c>] snd_soc_dapm_stream_event+0x74/0xa8 > [<ffff00000871b23c>] close_delayed_work+0x3c/0x50 > [<ffff0000080bbd6c>] process_one_work+0x1ac/0x318 > [<ffff0000080bbf20>] worker_thread+0x48/0x420 > [<ffff0000080c201c>] kthread+0xfc/0x128 > [<ffff0000080842f0>] ret_from_fork+0x10/0x18 > Code: b40005c9 a9bf7bfd 91048120 910003fd (f9409121) > ---[ end trace 6739a0ea1013e0b2 ]---
This snd_soc_dapm_stream_event() was called from close_delayed_work() and it was set on soc_pcm_close()
static int soc_pcm_close(struct snd_pcm_substream *substream) { ... if (substream->stream == SNDRV_PCM_STREAM_PLAYBACK) { if (snd_soc_runtime_ignore_pmdown_time(rtd)) { ... } else { /* start delayed pop wq here for playback streams */ rtd->pop_wait = 1; => queue_delayed_work(system_power_efficient_wq, &rtd->delayed_work, msecs_to_jiffies(rtd->pmdown_time)); } ... }
But, this soc_pcm_close() is called *after* flush_delayed_work() of soc_cleanup_card_resources(). It seems this close function seems called from snd_card_free() and this rtd will be freed on soc_remove_pcm_runtimes().
static int soc_cleanup_card_resources(struct snd_soc_card *card) { ...
/* make sure any delayed work runs */ list_for_each_entry(rtd, &card->rtd_list, list) { => flush_delayed_work(&rtd->delayed_work); }
/* free the ALSA card at first; this syncs with pending operations */ => snd_card_free(card->snd_card); ... => soc_remove_pcm_runtimes(card); ... }
Because of this, delayed called close_delayed_work() will call soc_dapm_dai_stream_event() and it access to already freed rtd, and kernel will die. I don't know why, but it seems this close is wokring on other thread (?), but I'm not sure.
Q1. does this close function run on other thread ? Q2. I can avoid this delayed close by setting rtd->pmdown_time = 0; before snd_card_free(). but is this correct approach ?
I can avoid this delayed calling close_delayed_work() by local patch, but then, re-bind doesn't work correctly.
/* * custom kernel for avoiding close_delayed_work() */ > aplay xxx.wav & > echo xxxx > /sys/bus/platform/drivers/rcar_sound/unbind /* unbind codec and card drivers here */ > /* * try re-bind */ /* re-bind codec and card drivers here */ > echo xxxx > /sys/bus/platform/drivers/rcar_sound/bind rcar_sound ec500000.sound: probed asoc-simple-card sound: ak4613-hifi <-> ec500000.sound mapping ok > > aplay xxx.wav Playing WAVE '/home/Calm_16bit_48k.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo ALSA lib pcm_params.c:2162:(snd1_pcm_hw_refine_slave) Slave PCM not usable aplay: set_params:1204: Broken configuration for this PCM: no configurations available
Do you know why or have hint to solve these issue ?
Best regards --- Kuninori Morimoto
On Fri, 25 Aug 2017 07:31:04 +0200, Kuninori Morimoto wrote:
Hi Takashi-san, Mark
I noticed snd_soc_dapm_stream_event() is called strange timing if I unbind sound device during playing
aplay xxx.wav & echo xxxx > /sys/bus/platform/drivers/xxx/unbind
...
Unable to handle kernel paging request at virtual address dead000000000220 Mem abort info:
(snip)
PC is at soc_dapm_dai_stream_event.isra.14+0x20/0xd0 LR is at snd_soc_dapm_stream_event+0x74/0xa8
(snip)
[<ffff000008715610>] soc_dapm_dai_stream_event.isra.14+0x20/0xd0 [<ffff00000871989c>] snd_soc_dapm_stream_event+0x74/0xa8 [<ffff00000871b23c>] close_delayed_work+0x3c/0x50 [<ffff0000080bbd6c>] process_one_work+0x1ac/0x318 [<ffff0000080bbf20>] worker_thread+0x48/0x420 [<ffff0000080c201c>] kthread+0xfc/0x128 [<ffff0000080842f0>] ret_from_fork+0x10/0x18 Code: b40005c9 a9bf7bfd 91048120 910003fd (f9409121) ---[ end trace 6739a0ea1013e0b2 ]---
This snd_soc_dapm_stream_event() was called from close_delayed_work() and it was set on soc_pcm_close()
static int soc_pcm_close(struct snd_pcm_substream *substream) { ... if (substream->stream == SNDRV_PCM_STREAM_PLAYBACK) { if (snd_soc_runtime_ignore_pmdown_time(rtd)) { ... } else { /* start delayed pop wq here for playback streams */ rtd->pop_wait = 1; => queue_delayed_work(system_power_efficient_wq, &rtd->delayed_work, msecs_to_jiffies(rtd->pmdown_time)); } ... }
But, this soc_pcm_close() is called *after* flush_delayed_work() of soc_cleanup_card_resources(). It seems this close function seems called from snd_card_free() and this rtd will be freed on soc_remove_pcm_runtimes().
static int soc_cleanup_card_resources(struct snd_soc_card *card) { ...
/* make sure any delayed work runs */ list_for_each_entry(rtd, &card->rtd_list, list) { => flush_delayed_work(&rtd->delayed_work); }
/* free the ALSA card at first; this syncs with pending operations */ => snd_card_free(card->snd_card); ... => soc_remove_pcm_runtimes(card); ... }
Because of this, delayed called close_delayed_work() will call soc_dapm_dai_stream_event() and it access to already freed rtd, and kernel will die. I don't know why, but it seems this close is wokring on other thread (?), but I'm not sure.
It's just a race, so sometimes it may succeed, I guess.
Q1. does this close function run on other thread ?
Depends.
Q2. I can avoid this delayed close by setting rtd->pmdown_time = 0; before snd_card_free(). but is this correct approach ?
Basically yes -- supposing the driver / the hardware handles already correctly the DAPM shutdown path beforehand.
Or, on the real hotplugged device, even accessing the whole should be suppressed after the device disconnection. So, this might even not be sufficient.
But in anyway, you'd better to sync before the actual resource free. A patch below would add the sync point at PCM free so that the Oops above can be avoided, I suppose.
--- a/sound/soc/soc-pcm.c +++ b/sound/soc/soc-pcm.c @@ -2632,6 +2632,16 @@ static int dpcm_fe_dai_close(struct snd_pcm_substream *fe_substream) return ret; }
+static void soc_pcm_private_free(struct snd_pcm *pcm) +{ + struct snd_soc_pcm_runtime *rtd = pcm->private_data; + struct snd_soc_platform *platform = rtd->platform; + + flush_delayed_work(&rtd->delayed_work); + if (platform->driver->pcm_free) + if (platform->driver->pcm_free(pcm); +} + /* create a new pcm */ int soc_new_pcm(struct snd_soc_pcm_runtime *rtd, int num) { @@ -2757,7 +2767,7 @@ int soc_new_pcm(struct snd_soc_pcm_runtime *rtd, int num) } }
- pcm->private_free = platform->driver->pcm_free; + pcm->private_free = soc_pcm_private_free; out: dev_info(rtd->card->dev, "%s <-> %s mapping ok\n", (rtd->num_codecs > 1) ? "multicodec" : rtd->codec_dai->name,
I can avoid this delayed calling close_delayed_work() by local patch, but then, re-bind doesn't work correctly.
/* * custom kernel for avoiding close_delayed_work() */
aplay xxx.wav & echo xxxx > /sys/bus/platform/drivers/rcar_sound/unbind
/* unbind codec and card drivers here */
/* * try re-bind */ /* re-bind codec and card drivers here */
echo xxxx > /sys/bus/platform/drivers/rcar_sound/bind
rcar_sound ec500000.sound: probed asoc-simple-card sound: ak4613-hifi <-> ec500000.sound mapping ok
aplay xxx.wav
Playing WAVE '/home/Calm_16bit_48k.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo ALSA lib pcm_params.c:2162:(snd1_pcm_hw_refine_slave) Slave PCM not usable aplay: set_params:1204: Broken configuration for this PCM: no configurations available
Do you know why or have hint to solve these issue ?
It's hard to say only from that... But judging from your description, it must be relevant with the stale DAPM setup that was left untouched at the previous driver unbind? That is, the driver doesn't fully initialize the hardware at probe.
thanks,
Takashi
Hi Mark, Takashi-san
--- a/sound/soc/soc-pcm.c +++ b/sound/soc/soc-pcm.c @@ -2632,6 +2632,16 @@ static int dpcm_fe_dai_close(struct snd_pcm_substream *fe_substream) return ret; }
+static void soc_pcm_private_free(struct snd_pcm *pcm) +{
- struct snd_soc_pcm_runtime *rtd = pcm->private_data;
- struct snd_soc_platform *platform = rtd->platform;
- flush_delayed_work(&rtd->delayed_work);
- if (platform->driver->pcm_free)
if (platform->driver->pcm_free(pcm);+}
/* create a new pcm */ int soc_new_pcm(struct snd_soc_pcm_runtime *rtd, int num) { @@ -2757,7 +2767,7 @@ int soc_new_pcm(struct snd_soc_pcm_runtime *rtd, int num) } }
- pcm->private_free = platform->driver->pcm_free;
- pcm->private_free = soc_pcm_private_free;
Thanks ! I confirmed that this solved my issue from kernel Oops. - Renesas Lager board - Renesas R-Car Salvator-X board
Reported-by: Hiep Cao Minh cm-hiep@jinso.co.jp Reported-by: Kuninori Morimoto kuninori.morimoto.gx@renesas.com Tested-by: Kuninori Morimoto kuninori.morimoto.gx@renesas.com
Mark
If above patch was added, my current posted patch # ASoC: add Component level pcm_new/pcm_free v2 # Date: Tue, 08 Aug 2017 15:12:06 +0900 will have conflict. Then I can re-post it. Please let me know if your review was finished.
/* * custom kernel for avoiding close_delayed_work() */
aplay xxx.wav & echo xxxx > /sys/bus/platform/drivers/rcar_sound/unbind
/* unbind codec and card drivers here */
/* * try re-bind */ /* re-bind codec and card drivers here */
echo xxxx > /sys/bus/platform/drivers/rcar_sound/bind
rcar_sound ec500000.sound: probed asoc-simple-card sound: ak4613-hifi <-> ec500000.sound mapping ok
aplay xxx.wav
Playing WAVE '/home/Calm_16bit_48k.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo ALSA lib pcm_params.c:2162:(snd1_pcm_hw_refine_slave) Slave PCM not usable aplay: set_params:1204: Broken configuration for this PCM: no configurations available
Do you know why or have hint to solve these issue ?
It's hard to say only from that... But judging from your description, it must be relevant with the stale DAPM setup that was left untouched at the previous driver unbind? That is, the driver doesn't fully initialize the hardware at probe.
Thanks. I noticed that my one board could re-bind without issue, but one board had issue. I want to debug it. Do you know which function returns error to user side ? # set_params is only used on soc-compress, but my driver doesn't use it.
Best regards --- Kuninori Morimoto
On Fri, 25 Aug 2017 10:44:00 +0200, Kuninori Morimoto wrote:
Hi Mark, Takashi-san
--- a/sound/soc/soc-pcm.c +++ b/sound/soc/soc-pcm.c @@ -2632,6 +2632,16 @@ static int dpcm_fe_dai_close(struct snd_pcm_substream *fe_substream) return ret; }
+static void soc_pcm_private_free(struct snd_pcm *pcm) +{
- struct snd_soc_pcm_runtime *rtd = pcm->private_data;
- struct snd_soc_platform *platform = rtd->platform;
- flush_delayed_work(&rtd->delayed_work);
- if (platform->driver->pcm_free)
if (platform->driver->pcm_free(pcm);+}
/* create a new pcm */ int soc_new_pcm(struct snd_soc_pcm_runtime *rtd, int num) { @@ -2757,7 +2767,7 @@ int soc_new_pcm(struct snd_soc_pcm_runtime *rtd, int num) } }
- pcm->private_free = platform->driver->pcm_free;
- pcm->private_free = soc_pcm_private_free;
Thanks ! I confirmed that this solved my issue from kernel Oops.
- Renesas Lager board
- Renesas R-Car Salvator-X board
Reported-by: Hiep Cao Minh cm-hiep@jinso.co.jp Reported-by: Kuninori Morimoto kuninori.morimoto.gx@renesas.com Tested-by: Kuninori Morimoto kuninori.morimoto.gx@renesas.com
OK, I'll cook up a proper patch and submit soon later.
Mark
If above patch was added, my current posted patch # ASoC: add Component level pcm_new/pcm_free v2 # Date: Tue, 08 Aug 2017 15:12:06 +0900 will have conflict. Then I can re-post it. Please let me know if your review was finished.
/* * custom kernel for avoiding close_delayed_work() */
aplay xxx.wav & echo xxxx > /sys/bus/platform/drivers/rcar_sound/unbind
/* unbind codec and card drivers here */
/* * try re-bind */ /* re-bind codec and card drivers here */
echo xxxx > /sys/bus/platform/drivers/rcar_sound/bind
rcar_sound ec500000.sound: probed asoc-simple-card sound: ak4613-hifi <-> ec500000.sound mapping ok
aplay xxx.wav
Playing WAVE '/home/Calm_16bit_48k.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo ALSA lib pcm_params.c:2162:(snd1_pcm_hw_refine_slave) Slave PCM not usable aplay: set_params:1204: Broken configuration for this PCM: no configurations available
Do you know why or have hint to solve these issue ?
It's hard to say only from that... But judging from your description, it must be relevant with the stale DAPM setup that was left untouched at the previous driver unbind? That is, the driver doesn't fully initialize the hardware at probe.
Thanks. I noticed that my one board could re-bind without issue, but one board had issue. I want to debug it. Do you know which function returns error to user side ? # set_params is only used on soc-compress, but my driver doesn't use it.
You can try tracing that was recently added by Sakamoto-san. The error comes from the unavailable hw_params, that is, some hw_params setup narrowed too much.
Or, if it's about DPCM, it can be due to some stale setup in BE. What if you unload/reload the modules, not only rebind?
Takashi
Hi Takashi-san
Thanks ! I confirmed that this solved my issue from kernel Oops.
- Renesas Lager board
- Renesas R-Car Salvator-X board
Reported-by: Hiep Cao Minh cm-hiep@jinso.co.jp Reported-by: Kuninori Morimoto kuninori.morimoto.gx@renesas.com Tested-by: Kuninori Morimoto kuninori.morimoto.gx@renesas.com
OK, I'll cook up a proper patch and submit soon later.
Thanks
It's hard to say only from that... But judging from your description, it must be relevant with the stale DAPM setup that was left untouched at the previous driver unbind? That is, the driver doesn't fully initialize the hardware at probe.
Thanks. I noticed that my one board could re-bind without issue, but one board had issue. I want to debug it. Do you know which function returns error to user side ? # set_params is only used on soc-compress, but my driver doesn't use it.
You can try tracing that was recently added by Sakamoto-san. The error comes from the unavailable hw_params, that is, some hw_params setup narrowed too much.
Or, if it's about DPCM, it can be due to some stale setup in BE. What if you unload/reload the modules, not only rebind?
Thanks. I will check it
Best regards --- Kuninori Morimoto
participants (2)
-
Kuninori Morimoto -
Takashi Iwai