Linux-Trace-Devel Archive on lore.kernel.org
 help / color / Atom feed
* Tracing busy processes/threads freezes/stalls the whole machine
@ 2021-04-22 14:26 Stefan Metzmacher
  2021-04-22 14:55 ` Stefan Metzmacher
                   ` (2 more replies)
  0 siblings, 3 replies; 8+ messages in thread
From: Stefan Metzmacher @ 2021-04-22 14:26 UTC (permalink / raw)
  To: Steven Rostedt, Ingo Molnar; +Cc: linux-trace-devel, io-uring


Hi Steven, hi Ingo,

I recently tried to analyze the performance of Samba using io-uring.

I was using ubuntu 20.04 with the 5.10.0-1023-oem kernel, which is based on v5.10.25, see:
https://kernel.ubuntu.com/git/kernel-ppa/mirror/ubuntu-oem-5.10-focal.git/log/?h=oem-5.10-prep
trace-cmd is at version 2.8.3-4build1.

In order to find the bottleneck I tried to use (trace-cmd is at version 2.8.3-4build1):

  trace-cmd -e all -P ${pid_of_io_uring_worker}

As a result the server was completely dead immediately.

I tried to reproduce this in a virtual machine (inside virtualbox).

I used a modified 'io_uring-cp' that loops forever, see:
https://github.com/metze-samba/liburing/commit/5e98efed053baf03521692e786c1c55690b04d8e

When I run './io_uring-cp-forever link-cp.c file',
I see a 'io_wq_manager' and a 'io_wqe_worker-0' kernel thread,
while './io_uring-cp-forever link-cp.c file' as well as 'io_wqe_worker-0'
consume about 25% cpu each.

When I run 'trace-cmd -e all -P $pid' for 'io_wqe_worker-0' or 'io_wq_manager'
I can reproduce the problem, then I found that the same seems to happen for
also for other kernel threads e.g. '[kworker/1:1-events]', it seems that
it happens for all kernel threads, which are not completely idle.

Which this:

 From 'top':
   1341 root      20   0    2512    576    508 S  33,4   0,1   0:10.39 io_uring-cp-for
   1343 root      20   0       0      0      0 R  29,8   0,0   0:08.43 io_wqe_worker-0
      7 root      20   0       0      0      0 I   0,3   0,0   0:00.31 kworker/0:1-events

   PID 5 is [kworker/0:0-ata_sff]

# trace-cmd record -e all -P 5'
Hit Ctrl^C to stop recording
^CCPU0 data recorded at offset=0x7b8000
    0 bytes in size
CPU1 data recorded at offset=0x7b8000
    69632 bytes in size

# But
# trace-cmd record -e all -P 7
=> machine unresponsive (no blinking cursor on the console anymore)
On the host 'top' shows that the VirtualBoxVM cpu emulator thread 'EMT-1'
uses 100% cpu, so I guess the guest kernel is in something like an endless
recursion loop. Maybe a trace function recursing to itself?

On the same VM I tried a 5.12rc8 kernel and there I can also reproduce the
problem.

I also managed to reproduce the problem without io-uring, just using:

 while true; do cat linux-image-5.12.0-rc8-dbg_5.12.0-rc8-22_amd64.deb > /dev/null; done

in order to keep some kernel threads moving.
This happens with 5.12rc8 and 5.10.0-1023-oem, but I was not able to
reproduce any of this using the 5.8.0-50-generic kernel, see
https://kernel.ubuntu.com/git/ubuntu/ubuntu-focal.git/log/?h=Ubuntu-hwe-5.8-5.8.0-50.56_20.04.1

I was also able to reproduce this with a ubuntu 21.04 vm using
the 5.11.0-14-generic kernel, see:
https://kernel.ubuntu.com/git/ubuntu/ubuntu-hirsute.git/log/?h=Ubuntu-5.11.0-14.15
On this one I only managed to reproduce the problem with
'./io_uring-cp-forever link-cp.c file', but not with
'while true; do cat linux-image-5.12.0-rc8-dbg_5.12.0-rc8-22_amd64.deb > /dev/null; done'


