Skip to content

[BUG] [CML] [APL] using smp_processor_id() in preemptible (suspend/resume failure with 5.16-rc kernel) #3283

Closed
Closed
[BUG] [CML] [APL] using smp_processor_id() in preemptible (suspend/resume failure with 5.16-rc kernel)#3283
Assignees
plbossartlgirdwood
Labels
APLApplies to ApolloLake platformCMLApplies to Comet Lake platformbugSomething isn't workingsuspend resumeIssues related to suspend resume (e.g. rtcwake)

Description

@kv2019i
kv2019i
opened on Nov 18, 2021

Describe the bug
Kernel errors with 5.16-rc1 on UP2 that are picked up by sof-test:

[ 8044.297656] kernel: BUG: using smp_processor_id() in preemptible [00000000] code: rtcwake/115421
[ 8044.297985] kernel: BUG: using smp_processor_id() in preemptible [00000000] code: rtcwake/115421
[ 8044.298267] kernel: BUG: using __this_cpu_read() in preemptible [00000000] code: rtcwake/115421
[ 8044.298576] kernel: BUG: using smp_processor_id() in preemptible [00000000] code: rtcwake/115421
[ 8044.298945] kernel: BUG: using smp_processor_id() in preemptible [00000000] code: rtcwake/115421
[ 8044.299278] kernel: BUG: using smp_processor_id() in preemptible [00000000] code: rtcwake/115421
[ 8044.299593] kernel: BUG: using __this_cpu_read() in preemptible [00000000] code: rtcwake/115421
[ 8044.299927] kernel: BUG: using __this_cpu_read() in preemptible [00000000] code: rtcwake/115421
[ 8044.300232] kernel: BUG: using __this_cpu_read() in preemptible [00000000] code: rtcwake/115421
[ 8044.300535] kernel: BUG: using __this_cpu_read() in preemptible [00000000] code: rtcwake/115421

To Reproduce
https://sof-ci.sh.intel.com/#/result/planresultdetail/8296?model=APL_UP2_NOCODEC&testcase=check-suspend-resume-with-playback-5

Started with upstream merge #3282

Activity

  1. kv2019i commented on Nov 18, 2021

    @kv2019i
    kv2019i
    on Nov 18, 2021
    CollaboratorAuthor

    Also with CML:
    https://sof-ci.01.org/linuxpr/PR3282/build6722/devicetest/?model=CML_RVP_SDW&testcase=check-suspend-resume-with-playback-5

  2. marc-hb commented on Nov 18, 2021

    @marc-hb
    marc-hb
    on Nov 18, 2021
    Collaborator

    Interesting, could this help explain why we had so many timeouts with rtcwake thesofproject/sof-test#650 ?

  3. marc-hb
    assigned
    plbossart
    and
    lgirdwood
    on Nov 18, 2021

  4. marc-hb commented on Nov 19, 2021

    @marc-hb
    marc-hb
    on Nov 19, 2021
    Collaborator

    @kv2019i why is this filed in sof-test? This is a kernel: BUG: that is very clearly triggered by new kernel code.

    EDIT: now transferred to linux.

  5. marc-hb commented on Nov 19, 2021

    @marc-hb
    marc-hb
    on Nov 19, 2021
    Collaborator

    After a little bit of Googling, "preemptible" implies "migratable" - to a different CPU. This is why calling per-CPU functions is bad.

  6. marc-hb commented on Nov 19, 2021

    @marc-hb
    marc-hb
    on Nov 19, 2021
    Collaborator

    using .... in preemptible is not the first error. It's only the first error found by the test code. I'm not sure it's relevant. Here's a more complete trace from https://sof-ci.01.org/linuxpr/PR3282/build6722/devicetest/ that includes the first warning in drivers/base/syscore.c:96 syscore_resume

    Nov 18 14:06:23 up2-nocodec kernel: ACPI: PM: Low-level resume complete
