IPC error + kernel oops on WHL w/ HDA/DMIC and 1.3 signed firmware

[plbossart]

With this configuration, I get an IPC error followed by a kernel oops at the hw_params stage

kernel: c265f25
firmware: https://github.com/thesofproject/sof/releases/download/v1.3/sof-cnl-signed-intel.ri
topology: 2ca6a4afbb9475cd911207c67c25c6ea1452e70e ( sof-hda-generic-4ch.tplg)

I don't have the sof-cnl.ldc for that firmware so can't provide traces

dmesg attached:
dmesg.log

errors

[   43.634288] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[   43.634507] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60010000 size 20
[   43.634517] sof-audio-pci 0000:00:1f.3: error: hw params ipc failed for stream 2
[   43.634522] sof-audio-pci 0000:00:1f.3: ASoC: 0000:00:1f.3 hw params failed: -22
[   43.634528]  HDA Analog: ASoC: hw_params FE failed -22
[   43.634557] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[   43.634735] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
[   43.634752] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 1
[   43.634777] BUG: unable to handle page fault for address: fffffffffffffff8
[   43.634783] #PF: supervisor read access in kernel mode
[   43.634787] #PF: error_code(0x0000) - not-present page
[   43.634789] PGD 1aa20c067 P4D 1aa20c067 PUD 1aa20e067 PMD 0 
[   43.634797] Oops: 0000 [#1] SMP NOPTI
[   43.634803] CPU: 6 PID: 755 Comm: pulseaudio Not tainted 5.4.0-rc5-test+ #36
[   43.634806] Hardware name: Acer Swift SF314-55/MILLER_WL, BIOS V1.05 10/03/2018
[   43.634817] RIP: 0010:hda_link_config_ipc.isra.0+0xe/0xe0 [snd_sof_intel_hda_common]
[   43.634822] Code: 82 c0 e8 d5 50 ba ca b8 ed ff ff ff eb d6 b8 ed ff ff ff eb cf 0f 1f 80 00 00 00 00 41 57 41 56 41 55 41 54 55 53 48 83 ec 20 <4c> 8b 3f 89 54 24 04 49 8d 9f a0 03 00 00 65 48 8b 04 25 28 00 00
[   43.634825] RSP: 0018:ffffaebbc0cc7c58 EFLAGS: 00010282
[   43.634830] RAX: ffff898103679830 RBX: ffff89810366d200 RCX: 0000000000000001
[   43.634833] RDX: 00000000ffffffff RSI: ffff898120ac2c68 RDI: fffffffffffffff8
[   43.634836] RBP: ffff89810b9ccce8 R08: ffff89810b9ccce8 R09: 0000000000000007
[   43.634838] R10: 000000000000000a R11: 0000000000000004 R12: ffff898123dcc828
[   43.634841] R13: ffff89810ba7f028 R14: 0000000000000000 R15: ffff898120c62b60
[   43.634845] FS:  00007f6126a80c80(0000) GS:ffff898125b80000(0000) knlGS:0000000000000000
[   43.634849] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   43.634852] CR2: fffffffffffffff8 CR3: 000000024b8d6001 CR4: 00000000003606e0
[   43.634854] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[   43.634857] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[   43.634860] Call Trace:
[   43.634876]  ? __snd_hda_codec_cleanup_stream.part.0+0x28/0x70 [snd_hda_codec]
[   43.634884]  hda_link_hw_free+0x44/0xd0 [snd_sof_intel_hda_common]
[   43.634900]  soc_pcm_hw_free+0x158/0x180 [snd_soc_core]
[   43.634914]  dpcm_be_dai_hw_free+0xf0/0x150 [snd_soc_core]
[   43.634927]  dpcm_fe_dai_hw_free+0x86/0xf0 [snd_soc_core]
[   43.634938]  snd_pcm_hw_params+0x11f/0x560 [snd_pcm]
[   43.634949]  ? _cond_resched+0x10/0x20
[   43.634958]  ? __kmalloc_track_caller+0x54/0x200
[   43.634966]  snd_pcm_common_ioctl+0x1a0/0xc30 [snd_pcm]
[   43.634975]  snd_pcm_ioctl+0x1e/0x30 [snd_pcm]
[   43.634981]  do_vfs_ioctl+0x3f0/0x650
[   43.634988]  ksys_ioctl+0x59/0x90
[   43.634993]  __x64_sys_ioctl+0x11/0x20
[   43.634999]  do_syscall_64+0x43/0x110
[   43.635006]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[   43.635011] RIP: 0033:0x7f61290123c7
[   43.635017] Code: 00 00 90 48 8b 05 c9 3a 0d 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 99 3a 0d 00 f7 d8 64 89 01 48
[   43.635020] RSP: 002b:00007ffcd8a20e18 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[   43.635024] RAX: ffffffffffffffda RBX: 000055e2a4f128b0 RCX: 00007f61290123c7
[   43.635027] RDX: 00007ffcd8a20f20 RSI: 00000000c2604111 RDI: 0000000000000023
[   43.635030] RBP: 00007ffcd8a20f20 R08: 0000000000000000 R09: 0000000000000000
[   43.635033] R10: 0000000000000004 R11: 0000000000000246 R12: 000055e2a4f12930
[   43.635035] R13: 00007ffcd8a20e44 R14: 0000000000000000 R15: 00007ffcd8a20f20
[   43.635039] 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_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_intel_dspcfg snd_hda_codec snd_hwdep snd_hda_core snd_pcm snd_seq_midi snd_seq_midi_event snd_rawmidi snd_seq snd_seq_device snd_timer snd soundcore iwlmvm i915 i2c_algo_bit drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops iwlwifi x86_pkg_temp_thermal intel_powerclamp drm mei_me mei intel_pch_thermal efivarfs xhci_pci intel_lpss_pci intel_lpss xhci_hcd mfd_core
[   43.635080] CR2: fffffffffffffff8
[   43.635085] ---[ end trace 087815c1109fb0f2 ]---
[   43.635093] RIP: 0010:hda_link_config_ipc.isra.0+0xe/0xe0 [snd_sof_intel_hda_common]
[   43.635098] Code: 82 c0 e8 d5 50 ba ca b8 ed ff ff ff eb d6 b8 ed ff ff ff eb cf 0f 1f 80 00 00 00 00 41 57 41 56 41 55 41 54 55 53 48 83 ec 20 <4c> 8b 3f 89 54 24 04 49 8d 9f a0 03 00 00 65 48 8b 04 25 28 00 00
[   43.635100] RSP: 0018:ffffaebbc0cc7c58 EFLAGS: 00010282
[   43.635104] RAX: ffff898103679830 RBX: ffff89810366d200 RCX: 0000000000000001
[   43.635107] RDX: 00000000ffffffff RSI: ffff898120ac2c68 RDI: fffffffffffffff8
[   43.635109] RBP: ffff89810b9ccce8 R08: ffff89810b9ccce8 R09: 0000000000000007
[   43.635112] R10: 000000000000000a R11: 0000000000000004 R12: ffff898123dcc828
[   43.635115] R13: ffff89810ba7f028 R14: 0000000000000000 R15: ffff898120c62b60
[   43.635119] FS:  00007f6126a80c80(0000) GS:ffff898125b80000(0000) knlGS:0000000000000000
[   43.635122] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   43.635125] CR2: fffffffffffffff8 CR3: 000000024b8d6001 CR4: 00000000003606e0
[   43.635127] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[   43.635130] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400

