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

[Sven Schnelle <svens@linux.ibm.com>]

[-- 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 --]