Hi, Steven Rostedt <rostedt@xxxxxxxxxxx> writes: > On Tue, 21 Jun 2022 17:15:47 +0200 > Alexander Gordeev <agordeev@xxxxxxxxxxxxx> wrote: > >> So I assume (checked actually) the return 0 below from kernel/sched/core.c: >> wait_task_inactive() is where it bails out: >> >> 3303 while (task_running(rq, p)) { >> 3304 if (match_state && unlikely(READ_ONCE(p->__state) != match_state)) >> 3305 return 0; >> 3306 cpu_relax(); >> 3307 } >> >> Yet, the child task is always found in __TASK_TRACED state (as seen >> in crash dumps): >> >> > 101447 11342 13 ce3a8100 RU 0.0 10040 4412 strace >> 101450 101447 0 bb04b200 TR 0.0 2272 1136 kill_child >> 108261 101447 2 d0b10100 TR 0.0 2272 532 kill_child >> crash> task bb04b200 __state >> PID: 101450 TASK: bb04b200 CPU: 0 COMMAND: "kill_child" >> __state = 8, >> >> crash> task d0b10100 __state >> PID: 108261 TASK: d0b10100 CPU: 2 COMMAND: "kill_child" >> __state = 8, > > If you are using crash, can you enable all trace events? > > Then you should be able to extract the ftrace ring buffer from crash using > the trace.so extend (https://github.com/fujitsu/crash-trace) > > I guess it should still work with s390. > > Then you can see the events that lead up to the crash. Alexander is busy with other stuff, so I took over. I enabled the sys,signal,sched and task tracepoints and ftrace_dump_on_oops. The last lines from the trace buffer are: [ 281.043459] strace-1177215 0d.... 269457070us : sched_waking: comm=kill_child pid=1178157 prio=120 target_cpu=003 [ 281.043463] kill_chi-1177218 1d.... 269457070us : signal_generate: sig=17 errno=0 code=4 comm=strace pid=1177215 grp=1 res=1 [ 281.043467] kill_chi-1177218 1d.... 269457070us : sched_stat_runtime: comm=kill_child pid=1177218 runtime=5299 [ns] vruntime=1830714210855 [ns] [ 281.043471] kill_chi-1177218 1d.... 269457071us : sched_switch: prev_comm=kill_child prev_pid=1177218 prev_prio=120 prev_state=t ==> next_comm=swapper/1 next_pid=0 next_prio=120 [ 281.043475] strace-1177215 0..... 269457071us : sys_ptrace -> 0x50 [ 281.043478] strace-1177215 0..... 269457071us : sys_write(fd: 2, buf: 2aa15db3ad0, count: 12) [ 281.043482] strace-1177215 0..... 269457072us : sys_write -> 0x12 [ 281.043485] <idle>-0 3dNh.. 269457072us : sched_wakeup: comm=kill_child pid=1178157 prio=120 target_cpu=003 [ 281.043489] <idle>-0 3d.... 269457073us : sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kill_child next_pid=1178157 next_prio=120 [ 281.043493] strace-1177215 0..... 269457073us : sys_write(fd: 2, buf: 2aa15db3ad0, count: 1a) [ 281.043496] strace-1177215 0..... 269457073us : sys_write -> 0x1a [ 281.043500] kill_chi-1178157 3..... 269457073us : sys_sched_yield -> 0xffffffffffffffda [ 281.043504] strace-1177215 0..... 269457073us : sys_ptrace(request: 18, pid: 11fa2d, addr: 0, data: 0) [ 281.043508] kill_chi-1178157 3d.... 269457073us : signal_deliver: sig=9 errno=0 code=0 sa_handler=0 sa_flags=0 [ 281.043511] kill_chi-1178157 3d.... 269457074us : signal_generate: sig=17 errno=0 code=4 comm=strace pid=1177215 grp=1 res=1 [ 281.043515] kill_chi-1178157 3d.... 269457074us : sched_stat_runtime: comm=kill_child pid=1178157 runtime=2408 [ns] vruntime=1983050055579 [ns] [ 281.043519] kill_chi-1178157 3d.... 269457075us : sched_switch: prev_comm=kill_child prev_pid=1178157 prev_prio=120 prev_state=t ==> next_comm=swapper/3 next_pid=0 next_prio=120 I attached the full output to this mail. I haven't yet tried to understand the problem, i just wanted to send you the requested information in the hope that it will help you. Regards Sven
Attachment:
dmesg.xz
Description: application/xz