So it seems the problem was introduced after 5.8 and is not really related to
io-uring. And it may not be purely related to kernel threads.

With this on 5.12-rc8 (again):

  └─tmux: server,903
      ├─bash,904
      │   └─io_uring-cp-for,925 link-cp.c file
      │       ├─{iou-mgr-925},926
      │       └─{iou-wrk-925},927
      └─bash,929
          └─pstree,938 -a -t -p

I was able to to trace once:

root@ub1704-166:~# trace-cmd record -e all -P 925
Hit Ctrl^C to stop recording
^CCPU0 data recorded at offset=0x7b8000
    10842112 bytes in size
CPU1 data recorded at offset=0x120f000
    36450304 bytes in size

But the 2nd run reproduced the problem:
root@ub1704-166:~# trace-cmd record -e all -P 925

I was also able to reproduce it with:

while true; do cat linux-image-5.12.0-rc8-dbg_5.12.0-rc8-22_amd64.deb > /dev/null; done
and
pidofcat=$(pidof cat); echo $pidofcat; trace-cmd record -e all -P $pidofcat

So it seems any busy thread (user or kernel) triggers the problem.

Any ideas what has changed after 5.8?

Thanks!
metze

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: Tracing busy processes/threads freezes/stalls the whole machine
  2021-04-22 14:26 Tracing busy processes/threads freezes/stalls the whole machine Stefan Metzmacher
@ 2021-04-22 14:55 ` Stefan Metzmacher
  2021-05-04 12:26 ` Stefan Metzmacher
  2021-05-04 13:24 ` Steven Rostedt
  2 siblings, 0 replies; 8+ messages in thread
From: Stefan Metzmacher @ 2021-04-22 14:55 UTC (permalink / raw)
  To: Jens Axboe; +Cc: linux-trace-devel, io-uring, Steven Rostedt, Ingo Molnar

Hi Jens,

maybe not strictly related, but maybe it is...

> I recently tried to analyze the performance of Samba using io-uring.
> 
> I was using ubuntu 20.04 with the 5.10.0-1023-oem kernel, which is based on v5.10.25, see:
> https://kernel.ubuntu.com/git/kernel-ppa/mirror/ubuntu-oem-5.10-focal.git/log/?h=oem-5.10-prep
> trace-cmd is at version 2.8.3-4build1.
> 
> In order to find the bottleneck I tried to use (trace-cmd is at version 2.8.3-4build1):
> 
>   trace-cmd -e all -P ${pid_of_io_uring_worker}
> 
> As a result the server was completely dead immediately.
> 
> I tried to reproduce this in a virtual machine (inside virtualbox).
> 
> I used a modified 'io_uring-cp' that loops forever, see:
> https://github.com/metze-samba/liburing/commit/5e98efed053baf03521692e786c1c55690b04d8e
> 
> When I run './io_uring-cp-forever link-cp.c file',
> I see a 'io_wq_manager' and a 'io_wqe_worker-0' kernel thread,
> while './io_uring-cp-forever link-cp.c file' as well as 'io_wqe_worker-0'
> consume about 25% cpu each.


While doing the tests with 5.12-rc8, I somehow triggered
a backtrace on the VM console:

it contains:

...
io_issue_seq...
...
io_wq_submit_work
io_worker_handle_work
io_wqe_worker
...
io_worker_handle_work
...

RIP: 0100:trace_event_buffer_reserve+0xe5/0x150

Here's a screenshot of it:https://www.samba.org/~metze/io_issue_sqe_trace_event_buffer_reserve-5.12-rc8-backtrace.png

I don't know what the last action was, that I did before it happened.

metze



^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: Tracing busy processes/threads freezes/stalls the whole machine
  2021-04-22 14:26 Tracing busy processes/threads freezes/stalls the whole machine Stefan Metzmacher
  2021-04-22 14:55 ` Stefan Metzmacher
@ 2021-05-04 12:26 ` Stefan Metzmacher
  2021-05-04 13:24 ` Steven Rostedt
  2 siblings, 0 replies; 8+ messages in thread
From: Stefan Metzmacher @ 2021-05-04 12:26 UTC (permalink / raw)
  To: Steven Rostedt, Ingo Molnar; +Cc: linux-trace-devel, io-uring, linux-kernel

