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

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

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
Name of the topology file
- Topology: sof-adl-max98390-rt5682
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

dmesg.txt
sof-trace-logs.txt

@sathyap-chrome

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

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

@Vamshigopal

@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.

Duplicated with thesofproject/linux#3034?

@keqiaozhang

@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.

@lgirdwood

@lgirdwood we are working on that.

@lgirdwood

@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.

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

@kv2019i

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.

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);

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?

@cujomalainey

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

@cujomalainey attached the verbose build logs for above observation. If you are looking for same.

build-log-with-cmake.txt
build-log-without-cmake.txt

Hi Vamshi,

Are you building with multicore enabled? If so, please disable it to help the logs align better. Thanks

@cujomalainey

Hi @cujomalainey
here are logs from building made by make bin command
build-log-with-cmake-bkokoszx.txt
build-log-without-cmake-bkokoszx.txt
The main difference is in .static_log_entries section size, which I wrote above.
.

@bkokoszx

@bkokoszx Thanks, I also see a diff involving python in your log

-make[3]: Nothing to be done for 'CMakeFiles/genconfig.dir/build'.
+[  9%] Generating /home/admin/Documents/sof/sof/build_tgl/generated/include/autoconfig.h^M
+cd /home/admin/Documents/sof/sof/build_tgl/generated && /usr/local/bin/cmake -E env srctree=/home/admin/Documents/sof/sof "CC_VERSION_TEXT=xt-xcc version 12.0.8" ARCH=xtensa /usr/bin/python3.5 /home/admin/Documents/sof/sof/scripts/kconfig/genconfig.py --header-path /home/admin/Documents/sof/sof/build_tgl/generated/include/autoconfig.h /home/admin/Documents/sof/sof/Kconfig^M
+warning: the int symbol CORE_COUNT (defined at src/platform/Kconfig:227) has a non-int default MP_NUM_CPUS (undefined)^M

Python is involved in the breaking change. I wonder if maybe there is a different in artifacts generated. Can we check that? Is the script just gereating the autoconfig header?

Hi Vamshi,

Are you building with multicore enabled? If so, please disable it to help the logs align better. Thanks

Will try that !!

@sathyap-chrome

@sathyap-chrome just to make sure I am clear, I just mean don't pass -j to make not SOF multicore

Oh you mean just the build to be a single thread !! got it

So I've found something funny with structure alignment and the build (some structures having different alignments set), probably unrelated but worth double check.
I'm seeing a delta between what rimage and SOF use for some structure sizes esp when using ALIGN_UP_COMPILE(sizeof(struct ext_man_fw_version), EXT_MAN_ALIGN),
e.g. the manifest structures are aligned on 16bytes when used but on 4 bytes when declared.

---------------------- src/include/kernel/ext_manifest.h ----------------------
index c429cbe03..06beb9cb9 100644
@@ -119,39 +119,39 @@ struct ext_man_fw_version {
 	/* use sof_ipc struct because of code re-use */
 	struct sof_ipc_fw_version version;
 	uint32_t flags;
-} __attribute__((packed, aligned(4)));
+} __attribute__((packed, aligned(16)));
 
 /* windows info */
 struct ext_man_windows {
 	struct ext_man_elem_header hdr;
 	/* use sof_ipc struct because of code re-use */
 	struct sof_ipc_window window;
-} __attribute__((packed, aligned(4)));
+} __attribute__((packed, aligned(16)));
 
 /* Used C compiler description */
 struct ext_man_cc_version {
 	struct ext_man_elem_header hdr;
 	/* use sof_ipc struct because of code re-use */
 	struct sof_ipc_cc_version cc_version;
-} __attribute__((packed, aligned(4)));
+} __attribute__((packed, aligned(16)));
 
 struct ext_man_probe_support {
 	struct ext_man_elem_header hdr;
 	/* use sof_ipc struct because of code re-use */
 	struct sof_ipc_probe_support probe;
-} __attribute__((packed, aligned(4)));
+} __attribute__((packed, aligned(16)));
 
 struct ext_man_dbg_abi {
 	struct ext_man_elem_header hdr;
 	/* use sof_ipc struct because of code re-use */
 	struct sof_ipc_user_abi_version dbg_abi;
-} __attribute__((packed, aligned(4)));
+} __attribute__((packed, aligned(16)));
 
 /** EXT_MAN_ELEM_CONFIG_DATA elements (ABI3.17) */
 struct ext_man_config_data {
 	struct ext_man_elem_header hdr;
 
 	struct config_elem elems[];
-} __attribute__((packed, aligned(4)));
+} __attribute__((packed, aligned(16)));
 
 #endif /* __KERNEL_EXT_MANIFEST_H__ */

