Re: INFO: BISECTED: rcu_preempt detected expedited stalls on CPUs/tasks (6.1.0-rc3): in cat /sys/kernel/debug/kmemleak

From: Mirsad Goran Todorovac
Date: Tue Nov 08 2022 - 09:22:24 EST

On 05. 11. 2022. 00:39, Mirsad Goran Todorovac wrote:

On 05. 11. 2022. 00:00, srinivas pandruvada wrote:

On Fri, 2022-11-04 at 23:01 +0100, Mirsad Goran Todorovac wrote:
Dear all,

When investigating thermald kmemleak, it occurred that the "cat
/sys/kernel/debug/kmemleak"
and "tail -20 /sys/kernel/debug/kmemleak" commands take unusual
amount
of time.

This memleak occurred because of bad element in the BIOS configuration
of _OSC method.
Unfortunately fixing this in ACPI interpreter can have other side
effects as this is not expected. So the ACPICA team
(https://acpica.org/community) is looking further.

Thanks,
Srinivas

Dear Mr. Srinivas,

Thank you for the update.

However, the investigation on thermald memleak had lead to discovery of the RCU stalls
in the kmemleak itself. I felt it correct to include you in Cc: because thermald caused the
leaks in question. I suspected myself it is the problem specific to my Lenovo Ideapad 3 Intel core
i5 laptop's BIOS, because I couldn't reproduce it on the other (desktop Lenovo) computer.

Thank you very much,
Mirsad

As the system exhibited expedited stalls after which NMI and Call trace followed, under test
load the bug also caused multimedia "hickups" (i.e. Youtube video sound repeating like on
a broken record), so I thought it would be interesting to search for the cause of this behaviour.

To cut the long stroy short, here is the bisect log and log of the symptoms from syslog:

Nov  8 14:37:24 marvin-IdeaPad-3-15ITL6 kernel: [  122.907434] audit: type=1400 audit(1667914644.748:80): apparmor="DENIED" operation="capable" profile="/snap/snapd/17336/usr/lib/snapd/snap-confine" pid=3481 comm="snap-confine" capability=12  capname="net_admin"
Nov  8 14:37:24 marvin-IdeaPad-3-15ITL6 kernel: [  122.907468] audit: type=1400 audit(1667914644.748:81): apparmor="DENIED" operation="capable" profile="/snap/snapd/17336/usr/lib/snapd/snap-confine" pid=3481 comm="snap-confine" capability=38  capname="perfmon"
Nov  8 14:37:24 marvin-IdeaPad-3-15ITL6 systemd[1]: tmp-snap.rootfs_riJKwP.mount: Deactivated successfully.
Nov  8 14:37:24 marvin-IdeaPad-3-15ITL6 kernel: [  122.977628] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 0-... } 6 jiffies s: 669 root: 0x1/.
Nov  8 14:37:24 marvin-IdeaPad-3-15ITL6 kernel: [  122.977647] rcu: blocking rcu_node structures (internal RCU debug):
Nov  8 14:37:24 marvin-IdeaPad-3-15ITL6 kernel: [  122.977652] Task dump for CPU 0:
Nov  8 14:37:24 marvin-IdeaPad-3-15ITL6 kernel: [  122.977655] task:cat             state:R  running task     stack:    0 pid: 3495 ppid:  3032 flags:0x00000008
Nov  8 14:37:24 marvin-IdeaPad-3-15ITL6 kernel: [  122.977666] Call Trace:
Nov  8 14:37:24 marvin-IdeaPad-3-15ITL6 kernel: [  122.977669] <TASK>
--
Nov  8 14:37:24 marvin-IdeaPad-3-15ITL6 kernel: [  122.977717] R10: 0000000000000022 R11: 0000000000000246 R12: 0000000000022000
Nov  8 14:37:24 marvin-IdeaPad-3-15ITL6 kernel: [  122.977720] R13: 0000000000000003 R14: 0000000000020000 R15: 0000000000020000
Nov  8 14:37:24 marvin-IdeaPad-3-15ITL6 kernel: [  122.977727] </TASK>
Nov  8 14:37:24 marvin-IdeaPad-3-15ITL6 kernel: [  123.053628] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 0-... } 25 jiffies s: 669 root: 0x1/.
Nov  8 14:37:24 marvin-IdeaPad-3-15ITL6 kernel: [  123.053644] rcu: blocking rcu_node structures (internal RCU debug):
Nov  8 14:37:24 marvin-IdeaPad-3-15ITL6 kernel: [  123.053648] Task dump for CPU 0:
Nov  8 14:37:24 marvin-IdeaPad-3-15ITL6 kernel: [  123.053650] task:cat             state:R  running task     stack:    0 pid: 3495 ppid:  3032 flags:0x00000008
Nov  8 14:37:24 marvin-IdeaPad-3-15ITL6 kernel: [  123.053659] Call Trace:
Nov  8 14:37:24 marvin-IdeaPad-3-15ITL6 kernel: [  123.053661] <TASK>
--
Nov  8 14:37:24 marvin-IdeaPad-3-15ITL6 kernel: [  123.053705] R13: 0000000000000003 R14: 0000000000020000 R15: 0000000000020000
Nov  8 14:37:24 marvin-IdeaPad-3-15ITL6 kernel: [  123.053710] </TASK>
Nov  8 14:37:24 marvin-IdeaPad-3-15ITL6 kernel: [  123.087971] audit: type=1400 audit(1667914644.928:82): apparmor="DENIED" operation="capable" profile="/snap/snapd/17336/usr/lib/snapd/snap-confine" pid=3481 comm="snap-confine" capability=4  capname="fsetid"
Nov  8 14:37:25 marvin-IdeaPad-3-15ITL6 kernel: [  123.177707] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 7-... } 6 jiffies s: 685 root: 0x80/.
Nov  8 14:37:25 marvin-IdeaPad-3-15ITL6 kernel: [  123.177725] rcu: blocking rcu_node structures (internal RCU debug):
Nov  8 14:37:25 marvin-IdeaPad-3-15ITL6 kernel: [  123.177728] Task dump for CPU 7:
Nov  8 14:37:25 marvin-IdeaPad-3-15ITL6 kernel: [  123.177731] task:tail            state:R  running task     stack:    0 pid: 3511 ppid:  3032 flags:0x00000008
Nov  8 14:37:25 marvin-IdeaPad-3-15ITL6 kernel: [  123.177739] Call Trace:
Nov  8 14:37:25 marvin-IdeaPad-3-15ITL6 kernel: [  123.177742] <TASK>
--
Nov  8 14:37:25 marvin-IdeaPad-3-15ITL6 kernel: [  123.177786] R10: 0000000000000077 R11: 0000000000000246 R12: 0000000000000000
Nov  8 14:37:25 marvin-IdeaPad-3-15ITL6 kernel: [  123.177788] R13: 0000000000000003 R14: 0000559256e46160 R15: 0000000000000003
Nov  8 14:37:25 marvin-IdeaPad-3-15ITL6 kernel: [  123.177793] </TASK>
Nov  8 14:37:25 marvin-IdeaPad-3-15ITL6 kernel: [  123.253637] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 7-... } 25 jiffies s: 685 root: 0x80/.
Nov  8 14:37:25 marvin-IdeaPad-3-15ITL6 kernel: [  123.253658] rcu: blocking rcu_node structures (internal RCU debug):
Nov  8 14:37:25 marvin-IdeaPad-3-15ITL6 kernel: [  123.253661] Task dump for CPU 7:
Nov  8 14:37:25 marvin-IdeaPad-3-15ITL6 kernel: [  123.253663] task:tail            state:R  running task     stack:    0 pid: 3511 ppid:  3032 flags:0x00000008
Nov  8 14:37:25 marvin-IdeaPad-3-15ITL6 kernel: [  123.253671] Call Trace:
Nov  8 14:37:25 marvin-IdeaPad-3-15ITL6 kernel: [  123.253674] <TASK>
--
Nov  8 14:38:59 marvin-IdeaPad-3-15ITL6 thermald[6171]: optimized configuration on Linux with open source
Nov  8 14:38:59 marvin-IdeaPad-3-15ITL6 thermald[6171]: You may want to disable thermald on this system if you see issue
Nov  8 14:39:00 marvin-IdeaPad-3-15ITL6 thermald[6171]: terminating on user request ..
Nov  8 14:39:00 marvin-IdeaPad-3-15ITL6 kernel: [  218.806259] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 4-... } 6 jiffies s: 705 root: 0x10/.
Nov  8 14:39:00 marvin-IdeaPad-3-15ITL6 kernel: [  218.806284] rcu: blocking rcu_node structures (internal RCU debug):
Nov  8 14:39:00 marvin-IdeaPad-3-15ITL6 kernel: [  218.806289] Task dump for CPU 4:
Nov  8 14:39:00 marvin-IdeaPad-3-15ITL6 kernel: [  218.806293] task:cat             state:R  running task     stack:    0 pid: 6184 ppid:  3032 flags:0x00000008
Nov  8 14:39:00 marvin-IdeaPad-3-15ITL6 kernel: [  218.806304] Call Trace:
Nov  8 14:39:00 marvin-IdeaPad-3-15ITL6 kernel: [  218.806307] <TASK>
--
Nov  8 14:39:00 marvin-IdeaPad-3-15ITL6 kernel: [  218.806531]  ? asm_exc_page_fault+0x8/0x30
Nov  8 14:39:00 marvin-IdeaPad-3-15ITL6 kernel: [  218.806538]  ? entry_SYSCALL_64_after_hwframe+0x44/0xae
Nov  8 14:39:00 marvin-IdeaPad-3-15ITL6 kernel: [  218.806547] </TASK>

