Re: [PATCH v4 12/12] sched,signal,ptrace: Rework TASK_TRACED, TASK_STOPPED state

Sven Schnelle
2022-07-05T13:47:44Z

[-- Attachment #1: Type: text/plain, Size: 3889 bytes --]

Hi,

Steven Rostedt <rostedt@goodmis.org> writes:

> On Tue, 21 Jun 2022 17:15:47 +0200
> Alexander Gordeev <agordeev@linux.ibm.com> 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 #2: dmesg.xz --]
[-- Type: application/x-xz, Size: 29004 bytes --]