Nov 18 14:06:23 up2-nocodec kernel: ACPI: PM: Restoring platform NVS memory
Nov 18 14:06:23 up2-nocodec kernel: ------------[ cut here ]------------
Nov 18 14:06:23 up2-nocodec kernel: Interrupts enabled before system core resume.
Nov 18 14:06:23 up2-nocodec kernel: WARNING: CPU: 0 PID: 28872 at drivers/base/syscore.c:96 syscore_resume+0x1b3/0x1d0
Nov 18 14:06:23 up2-nocodec 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_nocod>
Nov 18 14:06:23 up2-nocodec kernel: CPU: 0 PID: 28872 Comm: rtcwake Not tainted 5.16.0-rc1-pr3282-6722-nocodec #12d19efd
Nov 18 14:06:23 up2-nocodec kernel: Hardware name: AAEON UP-APL01/UP-APL01, BIOS UPA1AM36 04/10/2018
Nov 18 14:06:23 up2-nocodec kernel: RIP: 0010:syscore_resume+0x1b3/0x1d0
Nov 18 14:06:23 up2-nocodec kernel: Code: 42 50 00 0f 0b e9 d0 fe ff ff 80 3d cd 93 32 01 00 0f 85 88 fe ff ff 48 c7 c7 a0 8d 62 bd c6 05 b9 93 32 01 01 e8 da>
Nov 18 14:06:23 up2-nocodec kernel: RSP: 0018:ffffb02e40bf7d58 EFLAGS: 00010282
Nov 18 14:06:23 up2-nocodec kernel: RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
Nov 18 14:06:23 up2-nocodec kernel: RDX: 0000000000000001 RSI: ffffffffbd5b3e89 RDI: 00000000ffffffff
Nov 18 14:06:23 up2-nocodec kernel: RBP: 0000000000000003 R08: 00000177acf52545 R09: 0000000000000000
Nov 18 14:06:23 up2-nocodec kernel: R10: 0000000000000001 R11: 0000000000000001 R12: 0000000000000000
Nov 18 14:06:23 up2-nocodec kernel: R13: ffffb02e40bf7d70 R14: 0000000000000000 R15: 0000000000000003
Nov 18 14:06:23 up2-nocodec kernel: FS:  00007f6b4843c580(0000) GS:ffffa1e67b600000(0000) knlGS:0000000000000000
Nov 18 14:06:23 up2-nocodec kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Nov 18 14:06:23 up2-nocodec kernel: CR2: 00007f2b49ed1b08 CR3: 00000001353de000 CR4: 00000000003506f0
Nov 18 14:06:23 up2-nocodec kernel: Call Trace:
Nov 18 14:06:23 up2-nocodec kernel:  <TASK>
Nov 18 14:06:23 up2-nocodec kernel:  suspend_devices_and_enter+0x749/0x8f0
Nov 18 14:06:23 up2-nocodec kernel:  pm_suspend.cold+0x2b1/0x2fc
Nov 18 14:06:23 up2-nocodec kernel:  state_store+0x6c/0xd0
Nov 18 14:06:23 up2-nocodec kernel:  kernfs_fop_write_iter+0x124/0x1c0
Nov 18 14:06:23 up2-nocodec kernel:  new_sync_write+0x120/0x1b0
Nov 18 14:06:23 up2-nocodec kernel:  vfs_write+0x239/0x310
Nov 18 14:06:23 up2-nocodec kernel:  ksys_write+0x63/0xe0
Nov 18 14:06:23 up2-nocodec kernel:  do_syscall_64+0x3b/0x90
Nov 18 14:06:23 up2-nocodec kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xae
Nov 18 14:06:23 up2-nocodec kernel: RIP: 0033:0x7f6b4835a057
Nov 18 14:06:23 up2-nocodec 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>
Nov 18 14:06:23 up2-nocodec kernel: RSP: 002b:00007ffe0abe5dd8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
Nov 18 14:06:23 up2-nocodec kernel: RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007f6b4835a057
Nov 18 14:06:23 up2-nocodec kernel: RDX: 0000000000000004 RSI: 00005600c2c99640 RDI: 0000000000000004
Nov 18 14:06:23 up2-nocodec kernel: RBP: 00005600c2c99640 R08: 0000000000000000 R09: 0000000000000004
Nov 18 14:06:23 up2-nocodec kernel: R10: 00005600c279a2a6 R11: 0000000000000246 R12: 0000000000000004
Nov 18 14:06:23 up2-nocodec kernel: R13: 00005600c2c965e0 R14: 00007f6b484364a0 R15: 00007f6b484358a0
Nov 18 14:06:23 up2-nocodec kernel:  </TASK>
Nov 18 14:06:23 up2-nocodec kernel: ---[ end trace 88a06c414b3cf79c ]---
Nov 18 14:06:23 up2-nocodec kernel: ------------[ cut here ]------------
Nov 18 14:06:23 up2-nocodec kernel: Interrupts enabled after init_counter_refs+0x0/0x60
Nov 18 14:06:23 up2-nocodec kernel: WARNING: CPU: 0 PID: 28872 at drivers/base/syscore.c:103 syscore_resume+0x18c/0x1d0
Nov 18 14:06:23 up2-nocodec 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_nocod>
Nov 18 14:06:23 up2-nocodec kernel: CPU: 0 PID: 28872 Comm: rtcwake Tainted: G        W         5.16.0-rc1-pr3282-6722-nocodec #12d19efd
Nov 18 14:06:23 up2-nocodec kernel: Hardware name: AAEON UP-APL01/UP-APL01, BIOS UPA1AM36 04/10/2018
Nov 18 14:06:23 up2-nocodec kernel: RIP: 0010:syscore_resume+0x18c/0x1d0
Nov 18 14:06:23 up2-nocodec kernel: Code: 00 e9 b5 fe ff ff 80 3d f7 93 32 01 00 0f 85 ee fe ff ff 48 8b 73 18 48 c7 c7 47 8e 62 bd c6 05 df 93 32 01 01 e8 01>
Nov 18 14:06:23 up2-nocodec kernel: RSP: 0018:ffffb02e40bf7d58 EFLAGS: 00010282
Nov 18 14:06:23 up2-nocodec kernel: RAX: 0000000000000000 RBX: ffffffffbd855fc0 RCX: 0000000000000000
Nov 18 14:06:23 up2-nocodec kernel: RDX: 0000000000000001 RSI: ffffffffbd5b3e89 RDI: 00000000ffffffff
Nov 18 14:06:23 up2-nocodec kernel: RBP: 0000000000000003 R08: 00000177acfee096 R09: 0000000000000000
Nov 18 14:06:23 up2-nocodec kernel: R10: 0000000000000001 R11: 0000000000000001 R12: 0000000000000000
Nov 18 14:06:23 up2-nocodec kernel: R13: ffffb02e40bf7d70 R14: 0000000000000000 R15: 0000000000000003
Nov 18 14:06:23 up2-nocodec kernel: FS:  00007f6b4843c580(0000) GS:ffffa1e67b600000(0000) knlGS:0000000000000000
Nov 18 14:06:23 up2-nocodec kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Nov 18 14:06:23 up2-nocodec kernel: CR2: 00007f2b49ed1b08 CR3: 00000001353de000 CR4: 00000000003506f0
Nov 18 14:06:23 up2-nocodec kernel: Call Trace:
Nov 18 14:06:23 up2-nocodec kernel:  <TASK>
Nov 18 14:06:23 up2-nocodec kernel:  suspend_devices_and_enter+0x749/0x8f0
Nov 18 14:06:23 up2-nocodec kernel:  pm_suspend.cold+0x2b1/0x2fc
Nov 18 14:06:23 up2-nocodec kernel:  state_store+0x6c/0xd0
Nov 18 14:06:23 up2-nocodec kernel:  kernfs_fop_write_iter+0x124/0x1c0
Nov 18 14:06:23 up2-nocodec kernel:  new_sync_write+0x120/0x1b0
Nov 18 14:06:23 up2-nocodec kernel:  vfs_write+0x239/0x310
Nov 18 14:06:23 up2-nocodec kernel:  ksys_write+0x63/0xe0
Nov 18 14:06:23 up2-nocodec kernel:  do_syscall_64+0x3b/0x90
Nov 18 14:06:23 up2-nocodec kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xae
Nov 18 14:06:23 up2-nocodec kernel: RIP: 0033:0x7f6b4835a057
Nov 18 14:06:23 up2-nocodec 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>
Nov 18 14:06:23 up2-nocodec kernel: RSP: 002b:00007ffe0abe5dd8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
Nov 18 14:06:23 up2-nocodec kernel: RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007f6b4835a057
Nov 18 14:06:23 up2-nocodec kernel: RDX: 0000000000000004 RSI: 00005600c2c99640 RDI: 0000000000000004
Nov 18 14:06:23 up2-nocodec kernel: RBP: 00005600c2c99640 R08: 0000000000000000 R09: 0000000000000004
Nov 18 14:06:23 up2-nocodec kernel: R10: 00005600c279a2a6 R11: 0000000000000246 R12: 0000000000000004
Nov 18 14:06:23 up2-nocodec kernel: R13: 00005600c2c965e0 R14: 00007f6b484364a0 R15: 00007f6b484358a0
Nov 18 14:06:23 up2-nocodec kernel:  </TASK>
Nov 18 14:06:23 up2-nocodec kernel: ---[ end trace 88a06c414b3cf79d ]---
Nov 18 14:06:23 up2-nocodec kernel: BUG: using smp_processor_id() in preemptible [00000000] code: rtcwake/28872
Nov 18 14:06:23 up2-nocodec kernel: caller is tsc_verify_tsc_adjust+0x14/0xe0
Nov 18 14:06:23 up2-nocodec kernel: CPU: 0 PID: 28872 Comm: rtcwake Tainted: G        W         5.16.0-rc1-pr3282-6722-nocodec #12d19efd
Nov 18 14:06:23 up2-nocodec kernel: Hardware name: AAEON UP-APL01/UP-APL01, BIOS UPA1AM36 04/10/2018
Nov 18 14:06:23 up2-nocodec kernel: Call Trace:
Nov 18 14:06:23 up2-nocodec kernel:  <TASK>
Nov 18 14:06:23 up2-nocodec kernel:  dump_stack_lvl+0x34/0x44
Nov 18 14:06:23 up2-nocodec kernel:  check_preemption_disabled+0xd9/0xe0
Nov 18 14:06:23 up2-nocodec kernel:  tsc_verify_tsc_adjust+0x14/0xe0
Nov 18 14:06:23 up2-nocodec kernel:  clocksource_resume+0x25/0x40
Nov 18 14:06:23 up2-nocodec kernel:  timekeeping_resume+0x38/0x270
Nov 18 14:06:23 up2-nocodec kernel:  syscore_resume+0x58/0x1d0
Nov 18 14:06:23 up2-nocodec kernel:  suspend_devices_and_enter+0x749/0x8f0
Nov 18 14:06:23 up2-nocodec kernel:  pm_suspend.cold+0x2b1/0x2fc
Nov 18 14:06:23 up2-nocodec kernel:  state_store+0x6c/0xd0
Nov 18 14:06:23 up2-nocodec kernel:  kernfs_fop_write_iter+0x124/0x1c0
Nov 18 14:06:23 up2-nocodec kernel:  new_sync_write+0x120/0x1b0
Nov 18 14:06:23 up2-nocodec kernel:  vfs_write+0x239/0x310
Nov 18 14:06:23 up2-nocodec kernel:  ksys_write+0x63/0xe0
Nov 18 14:06:23 up2-nocodec kernel:  do_syscall_64+0x3b/0x90
Nov 18 14:06:23 up2-nocodec kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xae
Nov 18 14:06:23 up2-nocodec kernel: RIP: 0033:0x7f6b4835a057
Nov 18 14:06:23 up2-nocodec 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>
Nov 18 14:06:23 up2-nocodec kernel: RSP: 002b:00007ffe0abe5dd8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
Nov 18 14:06:23 up2-nocodec kernel: RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007f6b4835a057
Nov 18 14:06:23 up2-nocodec kernel: RDX: 0000000000000004 RSI: 00005600c2c99640 RDI: 0000000000000004
Nov 18 14:06:23 up2-nocodec kernel: RBP: 00005600c2c99640 R08: 0000000000000000 R09: 0000000000000004
Nov 18 14:06:23 up2-nocodec kernel: R10: 00005600c279a2a6 R11: 0000000000000246 R12: 0000000000000004
Nov 18 14:06:23 up2-nocodec kernel: R13: 00005600c2c965e0 R14: 00007f6b484364a0 R15: 00007f6b484358a0
Nov 18 14:06:23 up2-nocodec kernel:  </TASK>
Nov 18 14:06:23 up2-nocodec kernel: BUG: using smp_processor_id() in preemptible [00000000] code: rtcwake/28872
Nov 18 14:06:23 up2-nocodec kernel: caller is tick_resume_local+0xe/0x50
Nov 18 14:06:23 up2-nocodec kernel: CPU: 0 PID: 28872 Comm: rtcwake Tainted: G        W         5.16.0-rc1-pr3282-6722-nocodec #12d19efd
Nov 18 14:06:23 up2-nocodec kernel: Hardware name: AAEON UP-APL01/UP-APL01, BIOS UPA1AM36 04/10/2018
Nov 18 14:06:23 up2-nocodec kernel: Call Trace:
Nov 18 14:06:23 up2-nocodec kernel:  <TASK>
Nov 18 14:06:23 up2-nocodec kernel:  dump_stack_lvl+0x34/0x44
Nov 18 14:06:23 up2-nocodec kernel:  check_preemption_disabled+0xd9/0xe0
Nov 18 14:06:23 up2-nocodec kernel:  tick_resume_local+0xe/0x50
Nov 18 14:06:23 up2-nocodec kernel:  timekeeping_resume+0x1f7/0x270
Nov 18 14:06:23 up2-nocodec kernel:  syscore_resume+0x58/0x1d0
Nov 18 14:06:23 up2-nocodec kernel:  suspend_devices_and_enter+0x749/0x8f0
Nov 18 14:06:23 up2-nocodec kernel:  pm_suspend.cold+0x2b1/0x2fc
Nov 18 14:06:23 up2-nocodec kernel:  state_store+0x6c/0xd0
Nov 18 14:06:23 up2-nocodec kernel:  kernfs_fop_write_iter+0x124/0x1c0
Nov 18 14:06:23 up2-nocodec kernel:  new_sync_write+0x120/0x1b0
Nov 18 14:06:23 up2-nocodec kernel:  vfs_write+0x239/0x310
Nov 18 14:06:23 up2-nocodec kernel:  ksys_write+0x63/0xe0
Nov 18 14:06:23 up2-nocodec kernel:  do_syscall_64+0x3b/0x90
Nov 18 14:06:23 up2-nocodec kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xae
Nov 18 14:06:23 up2-nocodec kernel: RIP: 0033:0x7f6b4835a057
Nov 18 14:06:23 up2-nocodec 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>
Nov 18 14:06:23 up2-nocodec kernel: RSP: 002b:00007ffe0abe5dd8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
Nov 18 14:06:23 up2-nocodec kernel: RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007f6b4835a057
Nov 18 14:06:23 up2-nocodec kernel: RDX: 0000000000000004 RSI: 00005600c2c99640 RDI: 0000000000000004
Nov 18 14:06:23 up2-nocodec kernel: RBP: 00005600c2c99640 R08: 0000000000000000 R09: 0000000000000004
Nov 18 14:06:23 up2-nocodec kernel: R10: 00005600c279a2a6 R11: 0000000000000246 R12: 0000000000000004
Nov 18 14:06:23 up2-nocodec kernel: R13: 00005600c2c965e0 R14: 00007f6b484364a0 R15: 00007f6b484358a0
Nov 18 14:06:23 up2-nocodec kernel:  </TASK>
Nov 18 14:06:23 up2-nocodec kernel: BUG: using __this_cpu_read() in preemptible [00000000] code: rtcwake/28872
Nov 18 14:06:23 up2-nocodec kernel: caller is tick_resume_oneshot+0xd/0x40
Nov 18 14:06:23 up2-nocodec kernel: CPU: 0 PID: 28872 Comm: rtcwake Tainted: G        W         5.16.0-rc1-pr3282-6722-nocodec #12d19efd
Nov 18 14:06:23 up2-nocodec kernel: Hardware name: AAEON UP-APL01/UP-APL01, BIOS UPA1AM36 04/10/2018
  7. marc-hb
    changed the title [-][BUG] check-suspend-resume-with-playback-5 fail on APL2 with 5.16-rc kernel[/-] [+][BUG] Interrupts enabled before system core resume (check-suspend-resume-with-playback-5 fail on APL2 with 5.16-rc kernel)[/+] on Nov 19, 2021

  8. kv2019i commented on Nov 19, 2021

    @kv2019i
    kv2019i
    on Nov 19, 2021
    CollaboratorAuthor

    @marc-hb I thought you told earlier week that this kind of non-audio kernel stuff should/could be filed here for tracking. But ack, let's file elsewhere. Retest on plain 5.16-rc1 is needed to file to kernel bugzilla.

  9. kv2019i
    closed this as completedon Nov 19, 2021
  10. marc-hb
    reopened this on Nov 19, 2021
  11. marc-hb
    transferred this issue fromthesofproject/sof-teston Nov 19, 2021

  12. marc-hb commented on Nov 19, 2021

    @marc-hb
    marc-hb
    on Nov 19, 2021
    Collaborator

    I thought you told earlier week that this kind of non-audio kernel stuff should/could be filed here for tracking....

    ... yes but not as a bug but as a task to ignore it and only if we intend on ignoring it because we looked at it carefully and we know for sure it can be safely ignored because it will not affect audio test results in any way. Unfortunately, suspend/resume bugs are often difficult to ignore in suspend/resume tests - even when they're not audio-related.

  13. marc-hb commented on Nov 19, 2021

    @marc-hb
    marc-hb
    on Nov 19, 2021
    Collaborator

    I ran journalctl -g 'Linux version|Interrupts enabled |BUG.*preempt' over the few days of logs we have on this system. Unlike the BUG: preemptible, the two Interrupts enabled warnings are NOT new to 5.16! Also, the BUG: preemptible is not happening every time with 5.16, in fact it happened only once (together with the warnings, see above)

    EDIT: one more: https://sof-ci.01.org/sofpr/PR5016/build11211/devicetest/

  14. marc-hb
    changed the title [-][BUG] Interrupts enabled before system core resume (check-suspend-resume-with-playback-5 fail on APL2 with 5.16-rc kernel)[/-] [+][BUG] [CML] [APL] using smp_processor_id() in preemptible (suspend/resume failure with 5.16-rc kernel)[/+] on Nov 20, 2021

  15. 12 remaining items

  16. plbossart commented on Dec 1, 2021

    @plbossart
    plbossart
    on Dec 1, 2021
    Member

    What this commit a8b7691 seems to do is change the configs

     diff good.config bad.config 
