"Interrupts enabled before system core resume" warning

[plbossart]

Forking a new issue from #3283. Re-adding the finding from @marc-hb that we've add this issue since PR #3153 (tested on 2021-09-14)

After a lot of "data-mining", https://sof-ci.01.org/linuxpr/PR3153/build6340/devicetest/?model=APL_UP2_NOCODEC&testcase=check-suspend-resume-with-playback is apparently the very first time the Interrupts enabled... syscore_resume warnings appeared:

[ 1310.243035] kernel: sof-audio-pci-intel-apl 0000:00:0e.0: Debug PCIW: 00000010 at  00000044
[ 1310.244151] kernel: sof-audio-pci-intel-apl 0000:00:0e.0: Current DSP power state: D3
[ 1310.303552] kernel: ACPI: PM: Preparing to enter system sleep state S3
[ 1310.304029] kernel: ACPI: PM: Saving platform NVS memory
[ 1310.304036] kernel: Disabling non-boot CPUs ...
[ 1310.306051] kernel: smpboot: CPU 1 is now offline
[ 1310.308507] kernel: smpboot: CPU 2 is now offline
[ 1310.310910] kernel: smpboot: CPU 3 is now offline
[ 1310.313049] kernel: ACPI: PM: Low-level resume complete
[ 1310.313396] kernel: ACPI: PM: Restoring platform NVS memory
[ 1310.313406] kernel: ------------[ cut here ]------------
[ 1310.313409] kernel: Interrupts enabled before system core resume.
[ 1310.313445] kernel: WARNING: CPU: 0 PID: 24845 at drivers/base/syscore.c:96 syscore_resume+0x190/0x1a0
[ 1310.313468] kernel: Modules linked in: snd_usb_audio snd_hwdep snd_sof_pci_intel_tgl snd_sof_pci_intel_icl snd_sof_pci_intel_cnl snd_sof_nocodec snd_sof_pci_intel_apl snd_sof_intel_hda_common snd_sof_pci_intel_tng snd_sof_pci snd_sof_acpi_intel_bdw snd_sof_acpi_intel_byt snd_sof_acpi snd_sof_intel_atom snd_sof snd_sof_xtensa_dsp snd_soc_core snd_compress snd_soc_acpi_intel_match snd_soc_acpi snd_intel_dspcfg snd_pcm snd_usbmidi_lib fuse ledtrig_audio snd_soc_sst_ipc snd_soc_sst_dsp snd_seq_midi snd_seq_midi_event x86_pkg_temp_thermal snd_rawmidi snd_seq snd_seq_device snd_timer snd i915 i2c_algo_bit ttm drm_kms_helper soundcore mei_me mei drm drm_panel_orientation_quirks efivarfs mmc_block sdhci_pci cqhci sdhci intel_lpss_pci intel_lpss idma64 xhci_pci mfd_core xhci_hcd [last unloaded: snd_pcm]
[ 1310.313678] kernel: CPU: 0 PID: 24845 Comm: rtcwake Not tainted 5.15.0-rc1-pr3153-6340-nocodec #9216e106
[ 1310.313688] kernel: Hardware name: AAEON UP-APL01/UP-APL01, BIOS UPA1AM36 04/10/2018
[ 1310.313693] kernel: RIP: 0010:syscore_resume+0x190/0x1a0
[ 1310.313704] kernel: Code: 58 4e 00 0f 0b e9 f3 fe ff ff 80 3d b3 fc 21 01 00 0f 85 ab fe ff ff 48 c7 c7 e8 b4 de 96 c6 05 9f fc 21 01 01 e8 54 58 4e 00 <0f> 0b e9 91 fe ff ff 66 0f 1f 84 00 00 00 00 00 41 54 53 0f 1f 44
[ 1310.313712] kernel: RSP: 0018:ffffa6ca01923d50 EFLAGS: 00010282
[ 1310.313720] kernel: RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000027
[ 1310.313726] kernel: RDX: 0000000000000027 RSI: 0000000074f5853d RDI: ffff96567b7d7778
[ 1310.313731] kernel: RBP: 0000000000000003 R08: ffff96567b7d7770 R09: 0000000000000000
[ 1310.313736] kernel: R10: 0000000000000001 R11: 00000000006d91b0 R12: 0000000000000000
[ 1310.313741] kernel: R13: ffffa6ca01923d68 R14: 0000000000000000 R15: 0000000000000003
[ 1310.313747] kernel: FS:  00007f4f330f1580(0000) GS:ffff96567b600000(0000) knlGS:0000000000000000
[ 1310.313753] kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1310.313759] kernel: CR2: 00005620e3e11478 CR3: 0000000109ae0000 CR4: 00000000003506f0
[ 1310.313764] kernel: Call Trace:
[ 1310.313776] kernel:  suspend_devices_and_enter+0x72c/0x880
[ 1310.313795] kernel:  pm_suspend.cold+0x329/0x374
[ 1310.313809] kernel:  state_store+0x6c/0xd0
[ 1310.313821] kernel:  kernfs_fop_write_iter+0x124/0x1c0
[ 1310.313836] kernel:  new_sync_write+0x120/0x1b0
[ 1310.313859] kernel:  vfs_write+0x223/0x300
[ 1310.313872] kernel:  ksys_write+0x63/0xe0
[ 1310.313884] kernel:  do_syscall_64+0x3b/0x90
[ 1310.313896] kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 1310.313906] kernel: RIP: 0033:0x7f4f3300f057
[ 1310.313914] kernel: Code: 64 89 02 48 c7 c0 ff ff ff ff eb bb 0f 1f 80 00 00 00 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 51 c3 48 83 ec 28 48 89 54 24 18 48 89 74 24
[ 1310.313921] kernel: RSP: 002b:00007ffd08e3c9c8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 1310.313930] kernel: RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007f4f3300f057
[ 1310.313936] kernel: RDX: 0000000000000004 RSI: 000055b079455640 RDI: 0000000000000004
[ 1310.313940] kernel: RBP: 000055b079455640 R08: 0000000000000000 R09: 0000000000000004
[ 1310.313946] kernel: R10: 000055b07758f2a6 R11: 0000000000000246 R12: 0000000000000004
[ 1310.313950] kernel: R13: 000055b0794525e0 R14: 00007f4f330eb4a0 R15: 00007f4f330ea8a0
[ 1310.313973] kernel: ---[ end trace a96540680a4e8096 ]---
[ 1310.313979] kernel: ------------[ cut here ]------------
[ 1310.313982] kernel: Interrupts enabled after init_counter_refs+0x0/0x60
[ 1310.314015] kernel: WARNING: CPU: 0 PID: 24845 at drivers/base/syscore.c:103 syscore_resume+0x169/0x1a0
[ 1310.314026] kernel: Modules linked in: snd_usb_audio snd_hwdep snd_sof_pci_intel_tgl snd_sof_pci_intel_icl snd_sof_pci_intel_cnl snd_sof_nocodec snd_sof_pci_intel_apl snd_sof_intel_hda_common snd_sof_pci_intel_tng snd_sof_pci snd_sof_acpi_intel_bdw snd_sof_acpi_intel_byt snd_sof_acpi snd_sof_intel_atom snd_sof snd_sof_xtensa_dsp snd_soc_core snd_compress snd_soc_acpi_intel_match snd_soc_acpi snd_intel_dspcfg snd_pcm snd_usbmidi_lib fuse ledtrig_audio snd_soc_sst_ipc snd_soc_sst_dsp snd_seq_midi snd_seq_midi_event x86_pkg_temp_thermal snd_rawmidi snd_seq snd_seq_device snd_timer snd i915 i2c_algo_bit ttm drm_kms_helper soundcore mei_me mei drm drm_panel_orientation_quirks efivarfs mmc_block sdhci_pci cqhci sdhci intel_lpss_pci intel_lpss idma64 xhci_pci mfd_core xhci_hcd [last unloaded: snd_pcm]
[ 1310.314208] kernel: CPU: 0 PID: 24845 Comm: rtcwake Tainted: G        W         5.15.0-rc1-pr3153-6340-nocodec #9216e106
[ 1310.314216] kernel: Hardware name: AAEON UP-APL01/UP-APL01, BIOS UPA1AM36 04/10/2018
[ 1310.314220] kernel: RIP: 0010:syscore_resume+0x169/0x1a0
[ 1310.314228] kernel: Code: 69 e9 d8 fe ff ff 80 3d dd fc 21 01 00 0f 85 11 ff ff ff 48 8b 73 18 48 c7 c7 8f b5 de 96 c6 05 c5 fc 21 01 01 e8 7b 58 4e 00 <0f> 0b e9 f3 fe ff ff 80 3d b3 fc 21 01 00 0f 85 ab fe ff ff 48 c7
[ 1310.314235] kernel: RSP: 0018:ffffa6ca01923d50 EFLAGS: 00010282
[ 1310.314243] kernel: RAX: 0000000000000000 RBX: ffffffff97055e00 RCX: 0000000000000027
[ 1310.314248] kernel: RDX: 0000000000000027 RSI: 0000000074f5853d RDI: ffff96567b7d7778
[ 1310.314253] kernel: RBP: 0000000000000003 R08: ffff96567b7d7770 R09: 0000000000000000
[ 1310.314258] kernel: R10: 0000000000000001 R11: 0000000097ef0fd8 R12: 0000000000000000
[ 1310.314263] kernel: R13: ffffa6ca01923d68 R14: 0000000000000000 R15: 0000000000000003
[ 1310.314268] kernel: FS:  00007f4f330f1580(0000) GS:ffff96567b600000(0000) knlGS:0000000000000000
[ 1310.314274] kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1310.314279] kernel: CR2: 00005620e3e11478 CR3: 0000000109ae0000 CR4: 00000000003506f0
[ 1310.314284] kernel: Call Trace:
[ 1310.314289] kernel:  suspend_devices_and_enter+0x72c/0x880
[ 1310.314305] kernel:  pm_suspend.cold+0x329/0x374
[ 1310.314316] kernel:  state_store+0x6c/0xd0
[ 1310.314327] kernel:  kernfs_fop_write_iter+0x124/0x1c0
[ 1310.314341] kernel:  new_sync_write+0x120/0x1b0
[ 1310.314361] kernel:  vfs_write+0x223/0x300
[ 1310.314374] kernel:  ksys_write+0x63/0xe0
[ 1310.314387] kernel:  do_syscall_64+0x3b/0x90
[ 1310.314397] kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 1310.314406] kernel: RIP: 0033:0x7f4f3300f057
[ 1310.314411] kernel: Code: 64 89 02 48 c7 c0 ff ff ff ff eb bb 0f 1f 80 00 00 00 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 51 c3 48 83 ec 28 48 89 54 24 18 48 89 74 24
[ 1310.314418] kernel: RSP: 002b:00007ffd08e3c9c8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 1310.314426] kernel: RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007f4f3300f057
[ 1310.314431] kernel: RDX: 0000000000000004 RSI: 000055b079455640 RDI: 0000000000000004
[ 1310.314436] kernel: RBP: 000055b079455640 R08: 0000000000000000 R09: 0000000000000004
[ 1310.314441] kernel: R10: 000055b07758f2a6 R11: 0000000000000246 R12: 0000000000000004
[ 1310.314446] kernel: R13: 000055b0794525e0 R14: 00007f4f330eb4a0 R15: 00007f4f330ea8a0
[ 1310.314467] kernel: ---[ end trace a96540680a4e8097 ]---
[ 1310.319741] kernel: Enabling non-boot CPUs ...
[ 1310.319928] kernel: x86: Booting SMP configuration:
[ 1310.319933] kernel: smpboot: Booting Node 0 Processor 1 APIC 0x2
[ 1310.322489] kernel: ACPI: \_PR_.CPU1: Found 3 idle states
[ 1310.323323] kernel: CPU1 is up
[ 1310.323488] kernel: smpboot: Booting Node 0 Processor 2 APIC 0x4
[ 1310.330333] kernel: ACPI: \_PR_.CPU2: Found 3 idle states
[ 1310.331121] kernel: CPU2 is up
[ 1310.331314] kernel: smpboot: Booting Node 0 Processor 3 APIC 0x6
[ 1310.334276] kernel: ACPI: \_PR_.CPU3: Found 3 idle states
[ 1310.335073] kernel: CPU3 is up
[ 1310.335425] kernel: ACPI: PM: Waking up from system sleep state S3
[ 1310.365081] kernel: sof-audio-pci-intel-apl 0000:00:0e.0: Debug PCIR: 00000000 at  00000044
[ 1310.365129] kernel: sof-audio-pci-intel-apl 0000:00:0e.0: Debug PCIR: 00000040 at  00000048
[ 1310.365140] kernel: sof-audio-pci-intel-apl 0000:00:0e.0: Debug PCIW: 00000000 at  00000048
[ 1310.368167] kernel: sof-audio-pci-intel-apl 0000:00:0e.0: Debug PCIR: 00000000 at  00000048
[ 1310.368185] kernel: sof-audio-pci-intel-apl 0000:00:0e.0: Debug PCIW: 00000040 at  00000048