+ linux-kernel

I just retested with 5.12 final:

As long as I give the VM more than one cpu, I can easily reproduce the problem with:

> while true; do cat linux-image-5.12.0-rc8-dbg_5.12.0-rc8-22_amd64.deb > /dev/null; done
> and
> pidofcat=$(pidof cat); echo $pidofcat; trace-cmd record -e all -P $pidofcat

On a single cpu VM it doesn't seem to trigger.

Is anyone else able to reproduce this?

Any ideas how to debug this?

It's really annoying to fear a machine freeze when trying to trace problems
on recent kernels...

Thanks for any possible hint...
metze

Am 22.04.21 um 16:26 schrieb Stefan Metzmacher:
> 
> Hi Steven, hi Ingo,
> 
> I recently tried to analyze the performance of Samba using io-uring.
> 
> I was using ubuntu 20.04 with the 5.10.0-1023-oem kernel, which is based on v5.10.25, see:
> https://kernel.ubuntu.com/git/kernel-ppa/mirror/ubuntu-oem-5.10-focal.git/log/?h=oem-5.10-prep
> trace-cmd is at version 2.8.3-4build1.
> 
> In order to find the bottleneck I tried to use (trace-cmd is at version 2.8.3-4build1):
> 
>   trace-cmd -e all -P ${pid_of_io_uring_worker}
> 
> As a result the server was completely dead immediately.
> 
> I tried to reproduce this in a virtual machine (inside virtualbox).
> 
> I used a modified 'io_uring-cp' that loops forever, see:
> https://github.com/metze-samba/liburing/commit/5e98efed053baf03521692e786c1c55690b04d8e
> 
> When I run './io_uring-cp-forever link-cp.c file',
> I see a 'io_wq_manager' and a 'io_wqe_worker-0' kernel thread,
> while './io_uring-cp-forever link-cp.c file' as well as 'io_wqe_worker-0'
> consume about 25% cpu each.
> 
> When I run 'trace-cmd -e all -P $pid' for 'io_wqe_worker-0' or 'io_wq_manager'
> I can reproduce the problem, then I found that the same seems to happen for
> also for other kernel threads e.g. '[kworker/1:1-events]', it seems that
> it happens for all kernel threads, which are not completely idle.
> 
> Which this:
> 
>  From 'top':
>    1341 root      20   0    2512    576    508 S  33,4   0,1   0:10.39 io_uring-cp-for
>    1343 root      20   0       0      0      0 R  29,8   0,0   0:08.43 io_wqe_worker-0
>       7 root      20   0       0      0      0 I   0,3   0,0   0:00.31 kworker/0:1-events
> 
>    PID 5 is [kworker/0:0-ata_sff]
> 
> # trace-cmd record -e all -P 5'
> Hit Ctrl^C to stop recording
> ^CCPU0 data recorded at offset=0x7b8000
>     0 bytes in size
> CPU1 data recorded at offset=0x7b8000
>     69632 bytes in size
> 
> # But
> # trace-cmd record -e all -P 7
> => machine unresponsive (no blinking cursor on the console anymore)
> On the host 'top' shows that the VirtualBoxVM cpu emulator thread 'EMT-1'
> uses 100% cpu, so I guess the guest kernel is in something like an endless
> recursion loop. Maybe a trace function recursing to itself?
> 
> On the same VM I tried a 5.12rc8 kernel and there I can also reproduce the
> problem.
> 
> I also managed to reproduce the problem without io-uring, just using:
> 
>  while true; do cat linux-image-5.12.0-rc8-dbg_5.12.0-rc8-22_amd64.deb > /dev/null; done
> 
> in order to keep some kernel threads moving.
> This happens with 5.12rc8 and 5.10.0-1023-oem, but I was not able to
> reproduce any of this using the 5.8.0-50-generic kernel, see
> https://kernel.ubuntu.com/git/ubuntu/ubuntu-focal.git/log/?h=Ubuntu-hwe-5.8-5.8.0-50.56_20.04.1
> 
> I was also able to reproduce this with a ubuntu 21.04 vm using
> the 5.11.0-14-generic kernel, see:
> https://kernel.ubuntu.com/git/ubuntu/ubuntu-hirsute.git/log/?h=Ubuntu-5.11.0-14.15
> On this one I only managed to reproduce the problem with
> './io_uring-cp-forever link-cp.c file', but not with
> 'while true; do cat linux-image-5.12.0-rc8-dbg_5.12.0-rc8-22_amd64.deb > /dev/null; done'
> 
> 
> So it seems the problem was introduced after 5.8 and is not really related to
> io-uring. And it may not be purely related to kernel threads.
> 
> With this on 5.12-rc8 (again):
> 
>   └─tmux: server,903
>       ├─bash,904
>       │   └─io_uring-cp-for,925 link-cp.c file
>       │       ├─{iou-mgr-925},926
>       │       └─{iou-wrk-925},927
>       └─bash,929
>           └─pstree,938 -a -t -p
> 
> I was able to to trace once:
> 
> root@ub1704-166:~# trace-cmd record -e all -P 925
> Hit Ctrl^C to stop recording
> ^CCPU0 data recorded at offset=0x7b8000
>     10842112 bytes in size
> CPU1 data recorded at offset=0x120f000
>     36450304 bytes in size
> 
> But the 2nd run reproduced the problem:
> root@ub1704-166:~# trace-cmd record -e all -P 925
> 
> I was also able to reproduce it with:
> 
> while true; do cat linux-image-5.12.0-rc8-dbg_5.12.0-rc8-22_amd64.deb > /dev/null; done
> and
> pidofcat=$(pidof cat); echo $pidofcat; trace-cmd record -e all -P $pidofcat
> 
> So it seems any busy thread (user or kernel) triggers the problem.
> 
> Any ideas what has changed after 5.8?
> 
> Thanks!
> metze
> 