116,119c116,119
< CONFIG_PREEMPT_NONE_BEHAVIOUR=y
< # CONFIG_PREEMPT_VOLUNTARY_BEHAVIOUR is not set
< # CONFIG_PREEMPT_BEHAVIOUR is not set
< CONFIG_PREEMPT=y
---
> CONFIG_PREEMPT_BUILD=y
> # CONFIG_PREEMPT_NONE is not set
> CONFIG_PREEMPT_VOLUNTARY=y
> # CONFIG_PREEMPT is not set

    CONFIG_PREEMPT is not set in the 'bad' case, that's probably not so good.

  17. plbossart
    added a commit that references this issue on Dec 1, 2021

    [HACK] drivers/base: report error on interrupts enabled before resume

    341d68b

  18. plbossart commented on Dec 1, 2021

    @plbossart
    plbossart
    on Dec 1, 2021
    Member

    Another possibility is that this Kconfig change exposes issues where hidden before. We do see a warning

    [1320.674726] kernel: Interrupts enabled before system core resume.

    in all the test results, so it could very well be that the preemption errors are just a side effect of the initial error with interrupts enabled too early.

  19. plbossart commented on Dec 1, 2021

    @plbossart
    plbossart
    on Dec 1, 2021
    Member

    The interrupt problem is indeed very likely, without reverting anything but using the following diff in .config, the error does not seem to happen

    diff .config bad.config 
