Repository navigation
Up2: load/unload module always fail because of IPC issues #534
Description
When executing sof_bootloop.sh, sooner or later we hit an issue with the trace. This time it was at the 39th iteration. Increasing the sleep time between insert/remove seems to make things better, maybe we have a synchronization issue. Once the IPC error occurs, it's no longer possible to load/unload modules.
[ 451.561107] sof-audio sof-audio: stream_tag: 1
[ 451.561144] sof-audio sof-audio: ipc tx: 0x90010000: GLB_TRACE_MSG
[ 451.561362] sof-audio sof-audio: error: ipc error for 0x90010000 size 0xc
[ 451.561802] sof-audio sof-audio: error: can't set params for DMA for trace -22
[ 451.562288] sof-audio sof-audio: warning: failed to initialize trace -22
[ 451.562430] sof-audio sof-audio: created machine bxt-pcm512x
Activity
plbossart commentedon Jan 11, 2019
Additional tests show the error may happen on resume as well, but still with the DMA trace.
boot_fail.log
kernel SHA1: 2ac82ee
sof SHA1: 872cefe
ranj063 commentedon Jan 11, 2019
@plbossart I cant even get to the second iteration in my case. But I have a hunch about the call to suspend_streams() in our PM suspend sequence.
@keyonjie and I talked about possibly checking if it is really required or not. It seems to work on chrome but I'll need to verify on up2.
plbossart commentedon Jan 12, 2019
@ranj063 indeed sof_bootloop.sh always failed, I had to add a sleep 5 between iterations to make it work for longer. Definitively a timing/race condition.
Also keep in mind Chrome stops the streams before suspend and restarts them, so there are differences to check.
zhuyingjiang commentedon Jan 16, 2019
@plbossart I still face a oops, during the loop, the first is ok, and then the scripts dead, the dmesg got the attached log.
bootloop_oops.log
I think this is another issue with this loop.
ranj063 commentedon Jan 16, 2019
@zhuyingjiang finally someone else is seeing the same issue as mine.
zhuyingjiang commentedon Jan 16, 2019
plbossart commentedon Jan 16, 2019
I don't have a kernel oops, and this one seems like the result of a bad error handling rather than a host-dsp issue. Maybe file it as a different issue? Also pretty please include all the dmesg (or all the sof parts) so that we can know what the setup is prior to the crash. I don't get if you are using the nocodec mode (known issue) or the PCM512x board?
ranj063 commentedon Jan 17, 2019
@zhuyingjiang @plbossart my log in the other bug #490 is very similar to what Yingjiang is seeing.
zhuyingjiang commentedon Jan 17, 2019
@ranj063 @plbossart Yes, the issue I found is the same as #490. I will focus on the issue Pierre found in this thread.
zhuyingjiang commentedon Jan 17, 2019
@plbossart My problem is that I use the same version you provide (kernel SHA1: 2ac82ee, sof SHA1: 872cefe) can't reproduce the issue you found, I am using PCM512x, and my issue found is the same as Rajani found in #490.
Am I missed something? which one do you use, PCM512x or nocodec?
ranj063 commentedon Jan 17, 2019
@zhuyingjiang @plbossart I fixed my problem by disabling pulseaudio. It was triggering a stream to play the boot up sound and it interfered with the timing of sof_remove.
So with pulseaudio disabled, I am able to run the loop of 100 iterations of load/unload.
zhuyingjiang commentedon Jan 17, 2019
@ranj063 @plbossart Yes, with pulseaudio disabled, I still got 100 loops. Can we close this issue and #490 ?
zhuyingjiang commentedon Jan 22, 2019
The analysis of this issue is:
The pulseaudio play a 5 seconds wav every time the sof module is inserted, but the sof_remove next run only delay 1 second; the PCM is locked during playing, when the sof_remove.sh try to disconnect device with snd_pcm_dev_disconnect it got stuck.
So there are 2 ways:
1 disable the pulseaudio when do the insert/remove loop.
2 sleep longer than 5 seconds after sof_insert
The pulse wav captured when do 10 seconds delay between remove and insert, although we can't heard it.
wav-captured-during-loop.zip
The pulse wav play can be seen in the end of the log(from 98 to 103, 10 seconds delay added in between):
[ 98.246567] sof-audio sof-audio: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: GET_VALUE
[ 98.246601] sof-audio sof-audio: ipc tx: 0x50020000: GLB_COMP_MSG: GET_VALUE
[ 98.246761] sof-audio sof-audio: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: GET_VALUE
[ 98.256752] sof-audio sof-audio: pcm: trigger stream 0 dir 0 cmd 1
[ 98.256787] sof-audio sof-audio: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 98.256998] sof-audio sof-audio: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 98.657926] sof-audio sof-audio: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 98.657948] sof-audio sof-audio: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 99.157886] sof-audio sof-audio: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 99.157909] sof-audio sof-audio: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 103.259662] sof-audio sof-audio: pcm: trigger stream 0 dir 0 cmd 0
[ 103.259918] sof-audio sof-audio: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 103.260254] sof-audio sof-audio: ipc tx succeeded: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 103.260344] sof-audio sof-audio: pcm: free stream 0 dir 0
[ 103.260367] sof-audio sof-audio: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 103.260517] sof-audio sof-audio: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 103.275925] sof-audio sof-audio: pcm: close stream 0 dir 0
by compare the 1 second delay and 10 seconds delay log, we can find that in 10 seconds delay log the PCM stream is stoped after 5 seconds:
boot_0-add-10s-delay.log
boot_0-add-1s-delay.log
this one is the log which disabled pulse, no PCM playing after sof_insert:
boot-disable-pulse_0.log
The call stack during sof_remove:
devm_card_release
=>snd_soc_unregister_card
=>snd_soc_unbind_card
=>snd_soc_dapm_shutdown
=>soc_cleanup_card_resources
1=>snd_soc_tplg_component_remove
=>remove_dai
=>remove_link
=>remove_widget
==>sof_widget_unload
===>hda_dsp_core_reset_power_down
====>hda_dsp_core_power_down
2=>snd_card_free
==>init_completion
==>snd_card_free_when_closed
===>snd_card_disconnect
====>snd_pcm_dev_disconnect (stuck here for the PCM is playing and locked)
===>put_device
==>wait_for_completion
The error may different depend on the PCM playing state.
We can do forbid module remove when PCM is playing, but this seems should be handled in ASOC?
@plbossart @lgirdwood
mengdonglin commentedon Jan 22, 2019
@plbossart @zhuyingjiang @ranj063 @keyonjie @bardliao
The script sof_remove.sh shows we start from removing the PCI device driver, not the machine driver that registers the sound card. Maybe we should remove the machine driver at first?
Probably ALSA can prevent removing the sound card that is being used, and report 'device busy' if Pulseaudio or aplay is using the device.
https://github.com/thesofproject/sof/blob/master/tools/kmod_scripts/sof_remove.sh:
remove_module sof_pci_dev
remove_module sof_acpi_dev
...
remove_module snd_soc_sst_bytcr_rt5640
remove_module snd_soc_sst_bytcr_rt5651
remove_module snd_soc_sst_cht_bsw_rt5645
remove_module snd_soc_sst_cht_bsw_rt5670
remove_module snd_soc_sst_byt_cht_da7213
remove_module snd_soc_sst_bxt_pcm512x
remove_module snd_soc_sst_bxt_tdf8532
remove_module snd_soc_cnl_rt274
remove_module snd_sof_nocodec
remove_module snd_sof
keyonjie commentedon Jan 22, 2019
@mengdonglin I just went though this, the existed scripts looks fine.
The crucial one in remove is "remove_module sof_pci_dev"(or remove_module sof_acpi_dev"), once this is removed, all platform devices we created in SOF drivers will be deleted, and then we can remove other remained drivers(machine driver, platform driver, intel platform drivers, xtensa drivers) in any sequence.
zhuyingjiang commentedon Jan 22, 2019
another case analysed:
if there is no PCM playing and do sof_remove.sh. for the sof_suspend has been called, sof_remove will call sof_resume first before remove.
but when PCM is playing, sof_suspend is not called, sof_remove will directly call devm_card_release, so the state is not correct, I will check the detail difference.
plbossart commentedon Jan 23, 2019
This thread has completely forked. My initial issue was that the Trace DMA IPC fails and that resulted in load/module failing. The problem with userspace trying to play while we remove is a different one. Please address each issue separately.
plbossart commentedon Jan 23, 2019
I retried with an updated code
firmware: eca416a
kernel: e4fb585
and still face a number of IPC issues - however not just with the trace DMA (likely because of a fix Keyon added today). Still this is not robust at all, the test fails within 80 loops. see below different results (not consecutive)
You need the update for kmod_scripts shared at thesofproject/sof#880
[-]Up2: load/unload module always fail because of trace DMA[/-][+]Up2: load/unload module always fail because of IPC issues[/+]wenqingfu commentedon Jan 27, 2019
this error is same as @ranj063 reported in thesofproject/sof#766. Can you try if non-SMP help?
plbossart commentedon Feb 8, 2019
closing, we've run hundreds of cycles of module load/unload without issues
regulator: push allocation in regulator_ena_gpio_request() out of lock