Re: [printk] b031a684bf: INFO:rcu_tasks_detected_stalls_on_tasks

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

On 2021-01-28, John Ogness <john.ogness@linutronix.de> wrote:
> [  903.189448][  T356] [  778.825864] [  655.250559] [  531.607066] [  407.120936] tasks-torture:torture_onoff task: online 0 failed: errno -5

So I at least found out what these multi-timestamp messages are (thanks
to reading /dev/kmsg). lkp is directing all its test output to
/dev/kmsg. This is why we see messages like:

  2021-01-28 21:15:15 rmmod rcutorture

The final line of its test is "dmesg | grep torture:". So it is dumping
dmesg output into /dev/kmsg! This causes the timestamp to be included in
the text of the new messages so we later see 2 timestamps. After 2
minutes it has reached the messages it fed into /dev/kmsg and feeds them
in again (thus a 3rd timestamp).

Here is a snippet from /dev/kmsg when it starts feeding dmesg into
/dev/kmsg. If the first number is >= 8, it is coming from userspace.

1,24066,323390711,-;tasks-torture:torture_onoff task: online 0 failed: errno -5
1,24067,323444452,-;tasks-torture:torture_onoff task: online 0 failed: errno -5
1,24068,323461363,-;tasks-torture:torture_onoff task: online 0 failed: errno -5
13,24069,323469754,-;2021-01-28 21:15:15 rmmod rcutorture
12,24070,323469775,-;
1,24071,323481652,-;tasks-torture:torture_onoff task: online 0 failed: errno -5
1,24072,323495879,-;tasks-torture:torture_onoff task: online 0 failed: errno -5
1,24073,323503276,-;tasks-torture:torture_onoff task: online 0 failed: errno -5
1,24074,323510766,-;tasks-torture:torture_onoff task: online 0 failed: errno -5
1,24075,323519658,-;tasks-torture:torture_onoff task: online 0 failed: errno -5
13,24076,323522146,-;[  158.513122] tasks-torture:torture_onoff task: online 0 failed: errno -5
12,24077,323522157,-;
13,24078,323526545,-;[  158.519672] tasks-torture:torture_onoff task: online 0 failed: errno -5
12,24079,323526556,-;
13,24080,323529365,-;[  158.534695] tasks-torture:torture_onoff task: online 0 failed: errno -5
12,24081,323529374,-;
13,24082,323531951,-;[  158.549755] tasks-torture:torture_onoff task: online 0 failed: errno -5
12,24083,323531961,-;

I don't know why it is doing the message text with loglevel 5 (NOTICE)
followed by a blank line with loglevel 4 (WARNING), but they are
definitely coming from userspace.

Anyway, enough with that madness. I now will return my focus to the rcu
stall, and see how printk could be responsible.

John Ogness