^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: Tracing busy processes/threads freezes/stalls the whole machine
  2021-04-22 14:26 Tracing busy processes/threads freezes/stalls the whole machine Stefan Metzmacher
  2021-04-22 14:55 ` Stefan Metzmacher
  2021-05-04 12:26 ` Stefan Metzmacher
@ 2021-05-04 13:24 ` Steven Rostedt
  2021-05-04 13:28   ` Stefan Metzmacher
  2 siblings, 1 reply; 8+ messages in thread
From: Steven Rostedt @ 2021-05-04 13:24 UTC (permalink / raw)
  To: Stefan Metzmacher; +Cc: Ingo Molnar, linux-trace-devel, io-uring

On Thu, 22 Apr 2021 16:26:57 +0200
Stefan Metzmacher <metze@samba.org> wrote:

> Hi Steven, hi Ingo,
> 

Sorry, somehow I missed this.

> # But
> # trace-cmd record -e all -P 7

I'm curious. 

What is the clock set to? What does:

 # trace-cmd list -C

show?

-- Steve

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: Tracing busy processes/threads freezes/stalls the whole machine
  2021-05-04 13:24 ` Steven Rostedt
@ 2021-05-04 13:28   ` Stefan Metzmacher
  2021-05-04 13:32     ` Steven Rostedt
  2021-05-04 13:35     ` Steven Rostedt
  0 siblings, 2 replies; 8+ messages in thread
From: Stefan Metzmacher @ 2021-05-04 13:28 UTC (permalink / raw)
  To: Steven Rostedt; +Cc: Ingo Molnar, linux-trace-devel, io-uring


Am 04.05.21 um 15:24 schrieb Steven Rostedt:
> On Thu, 22 Apr 2021 16:26:57 +0200
> Stefan Metzmacher <metze@samba.org> wrote:
> 
>> Hi Steven, hi Ingo,
>>
> 
> Sorry, somehow I missed this.
> 
>> # But
>> # trace-cmd record -e all -P 7
> 
> I'm curious. 
> 
> What is the clock set to? What does:
> 
>  # trace-cmd list -C
> 
> show?

On both machine (physical and VM):
trace-cmd list -C
[local] global counter uptime perf mono mono_raw boot x86-tsc