marvin@marvin-IdeaPad-3-15ITL6:~/linux/kernel/memleak$ cat kmemleak-bisect-20221108-1441.log
git bisect start
git bisect good f814957b018c867a2397bdd3c1816de7502d2c7f
# bad: [e1a8fde7203fa8a3e3f35d4f9df47477d23529c1] Merge tag 'for-5.19/io_uring-net-2022-05-22' of git://git.kernel.dk/linux-block
git bisect bad e1a8fde7203fa8a3e3f35d4f9df47477d23529c1
# good: [0184f08e65348f39aa4e8a71927e4538515f4ac0] io_uring: add fully sparse buffer registration
git bisect good 0184f08e65348f39aa4e8a71927e4538515f4ac0
# good: [be05ee54378d451e1d60196921566d6087f3079f] Merge branches 'docs.2022.04.20a', 'fixes.2022.04.20a', 'nocb.2022.04.11b', 'rcu-tasks.2022.04.11b', 'srcu.2022.05.03a', 'torture.2022.04.11b', 'torture-tasks.2022.04.20a' and 'torturescript.2022.04.20a' into HEAD
git bisect good be05ee54378d451e1d60196921566d6087f3079f
# good: [a4c76853609107f0e5e7b51571d966785fe89cb3] Merge branch 'tcp-pass-back-data-left-in-socket-after-receive' of git://git.kernel.org/pub/scm/linux/kernel/git/kuba/linux into for-5.19/io_uring-net
git bisect good a4c76853609107f0e5e7b51571d966785fe89cb3
# bad: [1e57930e9f4083ad5854ab6eadffe790a8167fb4] Merge tag 'rcu.2022.05.19a' of git://git.kernel.org/pub/scm/linux/kernel/git/paulmck/linux-rcu
git bisect bad 1e57930e9f4083ad5854ab6eadffe790a8167fb4
# bad: [ce13389053a347aa9f8ffbfda2238352536e15c9] Merge branch 'exp.2022.05.11a' into HEAD
git bisect bad ce13389053a347aa9f8ffbfda2238352536e15c9
# bad: [9621fbee44df940e2e1b94b0676460a538dffefa] rcu: Move expedited grace period (GP) work to RT kthread_worker
git bisect bad 9621fbee44df940e2e1b94b0676460a538dffefa
# bad: [28b3ae426598e722cf5d5ab9cc7038791b955a56] rcu: Introduce CONFIG_RCU_EXP_CPU_STALL_TIMEOUT
git bisect bad 28b3ae426598e722cf5d5ab9cc7038791b955a56
# first bad commit: [28b3ae426598e722cf5d5ab9cc7038791b955a56] rcu: Introduce CONFIG_RCU_EXP_CPU_STALL_TIMEOUT
marvin@marvin-IdeaPad-3-15ITL6:~/linux/kernel/memleak$