118,119c118,119
< # CONFIG_PREEMPT_VOLUNTARY is not set
< CONFIG_PREEMPT=y
---
> CONFIG_PREEMPT_VOLUNTARY=y
> # CONFIG_PREEMPT is not set

  20. plbossart commented on Dec 1, 2021

    @plbossart
    plbossart
    on Dec 1, 2021
    Member

    Conclusion for the day: it seems that the commit a8b7691 did change the scheduling defaults. Before CONFIG_PREEMPT was selected by default, and the change is to move to CONFIG_PREEMPT_VOLUNTARY

    We can fix this in the Kconfig options by explicitly selecting CONFIG_PREEMPT. That would give us the SAME results are before.

    And as a background task we'll have to figure out what happens when CONFIG_PREEMPT_VOLUNTARY is selected.

  21. plbossart
    added 2 commits that reference this issue on Dec 1, 2021

    base-defconfig: select PREEMPT as work-around for 5.16-rc1 changes

    63bb5b0

    base-defconfig: select PREEMPT as work-around for 5.16-rc1 changes

    3e6377c

  22. marc-hb commented on Dec 2, 2021

    @marc-hb
    marc-hb
    on Dec 2, 2021
    Collaborator

    [EDIT: this report is incomplete because I scanned only the dmesg.txt files but other test runs have only the converted dmesg.html]

    I ran a huge scan in all the kernel logs of all suspend resume test runs we still have on file. The "Interrupts enabled" warning is not old, I found it for the very first time on October 31st (daily run 7830) Sept 14 when looking at dmesg.html files too, see next comment.

    Bar one PR exception, all occurrences I found were in daily test results.

    Using playback or capture does not seem to make it more likely.

    Reproduction rate is highly platform-dependent:

    198 APL_UP2_NOCODEC