@ranj063 @kv2019i @juimonen does anyone have an HDaudio+DMIC platform who could try and reproduce this?
Wondering if this is a regression with the new kernel, or a compatibility issue with the 1.3 firmware?

@tlauda @jajanusz does anyone have the sof-cnl.ldc file for this signed firmware?

[plbossart]

kernel regression, the sof-dev-rebase-20190821 tag works fine. More bisect...

[ranj063]

@plbossart sure I can try it

[ranj063]

@plbossart I think I know what the problem is : Could you please try reverting my patch?
fcb9d23

If we have this change in the kernel, it will run into the error seen above.

[plbossart]

@ranj063 it works with the latest kernel if I use an older topology... I took the latest topology since I didn't which one corresponds to the signed 1.3 firmware. and of course it breaks.

[ranj063]

@ranj063 it works with the latest kernel if I use an older topology... I took the latest topology since I didn't which one corresponds to the signed 1.3 firmware. and of course it breaks.

hmm that makes sense. So we should take the 1.3 topology with the 1.3 firmware.
But Im curious to see what difference in topology breaks with the new kernel

[plbossart]

here's what bisect tells me:

77b6db88948f435114991f9b6e782dc56c983010 is the first bad commit
commit 77b6db88948f435114991f9b6e782dc56c983010
Author: Jaska Uimonen <jaska.uimonen@intel.com>
Date:   Thu Jan 3 14:11:21 2019 +0200

    topology: enable pcm range and pipeline rate and remove frame count
    
    Enable setting pcm min and max rate from top level m4 pipeline macro.
    This way it is possible to configure the whole pipeline to correct
    samplerate range in 1 file. Previously you needed to modify the pipeline
    macros where the rate was hardcoded. As the frame count is calculated
    from pcm/dai rate and scheduling time the frame count is obsolete.
    
    Introduce pipeline rate parameter to help configuring components with
    fixed output rate. We can't deduce this from pcm range since for example
    src might accept bigger max rate than the following dai. Even though the
    parameter is named "pipeline rate" it essentially means the "final"
    output rate to which this pipeline is connected to (dai or other
    pipeline). In capture pipelines it means the originating fixed dai rate.
    
    Signed-off-by: Jaska Uimonen <jaska.uimonen@intel.com>

