[BUG] Early wake observed while running suspend-resume with WOV

[Vamshigopal]

Describe the bug

when wov is running in background and suspending the system, the system enter S0ix state but doesn’t stay longer, its comes to S0 state immediately.

To Reproduce
cras_test_client --set_hotword_model 18:0:en_all
cras_test_client --listen_for_hotword /tmp/wov.wav &
powerd_dbus_suspend

Reproduction Rate
1/5 tries.

Expected behavior
system should stay in S0ix state till the user wakes using keyword ("ok google")

Impact
showstopper

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).

   • Kernel: Chromeos-5.10 tree https://chromium.googlesource.com/chromiumos/third_party/kernel/+log/refs/heads/chromeos-5.10/sound
   • SOF: adl-003-drop-stable + some external patches to enable WOV

2. Name of the topology file

   • Topology: sof-adl-max98390-rt5682

3. Name of the platform(s) on which the bug is observed.
   ADL

Screenshots or console output
[ 715.899906] PM: resume of devices complete after 379.775 msecs
[ 715.904098] PM: Finishing wakeup.
[ 715.904101] OOM killer enabled.
[ 715.904105] Restarting tasks ... done.
[ 715.906101] mei_hdcp 0000:00:16.0-b638ab7e-94e2-4ea2-a552-d1c54b627f04: bound 0000:00:02.0 (ops 0xffffffffb90baf70)
[ 715.906567] mei_pxp 0000:00:16.0-fbf6fcf1-96cf-4e2e-a6a6-1bab8cbe36b1: bound 0000:00:02.0 (ops 0xffffffffb90c6b50)
[ 715.932404] Resume caused by IRQ 159, AudioDSP
[ 715.932438] PM: suspend exit

Please also include the relevant sections from the firmware log and kernel log in the report (and attach the full logs for complete reference). Kernel log is taken from dmesg and firmware log from sof-logger. See https://thesofproject.github.io/latest/developer_guides/debugability/logger/index.html

[Vamshigopal]

dmesg.txt
sof-trace-logs.txt

[Vamshigopal]

@sathyap-chrome @sathya-nujella @kv2019i @ranj063 @libinyang @keqiaozhang

[Vamshigopal]

After trying bisecting experiments,
Issue not reproducing with tgl/v13.0-hotfix3 and with built release tag: releases/adl/v3.0-hotfix1 issue reproduced.

3099b80 (tag: releases/adl/v3.0-hotfix1) topology: intel: use 38.4Mhz MCLK for all Bluetooth use-cases
d12e4c2 pm_runtime: writeback secondary core's data before going to lps_wait
b04aa4b init: secondary_core_restore possibility on boot
65cc975 schedule: add possibility to restore all schedulers
815ca11 idc: add idc_restore
ed71838 lps: restore secondary cores on wake up
92ea2a3 platform: lps_wait_for_interrupt entry core check
613a57f Audio: Fix sink buffer size check in several processing components
b8c99e7 topology: sof-tgl-max9357a-rt5682: add support for ADL
ab6cf6e topology1: tgl-max98357a-rt5682 fix ENDPOINT_NAME macro
364f715 (tag: releases/tgl/v13.0-hotfix3) buffer: alloc main buffer struct in the runtime shared zone

[lgirdwood]

@Vamshigopal are you able to bisect further to a single commit as the list above has several candidates taht could potentially send a wake IRQ.

[keqiaozhang]

Duplicated with thesofproject/linux#3034?

[sathyap-chrome]

@keqiaozhang not sure 3034 is related as this one has a memory issue in logs unlike 3034 where the trace was just creating a wake event. I think both are different issues.

[sathyap-chrome]

@lgirdwood we are working on that.

[sathyap-chrome]

@lgirdwood we have narrowed down further.

On the ADL003, we have few private patches to enable Google hotword and the issue is seen with that. Interesting is that patch itself is to move the Cmake version from 3.10 to 3.13.

So we did further investigation to conclude that this commit is indeed introducing the issue

Exp 1 : TGLv13.0-hotfix3 as is + test with INTEL CLAP == NO SPURIOUS WAKES SEEN
Exp 2 : TGLv13.0-hotfix3 + only the CMKAE update patch + test with INTEL CLAP == SPURIOUS WAKE IS SEEN

Request FW team to also replicate the issue and suggest debug steps.

CCing @cujomalainey to confirm we can share the Cmake patch here (which is currently in private repo)

NOTE:
Based on @kv2019i suggestion, we took his help and took his kernel : https://github.com/kv2019i/linux/tree/topic/cros/5.10-stop-dma-backport-draft -> which has latest STOP DMA fix patches, but the issue still reproduces.

[cujomalainey]

Hi Satya, are you referring to the cake version jump to 3.13? That should already be upstream and in this repo.

[bkokoszx]

A little update.

With @kv2019i and @Vamshigopal we were trying to compare binaries with and without CMAKE update patch.
Here are the only significant difference in build log between tgl-013-drop-stable+cmake_patch (left) and tgl-013-drop-stable (right):

It is hard to explain for me why cmake update changes .static_log_entries section size, but still it should not introduce issue.

Below, there are differences in sof.map files:

The .config files are identical.

[bkokoszx]

The .static_log_entries section length difference could be probably caused by this trace:

tr_err(&dt_tr, "FW ABI 0x%x DBG ABI 0x%x tag " SOF_GIT_TAG " src hash 0x%08x (ldc hash " META_QUOTE(SOF_SRC_HASH) ")",
	       SOF_ABI_VERSION, SOF_ABI_DBG_VERSION, SOF_SRC_HASH);

[cujomalainey]

Hi Satya, are you referring to the cake version jump to 3.13? That should already be upstream and in this repo.

Well, that is the last time I try to respond to a message on my phone

Can we dump a verbose build to see what the differences are in the log?