80  APL_UP2_HDA

75 CML_RVP_SDW
34 CML_RVP_NOCODEC

13 ADLS_RVP_HDA

9 WHL_UPEXT_HDA_ZEPHYR

6 TGLU_RVP_HDA_ZEPHYR
4 TGLH_RVP_NOCODEC_ZEPHYR
2 TGLH_RVP_HDA
2 TGLU_RVP_HDA

423 dmesg.txt files with the warning.

  23. marc-hb commented on Dec 2, 2021

    @marc-hb
    marc-hb
    on Dec 2, 2021
    Collaborator

    After looking at dmesg.html files too I think I found the very very first Interrupts enabled... warning:
    https://sof-ci.01.org/linuxpr/PR3153/build6340/devicetest/?model=APL_UP2_NOCODEC&testcase=check-suspend-resume-with-playback

    This was on Sep. 14th, testing #3153 Merge/sound upstream 20210914 v5.15-rc1 - probably not a coincidence!

    Stay tuned for more stats.

    EDIT: the list of platforms for the 636 dmesg.html files with the warning is basically the same: APL far more frequent than anything else, then CML, then ADLS and finally WHL and TGL. Roughly the same proportions as above.

    I'm not sure there is correlation between the WARNINGs and the test failing, at least no obvious one. Are these warnings really related to the preemptible BUG? Track in a different github issue? One appeared with 5.15, the other with 5.16

    The Interrupts enabled... warnings always go in pairs (never reproduced more than once each in a single run) except on TGLx_RVP (and only on TGLx RVP) where there is rarely a 3rd, iommu_suspend warning before the usual two. See for example internal weekly test plan 8513?model=TGLU_RVP_HDA&testcase=check-suspend-resume-100

    [ 7791.797786] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Turning i915 HDAC power 0