:040000 040000 0f19fb6b87e672325e2ca382b44782a5cfd77b47 76f2a4e2b8a490e8456dea0d099ca19d5da600af M	tools

[plbossart]

why would this change the hw_params information?

[plbossart]

Looks like a problematic integration. The pipeline definition moved to

-dnl W_PIPELINE(stream, period, priority, frames, core, initiator, platform)
+dnl W_PIPELINE(stream, period, priority, core, initiator, platform)
 define(`W_PIPELINE',
 `SectionVendorTuples."'N_PIPELINE($1)`_tuples" {'
 `	tokens "sof_sched_tokens"'
 `	tuples."word" {'
 `		SOF_TKN_SCHED_PERIOD'		STR($2)
 `		SOF_TKN_SCHED_PRIORITY'		STR($3)
-`		SOF_TKN_SCHED_CORE'		STR($5)
-`		SOF_TKN_SCHED_FRAMES'		STR($4)
-`		SOF_TKN_SCHED_TIME_DOMAIN'	STR($6)
+`		SOF_TKN_SCHED_CORE'		STR($4)
+`		SOF_TKN_SCHED_FRAMES'		"0"
+`		SOF_TKN_SCHED_TIME_DOMAIN'	STR($5)
 `	}'
 `}'

so a value required by firmware is no longer set, but it was required by previous firmware. And we still have code in the kernel that uses this:

diff --git a/sound/soc/sof/topology.c b/sound/soc/sof/topology.c
index 17fe6a1d5f3e..e165ff915294 100644
--- a/sound/soc/sof/topology.c
+++ b/sound/soc/sof/topology.c
@@ -1504,6 +1504,13 @@ static int sof_widget_load_pipeline(struct snd_soc_component *scomp,
                goto err;
        }
 
+       if (pipeline->frames_per_sched == 0) {
+               pipeline->frames_per_sched = 48;
+               dev_dbg(sdev->dev, "plb: pipeline %s: forcing frame per sched\n",
+                       swidget->widget->name,
+                       pipeline->frames_per_sched);
+       }
+
        dev_dbg(sdev->dev, "pipeline %s: period %d pri %d mips %d core %d frames %d\n",
                swidget->widget->name, pipeline->period, pipeline->priority,
                pipeline->period_mips, pipeline->core, pipeline->frames_per_sched);

This diff fixes the problem, but to me that's a botched ABI change. if frame_per_sched is no longer necessary, it needs to be removed from the IPC definitions.

[plbossart]

@ranj063 we could fix this by putting a default value back. If only I could figure out what the M4 syntax should be, it's just painful to figure out how to divide one parameter by another...

diff --git a/tools/topology/m4/pipeline.m4 b/tools/topology/m4/pipeline.m4
index 37c5ca8d..82192fd2 100644
--- a/tools/topology/m4/pipeline.m4
+++ b/tools/topology/m4/pipeline.m4
@@ -20,7 +20,7 @@ define(`W_PIPELINE',
 `              SOF_TKN_SCHED_PERIOD'           STR($2)
 `              SOF_TKN_SCHED_PRIORITY'         STR($3)
 `              SOF_TKN_SCHED_CORE'             STR($4)
-`              SOF_TKN_SCHED_FRAMES'           "0"
+`              SOF_TKN_SCHED_FRAMES'           STR(48)
 `              SOF_TKN_SCHED_TIME_DOMAIN'      STR($5)
 `      }'
 `}'

works, but I'd need to do something like:

`		SOF_TKN_SCHED_FRAMES'		STR(`eval(`$5 / $2')')

I just can't figure out how m4 is supposed to work. We should have done the topologies in lisp, at least it would have been self-explanatory.

[ranj063]

@plbossart what you need is :

`		SOF_TKN_SCHED_FRAMES'		STR(``eval(` $5 / $2 ')'')

But the problem is that $5 is empty in some cases, in which case the above expression will evaluate to "".