lkml.org 
[lkml]   [2021]   [Jan]   [28]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
From
SubjectRe: [printk] b031a684bf: INFO:rcu_tasks_detected_stalls_on_tasks
Date
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

\
 
 \ /
  Last update: 2021-01-28 22:41    [W:0.185 / U:0.160 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site