Re: [printk] b031a684bf: INFO:rcu_tasks_detected_stalls_on_tasks

[John Ogness <john.ogness@linutronix.de>]

On 2021-01-28, Petr Mladek <pmladek@suse.com> wrote:
> If you are able to reproduce this, it might be interesting to see
> backtraces from all CPUs when RCU stall gets detected. Or even
> printing all processes, even the sleeping ones.

OK, I now have lkp running on my intel core i5 machine and it reliably
reproduces this. First let me say a word about lkp. The instructions in
the report email are a bit misleading. There are lots of steps that it
doesn't mention.

First I needed to install lkp and its dependencies. I did all of this as
root because lkp seems to get confused when sudo is involved.

# git clone https://github.com/intel/lkp-tests.git
# cd lkp-tests
# make install
# lkp install

Then I built the kernel and modules using a helper script to setup the
environment for me:

----- BEGIN /tmp/mk.sh -----
#!/bin/sh

export INSTALL_MOD_PATH=`pwd`
export HOSTCC=gcc-9
export CC=gcc-9
export ARCH=x86_64

exec make "$@"
----- END /tmp/mk.sh -----

# cd linux
# git checkout -b lkp b031a684bfd01d633c79d281bd0cf11c2f834ada
# cp /tmp/config-5.10.0-rc5-gb031a684bfd0 .config
# /tmp/mk.sh -j `nproc` olddefconfig prepare modules_prepare bzImage modules modules_install

Then I created the modules.cgz:

# find lib/modules | cpio -H newc -o | gzip -9c > modules.cgz

I put kernel and modules in /tmp/:

# cp arch/x86/boot/bzImage modules.cgz /tmp/

And ran lkp inside script(1) so I have a logfile:

# script
# lkp qemu -k /tmp/bzImage -m /tmp/modules.cgz /tmp/job-script

And reliably I see the first stall at about 925 seconds:

[  926.386441][   T22] INFO: rcu_tasks detected stalls on tasks:
[  926.387310][   T22] 0000000041eb5240: .. nvcsw: 0/0 holdout: 1 idle_cpu: -1/1
[  926.388196][   T22] task:dmesg           state:R  running task     stack:    0 pid: 1752 ppid:   511 flags:0x2002000
0
[  926.389509][   T22] Call Trace:
[  926.389962][   T22]  __schedule+0xa12/0xab5
[  926.390534][   T22]  ? firmware_map_remove+0xd1/0xd1
[  926.391190][   T22]  ? ksys_read+0x116/0x150
[  926.391773][   T22]  schedule+0x16c/0x1df
[  926.392317][   T22]  exit_to_user_mode_loop+0x28/0x84
[  926.392977][   T22]  exit_to_user_mode_prepare+0x1d/0x4a
[  926.393671][   T22]  syscall_exit_to_user_mode+0x41/0x4f
[  926.394357][   T22]  entry_INT80_compat+0x71/0x76
[  926.394982][   T22] RIP: 0023:0xf7f0fa02
[  926.395528][   T22] RSP: 002b:00000000ff850364 EFLAGS: 00000246 ORIG_RAX: 0000000000000003
[  926.396590][   T22] RAX: ffffffffffffffe0 RBX: 0000000000000004 RCX: 00000000565c8234
[  926.397607][   T22] RDX: 0000000000001fff RSI: 00000000000001e0 RDI: 00000000565c8234
[  926.398617][   T22] RBP: 00000000ffffffff R08: 0000000000000000 R09: 0000000000000000
[  926.399629][   T22] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[  926.400643][   T22] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000

But actually it is not the rcu stall that interests me so much. I am
more interested in some bizarre console output I am seeing. Here is a
snippet:

[  903.008486][  T356] [  778.732883] tasks-torture:torture_onoff task: online 0 failed: errno -5
[  903.008496][  T356]
[  903.014733][  T528] tasks-torture:torture_onoff task: online 0 failed: errno -5
[  903.030232][  T356] [  778.735197] [  655.203106] tasks-torture:torture_onoff task: online 0 failed: errno -5
[  903.030242][  T356]
[  903.040809][  T528] tasks-torture:torture_onoff task: online 0 failed: errno -5
[  903.044327][  T356] [  778.746898] [  655.214214] [  531.584847] tasks-torture:torture_onoff task: online 0 failed: errno -5
[  903.044337][  T356]
[  903.048732][  T528] tasks-torture:torture_onoff task: online 0 failed: errno -5
[  903.066039][  T356] [  778.751162] tasks-torture:torture_onoff task: online 0 failed: errno -5
[  903.066050][  T356]
[  903.070123][  T528] tasks-torture:torture_onoff task: online 0 failed: errno -5
[  903.077137][  T356] [  778.768744] [  655.227204] tasks-torture:torture_onoff task: online 0 failed: errno -5
[  903.077147][  T356]
[  903.092792][  T528] tasks-torture:torture_onoff task: online 0 failed: errno -5
[  903.095313][  T356] [  778.773836] tasks-torture:torture_onoff task: online 0 failed: errno -5
[  903.095323][  T356]
[  903.106788][  T356] [  778.781780] tasks-torture:torture_onoff task: online 0 failed: errno -5
[  903.106798][  T356]
[  903.121986][  T356] [  778.791183] [  655.230287] [  531.589973] [  407.116952] [  283.068815] tasks-torture:torture_onoff task: online 0 failed: errno -5
[  903.121997][  T356]
[  903.134120][  T356] [  778.797950] tasks-torture:torture_onoff task: online 0 failed: errno -5
[  903.134130][  T356]
[  903.148741][  T528] tasks-torture:torture_onoff task: online 0 failed: errno -5
[  903.151626][  T356] [  778.805164] [  655.241173] tasks-torture:torture_onoff task: online 0 failed: errno -5
[  903.151637][  T356]
[  903.160126][  T528] tasks-torture:torture_onoff task: online 0 failed: errno -5
[  903.166936][  T356] [  778.818740] tasks-torture:torture_onoff task: online 0 failed: errno -5
[  903.166946][  T356]
[  903.175785][  T528] tasks-torture:torture_onoff task: online 0 failed: errno -5
[  903.185955][  T528] tasks-torture:torture_onoff task: online 0 failed: errno -5
[  903.189448][  T356] [  778.825864] [  655.250559] [  531.607066] [  407.120936] tasks-torture:torture_onoff task: online 0 failed: errno -5

These multi-timestamp lines are odd. And they are almost exactly 124
seconds apart. What is going on there? The investigation continues...

John Ogness