Re: [PATCH 1/2] tracing: Add a trace for task_exit

[<Peter.Enderborg@sony.com>]

On 5/3/21 3:50 PM, Mathieu Desnoyers wrote:
> ----- On May 1, 2021, at 9:11 AM, rostedt rostedt@goodmis.org wrote:
>
>> On Sat, 1 May 2021 09:29:41 +0000
>> <Peter.Enderborg@sony.com> wrote:
>>
>>> On 4/30/21 7:48 PM, Eric W. Biederman wrote:
>>>> Peter Enderborg <peter.enderborg@sony.com> writes:
>>>>  
>>>>> This is the peer functions to task_rename and task_newtask.
>>>>> With this we get hole "life-cycle" of task and can easily
>>>>> see short livied task and their exit status.
>>>> This patch is incorrect.  The location you are dealing with is not part
>>>> of task exit.  The location you have instrumented is part of reaping a
>>>> task which can come arbitrarily long after the task exits.
>>> That is what it aiming. When using this as tool for userspace you
>>> would like to know when the task is done. When it no longer
>>> holds any thing that might have any impact. If you think the
>>> exit imply something more specific I can change the name.
>>>
>>> I thought exit was a good name, it is in in exit.c.
>>>
>>> Will the name task_done, task_finished or task_reaped work for you?
>> I think "task_reaped" is probably the best name, and the most
>> descriptive of what happened.
> What would it provide that is not already available through the "sched_process_free"
> tracepoint in delayed_put_task_struct ?

For task_exit (or task_reaped)

        field:pid_t pid;        offset:8;       size:4; signed:1;
        field:short oom_score_adj;      offset:12;      size:2; signed:1;
        field:int exit_signal;  offset:16;      size:4; signed:1;
        field:int exit_code;    offset:20;      size:4; signed:1;
        field:int exit_state;   offset:24;      size:4; signed:1;
        field:__data_loc char[] comm;   offset:28;      size:4; signed:1;

sched_process_free
        field:char comm[16];    offset:8;       size:16;        signed:1;
        field:pid_t pid;        offset:24;      size:4; signed:1;
        field:int prio; offset:28;      size:4; signed:1;

So information about oom_score_adj, and it's exit parameters.

And it is also gives information on kernel tasks. The task exit also
gives information about it's parent.   sched_process_free is "idle" as parent.

          sshd-7399    [002] d... 262223.258018: task_exit: pid=7400 oom_score_adj=0 exit_signal=17 exit_code=0 exit_state=0x10 comm=ls
            sshd-7395    [007] ..s. 262223.263429: sched_process_free: comm=ps pid=7428 prio=120
          <idle>-0       [005] ..s. 262223.263440: sched_process_free: comm=basename pid=7427 prio=120
            sshd-800     [007] d... 262223.263844: task_exit: pid=7395 oom_score_adj=0 exit_signal=17 exit_code=65280 exit_state=0x10 comm=sshd
         systemd-1       [001] d... 262223.264126: task_exit: pid=7399 oom_score_adj=0 exit_signal=17 exit_code=65280 exit_state=0x10 comm=sshd
          <idle>-0       [002] ..s. 262223.268439: sched_process_free: comm=ls pid=7400 prio=120
          <idle>-0       [007] ..s. 262223.272484: sched_process_free: comm=sshd pid=7395 prio=120
          <idle>-0       [001] ..s. 262223.273446: sched_process_free: comm=sshd pid=7399 prio=120

With the exit_signal you can also see that the process is gone, not only one of the thread that might not be the last.

               t-7734    [006] .... 263946.427704: task_newtask: pid=7736 comm=t clone_flags=3d0f00 oom_score_adj=0
               t-7734    [006] .... 263946.427778: task_newtask: pid=7737 comm=t clone_flags=3d0f00 oom_score_adj=0
               t-7735    [000] .... 263946.428138: task_newtask: pid=7738 comm=t clone_flags=3d0f00 oom_score_adj=0
               t-7736    [001] .... 263946.428387: task_newtask: pid=7739 comm=t clone_flags=3d0f00 oom_score_adj=0
               t-7737    [002] .... 263946.428515: task_newtask: pid=7740 comm=t clone_flags=3d0f00 oom_score_adj=0
           <...>-7740    [002] dN.. 263979.289647: task_exit: pid=7740 oom_score_adj=0 exit_signal=-1 exit_code=15 exit_state=0x10 comm=t
               t-7739    [001] dN.. 263979.289661: task_exit: pid=7739 oom_score_adj=0 exit_signal=-1 exit_code=15 exit_state=0x10 comm=t
               t-7738    [000] dN.. 263979.289682: task_exit: pid=7738 oom_score_adj=0 exit_signal=-1 exit_code=15 exit_state=0x10 comm=t
               t-7737    [002] dN.. 263979.289686: task_exit: pid=7737 oom_score_adj=0 exit_signal=-1 exit_code=15 exit_state=0x10 comm=t
               t-7736    [001] dN.. 263979.289690: task_exit: pid=7736 oom_score_adj=0 exit_signal=-1 exit_code=15 exit_state=0x10 comm=t
               t-7735    [000] dN.. 263979.289702: task_exit: pid=7735 oom_score_adj=0 exit_signal=-1 exit_code=15 exit_state=0x10 comm=t
            bash-7455    [005] d... 263979.289851: task_exit: pid=7734 oom_score_adj=0 exit_signal=17 exit_code=15 exit_state=0x10 comm=t
           <...>-740     [005] ..s. 263979.384477: sched_process_free: comm=t pid=7734 prio=120
          <idle>-0       [000] ..s. 263979.384481: sched_process_free: comm=t pid=7738 prio=120
          <idle>-0       [000] ..s. 263979.384488: sched_process_free: comm=t pid=7735 prio=120
          <idle>-0       [001] ..s. 263979.385482: sched_process_free: comm=t pid=7739 prio=120
          <idle>-0       [001] ..s. 263979.385496: sched_process_free: comm=t pid=7736 prio=120
          <idle>-0       [002] ..s. 263979.489469: sched_process_free: comm=t pid=7740 prio=120
          <idle>-0       [002] ..s. 263979.489490: sched_process_free: comm=t pid=7737 prio=120

Not also the order.

> Thanks,
>
> Mathieu
>
Thanks

Peter