[plbossart]

PR #3153 was based on 5.15-rc1, so we need to bisect between 5.14 and 5.15-rc1 to see what commit added this warning.

[plbossart]

I tried to bisect but was unsuccessful in locating an issue. If someone has time to spare this is very much open.

[jsarha]

I completed the bisect on my up11i and this is is where it ended:

a8b76910e465d718effce0cad306a21fa4f3526b is the first bad commit
commit a8b76910e465d718effce0cad306a21fa4f3526b
Author: Valentin Schneider <valentin.schneider@arm.com>
Date:   Wed Nov 10 20:24:44 2021 +0000

    preempt: Restore preemption model selection configs
    
    Commit c597bfddc9e9 ("sched: Provide Kconfig support for default dynamic
    preempt mode") changed the selectable config names for the preemption
    model. This means a config file must now select
    
      CONFIG_PREEMPT_BEHAVIOUR=y
    
    rather than
    
      CONFIG_PREEMPT=y
    
    to get a preemptible kernel. This means all arch config files would need to
    be updated - right now they'll all end up with the default
    CONFIG_PREEMPT_NONE_BEHAVIOUR.
    
    Rather than touch a good hundred of config files, restore usage of
    CONFIG_PREEMPT{_NONE, _VOLUNTARY}. Make them configure:
    o The build-time preemption model when !PREEMPT_DYNAMIC
    o The default boot-time preemption model when PREEMPT_DYNAMIC
    
    Add siblings of those configs with the _BUILD suffix to unconditionally
    designate the build-time preemption model (PREEMPT_DYNAMIC is built with
    the "highest" preemption model it supports, aka PREEMPT). Downstream
    configs should by now all be depending / selected by CONFIG_PREEMPTION
    rather than CONFIG_PREEMPT, so only a few sites need patching up.
    
    Signed-off-by: Valentin Schneider <valentin.schneider@arm.com>
    Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
    Acked-by: Marco Elver <elver@google.com>
    Link: https://lore.kernel.org/r/20211110202448.4054153-2-valentin.schneider@arm.com

 include/linux/kernel.h   |  2 +-
 include/linux/vermagic.h |  2 +-
 init/Makefile            |  2 +-
 kernel/Kconfig.preempt   | 42 +++++++++++++++++++++---------------------
 kernel/sched/core.c      |  6 +++---
 5 files changed, 27 insertions(+), 27 deletions(-)

[jsarha]

Hmm, the above bisect result is probably quite useless. The above commit just brought up the problem with my static defconfig setup. The root cause is still hidden. However, I have other tasks spend my time on now, so I leave this be for the time being.

[plbossart]

@jsarha the bisect not completely useless, you confirmed the initial finding in #3283 that a change in the preemption changes the way interrupts are handled.

I was also unable to find the real root cause, it's just too difficult to reproduce reliably.