According to the Code of Conduct, I have Cc:-ed Mr. Uladzislau Rezki for he is the principal author of
the troublesome commit and Mr. Catalin Marinas as the listed author in kmemleak source file.

commit 28b3ae426598e722cf5d5ab9cc7038791b955a56 (HEAD, refs/bisect/bad)
Author: Uladzislau Rezki <uladzislau.rezki@xxxxxxxx>
Date:   Wed Feb 16 14:52:09 2022 +0100

    rcu: Introduce CONFIG_RCU_EXP_CPU_STALL_TIMEOUT

    Currently both expedited and regular grace period stall warnings use
    a single timeout value that with units of seconds.  However, recent
    Android use cases problem require a sub-100-millisecond expedited RCU CPU
    stall warning.  Given that expedited RCU grace periods normally complete
    in far less than a single millisecond, especially for small systems,
    this is not unreasonable.

    Therefore introduce the CONFIG_RCU_EXP_CPU_STALL_TIMEOUT kernel
    configuration that defaults to 20 msec on Android and remains the same
    as that of the non-expedited stall warnings otherwise.  It also can be
    changed in run-time via: /sys/.../parameters/rcu_exp_cpu_stall_timeout.

    [ paulmck: Default of zero to use CONFIG_RCU_STALL_TIMEOUT. ]

    Signed-off-by: Uladzislau Rezki <uladzislau.rezki@xxxxxxxx>
    Signed-off-by: Uladzislau Rezki (Sony) <urezki@xxxxxxxxx>
    Signed-off-by: Paul E. McKenney <paulmck@xxxxxxxxxx>

