Skip to content

"Interrupts enabled before system core resume" warning #3307

Closed
Closed
"Interrupts enabled before system core resume" warning#3307
Labels
suspend resumeIssues related to suspend resume (e.g. rtcwake)

Description

@plbossart
plbossart
opened on Dec 2, 2021

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

Activity

  1. plbossart commented on Dec 2, 2021

    @plbossart
    plbossart
    on Dec 2, 2021
    MemberAuthor

    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.

  2. plbossart commented on Dec 17, 2021

    @plbossart
    plbossart
    on Dec 17, 2021
    MemberAuthor

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

  3. jsarha commented on Jan 5, 2022

    @jsarha
    jsarha
    on Jan 5, 2022
    Collaborator

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

  4. jsarha commented on Jan 5, 2022

    @jsarha
    jsarha
    on Jan 5, 2022
    Collaborator

    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.

  5. plbossart commented on Jan 10, 2022

    @plbossart
    plbossart
    on Jan 10, 2022
    MemberAuthor

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

  6. plbossart
    closed this as completedon Jun 29, 2022
  7. marc-hb
    added
    suspend resumeIssues related to suspend resume (e.g. rtcwake)
    on Jul 19, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    suspend resumeIssues related to suspend resume (e.g. rtcwake)

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions