Repository navigation
Position readback after D3. #1183
Description
Warning in dmesg from CI showing we are attempting to read stream position after D3. This is causing multiple failures in CI for valid FW changes.
[ 467.213034 < 4.088943>] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 5 dir 0 cmd 0
[ 467.213280 < 0.000246>] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20140000 successful
[ 467.213290 < 0.000010>] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 467.213479 < 0.000189>] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 467.213486 < 0.000007>] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 467.213613 < 0.000127>] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 467.213626 < 0.000013>] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=0
[ 467.213638 < 0.000012>] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[ 467.213757 < 0.000119>] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
[ 467.213866 < 0.000109>] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[ 467.214021 < 0.000155>] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
[ 467.214241 < 0.000220>] sof-audio-pci 0000:00:1f.3: pcm: close stream 5 dir 0
[ 468.123883 < 0.909642>] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 468.123917 < 0.000034>] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 469.617153 < 1.493236>] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20140000 successful
[ 469.652023 < 0.034870>] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[ 469.652177 < 0.000154>] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x40010000: GLB_PM_MSG: CTX_SAVE
[ 469.652218 < 0.000041>] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1010f0f successful
[ 469.652221 < 0.000003>] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1000f0f successful
[ 469.652222 < 0.000001>] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask f
[ 469.652254 < 0.000032>] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000010 at 00000044
[ 472.121547 < 2.469293>] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000000 at 00000044
[ 472.121557 < 0.000010>] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000040 at 00000048
[ 472.121564 < 0.000007>] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000000 at 00000048
[ 472.124413 < 0.002849>] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000000 at 00000048
[ 472.124424 < 0.000011>] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000040 at 00000048
[ 472.124502 < 0.000078>] sof-audio-pci 0000:00:1f.3: loading firmware
[ 472.124507 < 0.000005>] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000002 at 00000048
[ 472.124512 < 0.000005>] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000000 at 00000048
[ 472.124517 < 0.000005>] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000000 at 00000044
[ 472.124522 < 0.000005>] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000004 at 00000044
[ 472.124523 < 0.000001>] sof-audio-pci 0000:00:1f.3: booting DSP firmware
[ 472.124579 < 0.000056>] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful
[ 472.124600 < 0.000021>] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful
[ 472.124603 < 0.000003>] sof-audio-pci 0000:00:1f.3: period_bytes:0x0
[ 472.124605 < 0.000002>] sof-audio-pci 0000:00:1f.3: periods:1
[ 472.124652 < 0.000047>] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f0f0f successful
[ 472.124661 < 0.000009>] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f0f0e successful
[ 472.124664 < 0.000003>] sof-audio-pci 0000:00:1f.3: unstall/run core: core_mask = 1
[ 472.124668 < 0.000004>] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 1 : core_mask 1
[ 472.125279 < 0.000611>] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x80000000 successful
[ 472.125291 < 0.000012>] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1010e0e successful
[ 472.125360 < 0.000069>] sof-audio-pci 0000:00:1f.3: error: no reply expected, received 0x0
[ 472.207944 < 0.082584>] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x5000001 successful
[ 472.210669 < 0.002725>] ------------[ cut here ]------------
[ 472.210716 < 0.000047>] WARNING: CPU: 4 PID: 989 at /home/test/jenkins/workspace/kernel_build_template/sound/core/pcm_lib.c:1785 snd_pcm_period_elapsed+0xa3/0xb0 [snd_pcm]
[ 472.210718 < 0.000002>] Modules linked in: snd_soc_skl_hda_dsp snd_soc_hdac_hdmi snd_hda_codec_realtek snd_hda_codec_generic snd_soc_dmic snd_sof_pci snd_sof_intel_hda_common snd_soc_hdac_hda snd_intel_nhlt snd_sof_intel_hda snd_sof_intel_byt snd_soc_acpi_intel_match snd_sof_intel_ipc snd_sof snd_sof_xtensa_dsp snd_soc_acpi snd_hda_ext_core snd_soc_core snd_usb_audio snd_hda_codec snd_usbmidi_lib snd_hda_core snd_hwdep snd_pcm snd_seq_midi snd_seq_midi_event snd_rawmidi snd_seq iwlmvm snd_seq_device snd_timer asix usbnet snd soundcore x86_pkg_temp_thermal intel_powerclamp iwlwifi intel_lpss_pci intel_lpss mfd_core efivarfs i915 i2c_algo_bit drm_kms_helper syscopyarea sysfillrect sdhci_pci xhci_pci sysimgblt fb_sys_fops cqhci xhci_hcd sdhci drm
[ 472.210756 < 0.000038>] CPU: 4 PID: 989 Comm: kworker/4:0 Tainted: G W 5.3.0-rc7-daily-hda-20190905 #45c901ba
[ 472.210758 < 0.000002>] Hardware name: Intel Corporation CometLake Client Platform/CometLake U DDR4 HR ERB, BIOS CMLSFWR1.R00.1155.D00.1904130508 04/13/2019
[ 472.210766 < 0.000008>] Workqueue: events sof_pcm_period_elapsed_work [snd_sof]
[ 472.210774 < 0.000008>] RIP: 0010:snd_pcm_period_elapsed+0xa3/0xb0 [snd_pcm]
[ 472.210778 < 0.000004>] Code: 78 ca f6 83 20 01 00 00 01 74 c1 48 8b bb 18 01 00 00 be 01 00 00 00 e8 bb 76 f6 ff eb ae 48 c7 c7 d8 1c 7d c0 e8 e6 cf ae da <0f> 0b 5b 5d 41 5c c3 66 0f 1f 44 00 00 83 fe 02 41 54 55 48 89 d5
[ 472.210780 < 0.000002>] RSP: 0018:ffff95ed439bbe80 EFLAGS: 00010282
[ 472.210783 < 0.000003>] RAX: 0000000000000024 RBX: ffff93e12e20e200 RCX: 0000000000000000
[ 472.210785 < 0.000002>] RDX: 0000000000000000 RSI: ffff93e14b9163d8 RDI: ffff93e14b9163d8
[ 472.210787 < 0.000002>] RBP: 0000000000000000 R08: 0000000000007ed0 R09: 0000000000000004
[ 472.210788 < 0.000001>] R10: ffff95ed4039fdc8 R11: 0000000000000001 R12: ffff93e14b92c100
[ 472.210790 < 0.000002>] R13: 0000000000000000 R14: ffff93e12388c3c0 R15: 0ffff93e14b92c10
[ 472.210792 < 0.000002>] FS: 0000000000000000(0000) GS:ffff93e14b900000(0000) knlGS:0000000000000000
[ 472.210794 < 0.000002>] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 472.210796 < 0.000002>] CR2: 00007f29bc81eb80 CR3: 0000000444146002 CR4: 00000000003606e0
[ 472.210798 < 0.000002>] Call Trace:
[ 472.210807 < 0.000009>] process_one_work+0x1e3/0x3d0
[ 472.210811 < 0.000004>] worker_thread+0x28/0x3c0
[ 472.210815 < 0.000004>] ? cancel_delayed_work+0x80/0x80
[ 472.210820 < 0.000005>] kthread+0x10e/0x130
[ 472.210824 < 0.000004>] ? kthread_park+0xa0/0xa0
[ 472.210829 < 0.000005>] ret_from_fork+0x1f/0x40
[ 472.210833 < 0.000004>] ---[ end trace 34b1eb7fbdb64498 ]---
Activity
ranj063 commentedon Sep 6, 2019
@lgirdwood I do not see this warning on my WHL laptop. I dont have a CML anymore but if someone else can try it on theirs it will be useful. @kv2019i do you have yours?
lgirdwood commentedon Sep 6, 2019
@ranj063 this is showing up on most FW PRs now and on more than one platform.
So this could be initiated from userspace, kernel or FW (via period elapsed IRQ). But this looks like we get a spurious IRQ on DSP boot that is being interpreted as a period elapsed IRQ.
kv2019i commentedon Sep 10, 2019
@ranj063 I'm seeing this also on CFL, but it is very random -- typically comes at boot.
kv2019i commentedon Sep 11, 2019
@ranj063 I was able to reproduce and rootcause. I'll take the bug in my name and will send a patch shortly.
kv2019i commentedon Sep 11, 2019
Reproduction steps (on APL):
-> bug gets hit every time
Jiangxinx commentedon Sep 16, 2019
@kv2019i I can't reproduce this issue on APL pcm512x and nocodec platform. Can you help me to check my test steps are correct?
test step
1.aplay -Dhw:0,0 -r48000 -c2 -fs16_LE test.wav & sudo rtcwake -m mem -s 2
Env
linux (topic/sof-dev): 6cf9ef0
sof (master): 2bd725d
Topology: file: sof-apl-nocodec.tplg & sof-apl-pcm512x.tplg
platform: APL
lgirdwood commentedon Sep 16, 2019
@mengdonglin, @ranj063 @kv2019i do you guys have an ETA for a fix to be merged ? This issue is failing most unrelated firmware PRs in CI now (and has been for over a week).
kv2019i commentedon Sep 16, 2019
@lgirdwood wrote:
Patch is missing second approval, but should be ready to go into today: #1193
Just pinged the reviewers again on this.
kv2019i commentedon Sep 16, 2019
@Jiangxinx wrote:
Hmm, the problem might be that you don't wait for the playback to complete before suspend. Please try this instead (it plays for 1sec, exits aplay and then goes to suspend). With this, I get the WARN_ON in dmesg every time with UP^2 and sof-apl-pcm512x.tplg
aplay -Dhw:0,0 -r48000 -c2 -d 1 -fs16_LE test.wav && sudo rtcwake -m mem -s 2