The problem persisted in the latest 6.1.0-rc4 release candidate in mainline Linux stable tree.
The only difference to mainline config is CONFIG_DEBUG_KMEMLEAK=y.

Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405239] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 5-.... } 6 jiffies s: 1037 root: 0x20/.
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405264] rcu: blocking rcu_node structures (internal RCU debug):
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405272] Sending NMI from CPU 1 to CPUs 5:
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405286] NMI backtrace for cpu 5
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405291] CPU: 5 PID: 15254 Comm: tail Not tainted 6.1.0-rc4 #1
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405299] Hardware name: LENOVO 82H8/LNVNB161216, BIOS GGCN34WW 03/08/2022
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405302] RIP: 0010:kmemleak_seq_start+0x41/0x80
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405315] Code: e5 f5 a5 00 4c 63 e0 85 c0 78 40 e8 09 81 db ff 48 8b 05 d2 fe 88 01 4c 8d 60 f8 48 3d b0 63 03 ad 75 17 eb 32 49 8b 44 24 08 <48>
 83 eb 01 4c 8d 60 f8 48 3d b0 63 03 ad 74 1d 48 85 db 7f e6 4c
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405321] RSP: 0018:ffffa7e6242afc28 EFLAGS: 00000206
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405327] RAX: ffff8efb59033b58 RBX: 0000000000035af9 RCX: 0000000000000001
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405331] RDX: ffff8efb6143c000 RSI: ffff8efb41593be0 RDI: ffffffffad036340
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405334] RBP: ffffa7e6242afc38 R08: 0000000000002000 R09: ffff8efb44502f80
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405338] R10: 0000000000020000 R11: 0000000000000000 R12: ffff8efb4a6b4ab0
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405342] R13: ffff8efb6a637900 R14: ffff8efb41593bb8 R15: ffffa7e6242afe28
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405345] FS:  00007f50bf8d4740(0000) GS:ffff8efce8940000(0000) knlGS:0000000000000000
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405350] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405354] CR2: 00005647c9879000 CR3: 000000023b99c004 CR4: 0000000000770ee0
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405358] PKRU: 55555554
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405360] Call Trace:
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405362] <TASK>
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405366] seq_read_iter+0x169/0x420
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405376] seq_read+0xad/0xe0
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405383] full_proxy_read+0x59/0x90
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405394] vfs_read+0xb2/0x2e0
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405403]  ? vfs_read+0xb2/0x2e0
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405409]  ? __schedule+0xeb2/0x1300
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405420] ksys_read+0x61/0xe0
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405428] __x64_sys_read+0x1a/0x20
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405435] do_syscall_64+0x58/0x80
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405442]  ? exit_to_user_mode_prepare+0x32/0x190
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405451]  ? syscall_exit_to_user_mode+0x1b/0x30
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405456]  ? do_syscall_64+0x67/0x80
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405462]  ? do_syscall_64+0x67/0x80
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405468]  ? do_user_addr_fault+0x1eb/0x690
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405475]  ? exit_to_user_mode_prepare+0x32/0x190
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405481]  ? irqentry_exit_to_user_mode+0x9/0x20
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405486]  ? irqentry_exit+0x3b/0x50
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405490]  ? exc_page_fault+0x8e/0x190
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405495] entry_SYSCALL_64_after_hwframe+0x63/0xcd
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405502] RIP: 0033:0x7f50bf714992
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405508] Code: c0 e9 b2 fe ff ff 50 48 8d 3d fa b2 0c 00 e8 c5 1d 02 00 0f 1f 44 00 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 0f 05 <48>
 3d 00 f0 ff ff 77 56 c3 0f 1f 44 00 00 48 83 ec 28 48 89 54 24
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405513] RSP: 002b:00007ffc6487e708 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405518] RAX: ffffffffffffffda RBX: 0000000000002000 RCX: 00007f50bf714992
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405522] RDX: 0000000000002000 RSI: 00005647c9878180 RDI: 0000000000000003
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405525] RBP: 00005647c9878180 R08: 00005647c9876fd1 R09: 00005647c9878180
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405527] R10: 0000000000000077 R11: 0000000000000246 R12: 0000000000000e71
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405530] R13: 0000000000000003 R14: 00005647c9876160 R15: 0000000000000003
Nov  7 11:16:14 marvin-IdeaPad-3-15ITL6 kernel: [ 3935.405538] </TASK>

The reproduction requires stopping and restarting thermald quite a number of times (500+) until
it produces /sys/kernel/debug/kmemleak unreferenced object list.

Torture reading of this file through for a in {1..5000}; do cat kmemleak; tail -40 memleak; grep thermald memleak | wc -l; done
eventually causes spurious non-determinisic expedite stalls everyonce in a while.

Please find the build config attached:

I hope this helps someone.

Have a nice day, and have peace.

Thanks,
Mirsad

--
Mirsad Goran Todorovac
Sistem inženjer
Grafički fakultet | Akademija likovnih umjetnosti
Sveučilište u Zagrebu
--
System engineer
Faculty of Graphic Arts | Academy of Fine Arts
University of Zagreb, Republic of Croatia
The European Union

Attachment: config.lrz
Description: application/lrzip