[ 7791.797789] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Current DSP power state: D3
[ 7791.797838] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state change: 6 -> 0
[ 7792.134067] kernel: ACPI: PM: Preparing to enter system sleep state S3
[ 7792.143100] kernel: ACPI: PM: Saving platform NVS memory
[ 7792.143170] kernel: Disabling non-boot CPUs ...
[ 7792.145551] kernel: smpboot: CPU 1 is now offline
[ 7792.147973] kernel: smpboot: CPU 2 is now offline
[ 7792.150265] kernel: smpboot: CPU 3 is now offline
[ 7792.151843] kernel: ------------[ cut here ]------------
[ 7792.151843] kernel: Interrupts enabled after iommu_suspend+0x0/0x1a0
[ 7792.151843] kernel: WARNING: CPU: 0 PID: 139667 at drivers/base/syscore.c:68 syscore_suspend+0x1c7/0x210
[ 7792.151843] kernel: Modules linked in: snd_sof_probes snd_soc_skl_hda_dsp snd_soc_intel_hda_dsp_common snd_soc_hdac_hdmi snd_sof_ipc_msg_injector snd_sof_ipc_flood_test snd_usb_audio snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic snd_soc_dmic snd_sof_pci_intel_tgl snd_sof_pci_intel_icl snd_sof_pci_intel_cnl snd_sof_pci_intel_apl snd_sof_intel_hda_common soundwire_intel soundwire_generic_allocation soundwire_cadence snd_sof_intel_hda snd_soc_hdac_hda snd_hda_ext_core snd_hda_codec snd_hwdep snd_hda_core 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_xtensa_dsp snd_sof snd_sof_utils snd_soc_acpi_intel_match snd_soc_acpi snd_intel_dspcfg snd_intel_sdw_acpi snd_soc_rt1011 snd_soc_rt715 snd_soc_rt1308_sdw snd_soc_rt1308 snd_soc_rt711 snd_soc_rt700 snd_soc_max98373_sdw snd_soc_max98373_i2c snd_soc_max98373 snd_soc_max98090 snd_soc_max98357a snd_soc_wm8804_i2c snd_soc_wm8804 snd_soc_pcm512x_i2c snd_soc_pcm512x
[ 7792.151843] kernel:  snd_soc_rt5682_sdw regmap_sdw soundwire_bus snd_soc_rt5682_i2c snd_soc_rt5682 snd_soc_rt5677 snd_soc_rt5677_spi snd_soc_rt5670 snd_soc_rt5660 snd_soc_rt5651 snd_soc_rt5645 snd_soc_rt5640 snd_soc_rl6231 snd_soc_rt298 snd_soc_rt286 snd_soc_rl6347a snd_soc_da7219 snd_soc_da7213 regmap_i2c snd_soc_core snd_compress snd_pcm fuse ax88796b asix usbnet snd_usbmidi_lib ledtrig_audio wmi_bmof snd_seq_midi snd_seq_midi_event snd_rawmidi snd_seq snd_seq_device x86_pkg_temp_thermal intel_powerclamp snd_timer snd soundcore i915 i2c_algo_bit mei_me ttm drm_kms_helper mei wmi intel_pmc_core drm drm_panel_orientation_quirks efivarfs spi_pxa2xx_platform xhci_pci intel_lpss_pci xhci_hcd intel_lpss idma64 mfd_core [last unloaded: snd_pcm]
[ 7792.151843] kernel: CPU: 0 PID: 139667 Comm: rtcwake Tainted: G     U            5.16.0-rc1-daily-default-20211127 #5
[ 7792.151843] kernel: Hardware name: AAEON UPX-TGL01/UPX-TGL01, BIOS UXTGBM14 11/05/2021
[ 7792.151843] kernel: RIP: 0010:syscore_suspend+0x1c7/0x210
[ 7792.151843] kernel: Code: 00 e9 7c fe ff ff 80 3d 4e 92 32 01 00 0f 85 db fe ff ff 48 8b 73 10 48 c7 c7 4f 91 e2 93 c6 05 36 92 32 01 01 e8 95 5f 50 00 <0f> 0b e9 bd fe ff ff 80 3d 24 92 32 01 00 0f 85 6a fe ff ff 48 c7
[ 7792.151843] kernel: RSP: 0000:ffffadb2c0b9fd50 EFLAGS: 00010282
[ 7792.151843] kernel: RAX: 0000000000000000 RBX: ffffffff9423c7a0 RCX: 0000000000000000
[ 7792.151843] kernel: RDX: 0000000000000001 RSI: ffffffff93db4179 RDI: 00000000ffffffff
[ 7792.151843] kernel: RBP: 0000000000000003 R08: 00000716407151b8 R09: 0000000000000000
[ 7792.151843] kernel: R10: 0000000000000001 R11: 0000000000000001 R12: 0000000000000000
[ 7792.151843] kernel: R13: ffffadb2c0b9fd70 R14: 0000000000000000 R15: 0000000000000003
[ 7792.151843] kernel: FS:  00007f82cd754580(0000) GS:ffff8d4cf3800000(0000) knlGS:0000000000000000
[ 7792.151843] kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 7792.151843] kernel: CR2: 00007eff24e5cb48 CR3: 000000011db8a001 CR4: 0000000000770ef0
[ 7792.151843] kernel: PKRU: 55555554
[ 7792.151843] kernel: Call Trace:
[ 7792.151843] kernel:  
[ 7792.151843] kernel:  suspend_devices_and_enter+0x1de/0x8f0
[ 7792.151843] kernel:  pm_suspend.cold+0x2b1/0x2fc
[ 7792.151843] kernel:  state_store+0x6c/0xd0
[ 7792.151843] kernel:  kernfs_fop_write_iter+0x121/0x1c0
[ 7792.151843] kernel:  new_sync_write+0x11d/0x1b0
[ 7792.151843] kernel:  vfs_write+0x239/0x310
[ 7792.151843] kernel:  ksys_write+0x63/0xe0
[ 7792.151843] kernel:  do_syscall_64+0x38/0x90
[ 7792.151843] kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 7792.151843] kernel: RIP: 0033:0x7f82cd6721e7
[ 7792.151843] 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
[ 7792.151843] kernel: RSP: 002b:00007ffd2b4254a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 7792.151843] kernel: RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007f82cd6721e7
[ 7792.151843] kernel: RDX: 0000000000000004 RSI: 00005632f0fba570 RDI: 0000000000000004
[ 7792.151843] kernel: RBP: 00005632f0fba570 R08: 0000000000000000 R09: 0000000000000004
[ 7792.151843] kernel: R10: 00005632ef3852a6 R11: 0000000000000246 R12: 0000000000000004
[ 7792.151843] kernel: R13: 00005632f0fb7510 R14: 00007f82cd74e4a0 R15: 00007f82cd74d8a0
[ 7792.151843] kernel:  
[ 7792.151843] kernel: ---[ end trace 5a4d379d2f79e963 ]---
[ 7792.151843] kernel: BUG: using __this_cpu_read() in preemptible [00000000] code: rtcwake/139667
[ 7792.151843] kernel: caller is x86_acpi_suspend_lowlevel+0x47/0x170
[ 7792.151843] kernel: CPU: 0 PID: 139667 Comm: rtcwake Tainted: G     U  W         5.16.0-rc1-daily-default-20211127 #5
[ 7792.151843] kernel: Hardware name: AAEON UPX-TGL01/UPX-TGL01, BIOS UXTGBM14 11/05/2021
[ 7792.151843] kernel: Call Trace:
[ 7792.151843] kernel:  
[ 7792.151843] kernel:  dump_stack_lvl+0x34/0x44
[ 7792.151843] kernel:  check_preemption_disabled+0xd9/0xe0
[ 7792.151843] kernel:  x86_acpi_suspend_lowlevel+0x47/0x170
[ 7792.151843] kernel:  acpi_suspend_enter+0x5d/0x260
[ 7792.151843] kernel:  ? _raw_spin_unlock_irqrestore+0x2e/0x50
[ 7792.151843] kernel:  suspend_devices_and_enter+0x790/0x8f0
[ 7792.151843] kernel:  pm_suspend.cold+0x2b1/0x2fc
[ 7792.151843] kernel:  state_store+0x6c/0xd0
[ 7792.151843] kernel:  kernfs_fop_write_iter+0x121/0x1c0
[ 7792.151843] kernel:  new_sync_write+0x11d/0x1b0
[ 7792.151843] kernel:  vfs_write+0x239/0x310
[ 7792.151843] kernel:  ksys_write+0x63/0xe0
[ 7792.151843] kernel:  do_syscall_64+0x38/0x90
[ 7792.151843] kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 7792.151843] kernel: RIP: 0033:0x7f82cd6721e7

  24. plbossart commented on Dec 2, 2021

    @plbossart
    plbossart
    on Dec 2, 2021
    Member

    Forking the discussion on the interrupt warning to #3307

  25. plbossart
    added a commit that references this issue on Dec 2, 2021

    base-defconfig: select PREEMPT as work-around for 5.16-rc1 changes

    d6d10b7

  26. marc-hb commented on Dec 10, 2021

    @marc-hb
    marc-hb
    on Dec 10, 2021
    Collaborator

    Bisecting intermittent failures is super, super hard.

    Stochastic bisection in Git https://lwn.net/Articles/877964/

  27. marc-hb
    added
    suspend resumeIssues related to suspend resume (e.g. rtcwake)
    on Jul 19, 2022

  28. plbossart commented on Jul 20, 2022

    @plbossart
    plbossart
    on Jul 20, 2022
    Member

    we haven't seen this issue in 6+ months, closing

  29. plbossart
    closed this as completedon Jul 20, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

APLApplies to ApolloLake platformCMLApplies to Comet Lake platformbugSomething isn't workingsuspend 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