Thanks for looking at it!
metze

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: Tracing busy processes/threads freezes/stalls the whole machine
  2021-05-04 13:28   ` Stefan Metzmacher
@ 2021-05-04 13:32     ` Steven Rostedt
  2021-05-04 13:35     ` Steven Rostedt
  1 sibling, 0 replies; 8+ messages in thread
From: Steven Rostedt @ 2021-05-04 13:32 UTC (permalink / raw)
  To: Stefan Metzmacher; +Cc: Ingo Molnar, linux-trace-devel, io-uring

On Tue, 4 May 2021 15:28:12 +0200
Stefan Metzmacher <metze@samba.org> wrote:

> Am 04.05.21 um 15:24 schrieb Steven Rostedt:
> > On Thu, 22 Apr 2021 16:26:57 +0200
> > Stefan Metzmacher <metze@samba.org> wrote:
> >   
> >> Hi Steven, hi Ingo,
> >>  
> > 
> > Sorry, somehow I missed this.
> >   
> >> # But
> >> # trace-cmd record -e all -P 7  
> > 
> > I'm curious. 
> > 
> > What is the clock set to? What does:
> > 
> >  # trace-cmd list -C
> > 
> > show?  
> 
> On both machine (physical and VM):
> trace-cmd list -C
> [local] global counter uptime perf mono mono_raw boot x86-tsc
> 
> Thanks for looking at it!

Bah, I was hoping it would show "[global]" as we just discovered a bug
because the global clock took a spin lock and a recent change allowed it to
recurse once (causing a deadlock if it happened). But the "[local]" clock
has no such issue. Which means I need to do a bit more digging into this
cause :-(

-- Steve


^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: Tracing busy processes/threads freezes/stalls the whole machine
  2021-05-04 13:28   ` Stefan Metzmacher
  2021-05-04 13:32     ` Steven Rostedt
@ 2021-05-04 13:35     ` Steven Rostedt
  2021-05-05  9:50       ` Stefan Metzmacher
  1 sibling, 1 reply; 8+ messages in thread
From: Steven Rostedt @ 2021-05-04 13:35 UTC (permalink / raw)
  To: Stefan Metzmacher; +Cc: Ingo Molnar, linux-trace-devel, io-uring

On Tue, 4 May 2021 15:28:12 +0200
Stefan Metzmacher <metze@samba.org> wrote:

> Am 04.05.21 um 15:24 schrieb Steven Rostedt:
> > On Thu, 22 Apr 2021 16:26:57 +0200
> > Stefan Metzmacher <metze@samba.org> wrote:
> >   
> >> Hi Steven, hi Ingo,
> >>  
> > 
> > Sorry, somehow I missed this.
> >   
> >> # But
> >> # trace-cmd record -e all -P 7  

Perhaps you could try something like this:

 # trace-cmd list -s |
    while read e ; do
      echo "testing $e";
      trace-cmd record -P 7 -e $e sleep 1;
    done

Which will enable each system at a time, and see if we can pin point what
is causing the lock up. Narrow it down to a tracing system.

-- Steve

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: Tracing busy processes/threads freezes/stalls the whole machine
  2021-05-04 13:35     ` Steven Rostedt
@ 2021-05-05  9:50       ` Stefan Metzmacher
  0 siblings, 0 replies; 8+ messages in thread
From: Stefan Metzmacher @ 2021-05-05  9:50 UTC (permalink / raw)
  To: Steven Rostedt; +Cc: Ingo Molnar, linux-trace-devel, io-uring


Am 04.05.21 um 15:35 schrieb Steven Rostedt:
> On Tue, 4 May 2021 15:28:12 +0200
> Stefan Metzmacher <metze@samba.org> wrote:
> 
>> Am 04.05.21 um 15:24 schrieb Steven Rostedt:
>>> On Thu, 22 Apr 2021 16:26:57 +0200
>>> Stefan Metzmacher <metze@samba.org> wrote:
>>>   
>>>> Hi Steven, hi Ingo,
>>>>  
>>>
>>> Sorry, somehow I missed this.
>>>   
>>>> # But
>>>> # trace-cmd record -e all -P 7  
> 
> Perhaps you could try something like this:
> 
>  # trace-cmd list -s |
>     while read e ; do
>       echo "testing $e";
>       trace-cmd record -P 7 -e $e sleep 1;
>     done
> 
> Which will enable each system at a time, and see if we can pin point what
> is causing the lock up. Narrow it down to a tracing system.

I wasn't able to reproduce it.

With a 5.12 kernel and ubuntu 20.04 amd64 userspace I was able
to produce the following strace output (in the 2nd try), like this:

# ssh root@172.31.9.166 strace -f -ttT trace-cmd record -e all -P 101 2>&1 | tee out

101 is the pid of a kthread while my './io-uring_cp-forever link-cp.c file' runs
on '172.31.9.166'. See https://github.com/metze-samba/liburing/commits/io_uring-cp-forever
pid 1375 is the pid of 'iou-wrk-1373'.

Maybe it's related to writing the pid into /sys/kernel/tracing/set_event_pid
as it ends like this:
> 10:56:07.493869 stat("/sys/kernel/tracing/set_event_pid", {st_mode=S_IFREG|0644, st_size=0, ...}) = 0 <0.000222>
> 10:56:07.494500 openat(AT_FDCWD, "/sys/kernel/tracing/set_event_pid", O_RDONLY) = 3 <0.000134>
> 10:56:07.494934 read(3, "1375\n", 8192) = 5 <0.000433>
> 10:56:07.495708 close(3)                = 0 <0.000121>
...> [pid  1443] 10:56:10.045293 openat(AT_FDCWD, "/sys/kernel/tracing/set_ftrace_pid", O_WRONLY|O_TRUNC|O_CLOEXEC <unfinished ...>
> [pid  1444] 10:56:10.045650 <... read resumed>"sysfs /sys sysfs rw,nosuid,nodev"..., 1024) = 1024 <0.000948>
> [pid  1443] 10:56:10.045821 <... openat resumed>) = 5 <0.000359>
> [pid  1445] 10:56:10.046000 <... fstat resumed>{st_mode=S_IFREG|0444, st_size=0, ...}) = 0 <0.000873>
> [pid  1443] 10:56:10.046174 write(5, "101 ", 4 <unfinished ...>
> [pid  1444] 10:56:10.046674 read(5,  <unfinished ...>
> [pid  1443] 10:56:10.047007 <... write resumed>) = 4 <0.000475>
> [pid  1445] 10:56:10.047188 read(5,  <unfinished ...>
> [pid  1443] 10:56:10.047498 write(5, " ", 1 <unfinished ...>
> [pid  1444] 10:56:10.048343 <... read resumed>"_cls,net_prio cgroup rw,nosuid,n"..., 1024) = 1024 <0.001312>
> [pid  1445] 10:56:10.048578 <... read resumed>"sysfs /sys sysfs rw,nosuid,nodev"..., 1024) = 1024 <0.001224>
> [pid  1444] 10:56:10.048796 read(5,  <unfinished ...>
> [pid  1445] 10:56:10.049195 read(5,  <unfinished ...>
> [pid  1444] 10:56:10.049547 <... read resumed>"ges hugetlbfs rw,relatime,pagesi"..., 1024) = 690 <0.000403>
> [pid  1445] 10:56:10.049722 <... read resumed>"_cls,net_prio cgroup rw,nosuid,n"..., 1024) = 1024 <0.000339>
> [pid  1444] 10:56:10.049924 close(5 <unfinished ...>
> [pid  1445] 10:56:10.050224 read(5,  <unfinished ...>
> [pid  1444] 10:56:10.050550 <... close resumed>) = 0 <0.000323>
> [pid  1445] 10:56:10.050714 <... read resumed>"ges hugetlbfs rw,relatime,pagesi"..., 1024) = 690 <0.000327>
> [pid  1444] 10:56:10.050883 openat(AT_FDCWD, "trace.dat.cpu0", O_WRONLY|O_CREAT|O_TRUNC, 0644 <unfinished ...>
> [pid  1445] 10:56:10.051299 close(5)    = 0 <0.016204>
> [pid  1445] 10:56:10.067841 openat(AT_FDCWD, "trace.dat.cpu1", O_WRONLY|O_CREAT|O_TRUNC, 0644 <unfinished ...>
> [pid  1443] 10:56:10.100729 <... write resumed>) = 0 <0.052057>
> [pid  1443] 10:56:10.101022 openat(AT_FDCWD, "/sys/kernel/tracing/set_event_pid", O_WRONLY|O_TRUNC|O_CLOEXEC) = 6 <0.014801>
> [pid  1443] 10:56:10.116299 write(6, "101 ", 4

The full output can be found here:
https://www.samba.org/~metze/strace.5.12-trace-cmd-record-all-P-101-kthread-fail-01.txt

I redid it on ubuntu 21.04 with this kernel:
https://kernel.ubuntu.com/git/ubuntu/ubuntu-hirsute.git/tag/?h=Ubuntu-5.11.0-16.17
which is based on Linux 5.11.12

I tried it onces using of pid from a kthread and it didn't reproduce:
> 09:10:50.719423 openat(AT_FDCWD, "/sys/kernel/tracing/set_event_pid", O_RDONLY) = 3 <0.000084>
> 09:10:50.719605 read(3, "", 8192)       = 0 <0.000075>
> 09:10:50.719774 close(3)                = 0 <0.000080>
...
> [pid  1135] 09:10:53.468541 fcntl(6, F_GETPIPE_SZ) = 65536 <0.000009>
> [pid  1135] 09:10:53.468589 splice(5, NULL, 7, NULL, 4096, SPLICE_F_MOVE <unfinished ...>
> [pid  1134] 09:10:53.480165 <... write resumed>) = 0 <0.014106>
> [pid  1134] 09:10:53.480201 close(4)    = 0 <0.000011>
> [pid  1134] 09:10:53.480250 openat(AT_FDCWD, "/sys/kernel/tracing/set_event_pid", O_WRONLY|O_TRUNC|O_CLOEXEC) = 4 <0.000024>
> [pid  1134] 09:10:53.480311 write(4, "7 ", 2) = 2 <0.000194>
> [pid  1134] 09:10:53.480530 close(4)    = 0 <0.000011>
> [pid  1134] 09:10:53.480565 openat(AT_FDCWD, "/sys/kernel/tracing/tracing_enabled", O_WRONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000013>
> [pid  1134] 09:10:53.480605 write(3, "1", 1) = 1 <0.000008>
> [pid  1134] 09:10:53.480632 newfstatat(1, "", {st_mode=S_IFIFO|0600, st_size=0, ...}, AT_EMPTY_PATH) = 0 <0.000007>
> [pid  1134] 09:10:53.480673 pidfd_open(7, 0) = 4 <0.000010>
> [pid  1134] 09:10:53.480701 poll([{fd=4, events=POLLIN}], 1, -1

The full output can be found here:
https://www.samba.org/~metze/strace.5.11.12-trace-cmd-record-all-P-7-kthread-nofail-02.txt

And using the pid of io_wqe_worker-0 it happened again,
also writing the pid into /sys/kernel/tracing/set_event_pid:
(remember 7 was the pid of the kthread):
> 09:13:18.000315 openat(AT_FDCWD, "/sys/kernel/tracing/set_event_pid", O_RDONLY) = 3 <0.000074>
> 09:13:18.000471 read(3, "7\n", 8192)    = 2 <0.000158>
> 09:13:18.000703 close(3)                = 0 <0.000052>
...> [pid  1224] 09:13:20.671939 close(4)    = 0 <0.000084>
> [pid  1224] 09:13:20.672106 openat(AT_FDCWD, "trace.dat.cpu0", O_WRONLY|O_CREAT|O_TRUNC, 0644) = 4 <0.000085>
> [pid  1224] 09:13:20.672292 openat(AT_FDCWD, "/sys/kernel/tracing/per_cpu/cpu0/trace_pipe_raw", O_RDONLY) = 5 <0.000062>
> [pid  1224] 09:13:20.672432 pipe([6, 7]) = 0 <0.000057>
> [pid  1224] 09:13:20.672595 fcntl(6, F_GETPIPE_SZ) = 65536 <0.000051>
> [pid  1224] 09:13:20.672728 splice(5, NULL, 7, NULL, 4096, SPLICE_F_MOVE <unfinished ...>
> [pid  1223] 09:13:20.688172 <... write resumed>) = 0 <0.020134>
> [pid  1223] 09:13:20.688215 close(4)    = 0 <0.000015>
> [pid  1223] 09:13:20.688276 openat(AT_FDCWD, "/sys/kernel/tracing/set_event_pid", O_WRONLY|O_TRUNC|O_CLOEXEC) = 4 <0.027854>
> [pid  1223] 09:13:20.716198 write(4, "1043 ", 5

The full output can be found here:
https://www.samba.org/~metze/strace.5.11.12-trace-cmd-record-all-P-1043-io_wqe_worker-fail-03.txt

I thought it happens always if there was already a value in /sys/kernel/tracing/set_event_pid...,
but the next time I started with pid 6 from a kthread and directly triggered it:

> 09:41:24.029860 openat(AT_FDCWD, "/sys/kernel/tracing/set_event_pid", O_RDONLY) = 3 <0.000048>
> 09:41:24.029982 read(3, "", 8192)       = 0 <0.000046>
> 09:41:24.030101 close(3)                = 0 <0.000045>
...
> [pid  1425] 09:41:26.212972 read(4, "sysfs /sys sysfs rw,nosuid,nodev"..., 1024) = 1024 <0.000077>
> [pid  1425] 09:41:26.213128 read(4, "group/rdma cgroup rw,nosuid,node"..., 1024) = 1024 <0.000075>
> [pid  1425] 09:41:26.213316 read(4, "ev/hugepages hugetlbfs rw,relati"..., 1024) = 1024 <0.000058>
> [pid  1425] 09:41:26.213459 close(4)    = 0 <0.000044>
> [pid  1425] 09:41:26.213584 openat(AT_FDCWD, "trace.dat.cpu0", O_WRONLY|O_CREAT|O_TRUNC, 0644) = 4 <0.000229>
> [pid  1425] 09:41:26.213895 openat(AT_FDCWD, "/sys/kernel/tracing/per_cpu/cpu0/trace_pipe_raw", O_RDONLY) = 5 <0.000055>
> [pid  1425] 09:41:26.214030 pipe([6, 7]) = 0 <0.000066>
> [pid  1425] 09:41:26.214188 fcntl(6, F_GETPIPE_SZ) = 65536 <0.000065>
> [pid  1425] 09:41:26.214332 splice(5, NULL, 7, NULL, 4096, SPLICE_F_MOVE

It ended here, but I think the rest ( close(4); openat("/sys/kernel/tracing/set_event_pid"); write("6 ")
was just eaten by the delayed output of the ssh session.

The full output can be found here:
https://www.samba.org/~metze/strace.5.11.12-trace-cmd-record-all-P-6-kthread-fail-04.txt

Does these details help already?

Thanks!
metze

^ permalink raw reply	[flat|nested] 8+ messages in thread

end of thread, back to index

Thread overview: 8+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-04-22 14:26 Tracing busy processes/threads freezes/stalls the whole machine Stefan Metzmacher
2021-04-22 14:55 ` Stefan Metzmacher
2021-05-04 12:26 ` Stefan Metzmacher
2021-05-04 13:24 ` Steven Rostedt
2021-05-04 13:28   ` Stefan Metzmacher
2021-05-04 13:32     ` Steven Rostedt
2021-05-04 13:35     ` Steven Rostedt
2021-05-05  9:50       ` Stefan Metzmacher

Linux-Trace-Devel Archive on lore.kernel.org

Archives are clonable:
	git clone --mirror https://lore.kernel.org/linux-trace-devel/0 linux-trace-devel/git/0.git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V2 linux-trace-devel linux-trace-devel/ https://lore.kernel.org/linux-trace-devel \
		linux-trace-devel@vger.kernel.org
	public-inbox-index linux-trace-devel

Example config snippet for mirrors

Newsgroup available over NNTP:
	nntp://nntp.lore.kernel.org/org.kernel.vger.linux-trace-devel


AGPL code for this site: git clone https://public-inbox.org/public-inbox.git