Binaries include the git version by default, which makes comparing binaries across git version very painful. But there is a very simple workaround: create a two-lines long sof/.tarball-version file. I always have one like this:

v1.2.3
deadbeef

For zephyr it's sof/zephyr/.tarball-version.

Don't forget to disable debug sections, they create a ton of binary noise

--- a/src/arch/xtensa/CMakeLists.txt
+++ b/src/arch/xtensa/CMakeLists.txt
@@ -125,7 +125,7 @@ separate_arguments(EXTRA_CFLAGS_AS_LIST  NATIVE_COMMAND  ${EXTRA_CFLAGS})
 # de-duplication "feature"
 target_compile_options(sof_options INTERFACE
        $<$<COMPILE_LANGUAGE:C>:
-               -${optimization_flag} -g
+               -${optimization_flag} -g0
                -Wall -Werror
                -Wl,-EL
                -Wmissing-prototypes

I also find this useful:

--- a/scripts/cmake/version.cmake
+++ b/scripts/cmake/version.cmake
@@ -85,7 +85,7 @@ if(NOT SOF_TAG)
 endif()
 
 # Calculate source hash value, used to check ldc file and firmware compatibility
-if(EXISTS ${SOF_ROOT_SOURCE_DIRECTORY}/.git/)
+if(EXISTS ${SOF_ROOT_SOURCE_DIRECTORY}/.gitxx/)
        set(SOURCE_HASH_DIR "${SOF_ROOT_BINARY_DIRECTORY}/source_hash")
        file(MAKE_DIRECTORY ${SOURCE_HASH_DIR})
        # list tracked files from src directory

The design of the dictionary checksum is wrong, it should checksum the dictionary. I digress.

Unlike the very simple sof/.tarball-version, these two patches are unfortunately less inconvenient to keep when bisecting/etc.

You may also find useful the reproducible.ri file I recently added to the build.
Last but not least, the awesome apt-get install diffoscope can recurse in ELF files and compare disassembled ELF sections in Xtensa code with this PATH hack:
PATH=$HOME/SOFworkspace/crosstool-ng/builds/xtensa-apl-elf/xtensa-apl-elf/bin/:$PATH
Do NOT make this PATH hack persistent or it will break a number of things including the... SOF build.

A quick update:

problem is only happening on some ADL system (e.g. on a brya board I have, problem is not reproduced)
we have at least one report of problem occuring without the cmake min-ver patch
on affected boards, there is some linkage to tracing (e.g. occurence rate changes with certain traces disabled), but the exact relation is not clear

We have now test data pointing to an algorithm and dmic sensitivity issue.

Some of the observations earlier in the debug were related to thesofproject/linux#3034 . By disabling FW trace, that can be excluded from experiments.

If we then force zero input (e.g. by muting with a PGA in the pipeline) on affected systems, we no longer unexpected early/spurious wakes. Some of the bisect results earlier were done with DUTs not in fully acoustically isolated environment. With controlled environment, there results cannot be reproduced. Further, we have checked from logs that when the early wakeups have occured, the DSP irq tree status values seem as expected -> e.g. it's a real wake-up triggered by DSP algorithm code.

Waiting for bug reporter to confirm, but from SOF driver and firmware perspective, system seems to work as expected.

Navigation Menu

Repository navigation

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

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

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

Description

Activity

Vamshigopal commented on Nov 30, 2021

Vamshigopal commented on Nov 30, 2021

Vamshigopal commented on Nov 30, 2021

lgirdwood commented on Dec 1, 2021

keqiaozhang commented on Dec 6, 2021

sathyap-chrome commented on Dec 6, 2021

sathyap-chrome commented on Dec 6, 2021

sathyap-chrome commented on Dec 6, 2021

cujomalainey commented on Dec 6, 2021

bkokoszx commented on Dec 7, 2021

bkokoszx commented on Dec 7, 2021

cujomalainey commented on Dec 7, 2021

Vamshigopal commented on Dec 8, 2021

cujomalainey commented on Dec 8, 2021

bkokoszx commented on Dec 8, 2021

cujomalainey commented on Dec 8, 2021

sathyap-chrome commented on Dec 8, 2021

cujomalainey commented on Dec 8, 2021

sathyap-chrome commented on Dec 8, 2021

lgirdwood commented on Dec 8, 2021

marc-hb commented on Dec 9, 2021

kv2019i commented on Dec 13, 2021

kv2019i commented on Dec 16, 2021

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions