perf sched timehist --state vs perf script

perf sched timehist --state vs perf script

[vmolnaro]

From: Veronika Molnarova <vmolnaro@redhat.com>

Hello!

We encountered an issue with 'perf sched timehist --state' when
we expected for a test case that the process of a workload would 
eventually end in the dead state(marked by 'X') and be switched
out. This can be seen also by using 'perf script':

    # perf sched record -a sleep 1
    [ perf record: Woken up 1 times to write data ]
    [ perf record: Captured and wrote 0.167 MB perf.data (166 samples) ]
    # perf script | grep sleep
           sleep  151541 [000] 193461.410617: sched:sched_stat_runtime: comm=sleep pid=151541 runtime=3132275 [ns]
           sleep  151541 [000] 193461.410624:       sched:sched_switch: sleep:151541 [120] S ==> swapper/0:0 [120]
         swapper       0 [000] 193462.410688:       sched:sched_waking: comm=sleep pid=151541 prio=120 target_cpu=000
         swapper       0 [000] 193462.410698:       sched:sched_switch: swapper/0:0 [120] R ==> sleep:151541 [120]
         :151541  151541 [000] 193462.411100: sched:sched_stat_runtime: comm=sleep pid=151541 runtime=407210 [ns]
         :151541  151541 [000] 193462.411107:       sched:sched_switch: sleep:151541 [120] X ==> swapper/0:0 [120]

But for the 'perf sched timehist --state' the process is shown
in the zombie state when it is being switched out:

    # perf sched timehist --state | grep 151541
    Samples do not have callchains.
      193461.410624 [0000]  sleep[151541]                       0.000      0.054      3.129      S 
      193462.411107 [0000]  :151541[151541]                     0.000      0.000      0.408      Z 

Shouldn't both commands report the same result, or is there a reason
why 'perf script' uses the dead state while 'perf sched' uses dead?
It also seems that the 'perf sched' cannot read the name of the zombie
process, but that can be a different issue.

Thanks,

Veronika

Re: perf sched timehist --state vs perf script

[Namhyung Kim]

On Thu, Oct 24, 2024 at 06:36:30PM +0200, vmolnaro@redhat.com wrote:
> From: Veronika Molnarova <vmolnaro@redhat.com>
> 
> Hello!
> 
> We encountered an issue with 'perf sched timehist --state' when
> we expected for a test case that the process of a workload would 
> eventually end in the dead state(marked by 'X') and be switched
> out. This can be seen also by using 'perf script':
> 
>     # perf sched record -a sleep 1
>     [ perf record: Woken up 1 times to write data ]
>     [ perf record: Captured and wrote 0.167 MB perf.data (166 samples) ]
>     # perf script | grep sleep
>            sleep  151541 [000] 193461.410617: sched:sched_stat_runtime: comm=sleep pid=151541 runtime=3132275 [ns]
>            sleep  151541 [000] 193461.410624:       sched:sched_switch: sleep:151541 [120] S ==> swapper/0:0 [120]
>          swapper       0 [000] 193462.410688:       sched:sched_waking: comm=sleep pid=151541 prio=120 target_cpu=000
>          swapper       0 [000] 193462.410698:       sched:sched_switch: swapper/0:0 [120] R ==> sleep:151541 [120]
>          :151541  151541 [000] 193462.411100: sched:sched_stat_runtime: comm=sleep pid=151541 runtime=407210 [ns]
>          :151541  151541 [000] 193462.411107:       sched:sched_switch: sleep:151541 [120] X ==> swapper/0:0 [120]
> 
> But for the 'perf sched timehist --state' the process is shown
> in the zombie state when it is being switched out:
> 
>     # perf sched timehist --state | grep 151541
>     Samples do not have callchains.
>       193461.410624 [0000]  sleep[151541]                       0.000      0.054      3.129      S 
>       193462.411107 [0000]  :151541[151541]                     0.000      0.000      0.408      Z 
> 
> Shouldn't both commands report the same result, or is there a reason
> why 'perf script' uses the dead state while 'perf sched' uses dead?

I remember there was a discussion related to this.

https://lore.kernel.org/all/20240122070859.1394479-2-zegao@tencent.com/

And it seems it's fixed both in perf and libtraceevent.  Maybe your
libtraceevent is somewhat outdated and doesn't have the update.

> It also seems that the 'perf sched' cannot read the name of the zombie
> process, but that can be a different issue.

Hmm.. right.  It should update thread->comm using the sched_switch event.

Thanks,
Namhyung

Re: perf sched timehist --state vs perf script

[Michael Petlan]

On Tue, 29 Oct 2024, Namhyung Kim wrote:
> On Thu, Oct 24, 2024 at 06:36:30PM +0200, vmolnaro@redhat.com wrote:
> > From: Veronika Molnarova <vmolnaro@redhat.com>
> > 
> > Hello!
> > 
> > We encountered an issue with 'perf sched timehist --state' when
> > we expected for a test case that the process of a workload would 
> > eventually end in the dead state(marked by 'X') and be switched
> > out. This can be seen also by using 'perf script':
> > 
> >     # perf sched record -a sleep 1
> >     [ perf record: Woken up 1 times to write data ]
> >     [ perf record: Captured and wrote 0.167 MB perf.data (166 samples) ]
> >     # perf script | grep sleep
> >            sleep  151541 [000] 193461.410617: sched:sched_stat_runtime: comm=sleep pid=151541 runtime=3132275 [ns]
> >            sleep  151541 [000] 193461.410624:       sched:sched_switch: sleep:151541 [120] S ==> swapper/0:0 [120]
> >          swapper       0 [000] 193462.410688:       sched:sched_waking: comm=sleep pid=151541 prio=120 target_cpu=000
> >          swapper       0 [000] 193462.410698:       sched:sched_switch: swapper/0:0 [120] R ==> sleep:151541 [120]
> >          :151541  151541 [000] 193462.411100: sched:sched_stat_runtime: comm=sleep pid=151541 runtime=407210 [ns]
> >          :151541  151541 [000] 193462.411107:       sched:sched_switch: sleep:151541 [120] X ==> swapper/0:0 [120]
> > 
> > But for the 'perf sched timehist --state' the process is shown
> > in the zombie state when it is being switched out:
> > 
> >     # perf sched timehist --state | grep 151541
> >     Samples do not have callchains.
> >       193461.410624 [0000]  sleep[151541]                       0.000      0.054      3.129      S 
> >       193462.411107 [0000]  :151541[151541]                     0.000      0.000      0.408      Z 
> > 
> > Shouldn't both commands report the same result, or is there a reason
> > why 'perf script' uses the dead state while 'perf sched' uses dead?

Hello! Thanks for reacting!
> 
> I remember there was a discussion related to this.
> 
> https://lore.kernel.org/all/20240122070859.1394479-2-zegao@tencent.com/
> 
> And it seems it's fixed both in perf and libtraceevent.  Maybe your
> libtraceevent is somewhat outdated and doesn't have the update.
>
Yes! When we've updated libtraceevent to 1.8.3, both show Z now, which is
probably correct.

Then it comes into my mind whether shouldn't perf-sched and perf-script
both take it from libtraceevent to unify the approaches, rather than
perf-sched using its own implementation and perf-script taking it from
libtraceevent... ?

> > It also seems that the 'perf sched' cannot read the name of the zombie
> > process, but that can be a different issue.
> 
> Hmm.. right.  It should update thread->comm using the sched_switch event.

According to the tests, the name seems that it used to be translated correctly
in past, so it'd be nice if it worked again, althoug it is pretty clear which
process it was, according to the PID. Thus, the test can be adjusted to search
for the combination "PID, status Z", instead of "command, status Z"... I.e. to
accept the current situation...

Thanks,

Michael

> 
> Thanks,
> Namhyung
> 
> 

Re: perf sched timehist --state vs perf script

[Namhyung Kim]

On Thu, Oct 31, 2024 at 12:32:31PM +0100, Michael Petlan wrote:
> On Tue, 29 Oct 2024, Namhyung Kim wrote:
> > On Thu, Oct 24, 2024 at 06:36:30PM +0200, vmolnaro@redhat.com wrote:
> > > From: Veronika Molnarova <vmolnaro@redhat.com>
> > > 
> > > Hello!
> > > 
> > > We encountered an issue with 'perf sched timehist --state' when
> > > we expected for a test case that the process of a workload would 
> > > eventually end in the dead state(marked by 'X') and be switched
> > > out. This can be seen also by using 'perf script':
> > > 
> > >     # perf sched record -a sleep 1
> > >     [ perf record: Woken up 1 times to write data ]
> > >     [ perf record: Captured and wrote 0.167 MB perf.data (166 samples) ]
> > >     # perf script | grep sleep
> > >            sleep  151541 [000] 193461.410617: sched:sched_stat_runtime: comm=sleep pid=151541 runtime=3132275 [ns]
> > >            sleep  151541 [000] 193461.410624:       sched:sched_switch: sleep:151541 [120] S ==> swapper/0:0 [120]
> > >          swapper       0 [000] 193462.410688:       sched:sched_waking: comm=sleep pid=151541 prio=120 target_cpu=000
> > >          swapper       0 [000] 193462.410698:       sched:sched_switch: swapper/0:0 [120] R ==> sleep:151541 [120]
> > >          :151541  151541 [000] 193462.411100: sched:sched_stat_runtime: comm=sleep pid=151541 runtime=407210 [ns]
> > >          :151541  151541 [000] 193462.411107:       sched:sched_switch: sleep:151541 [120] X ==> swapper/0:0 [120]
> > > 
> > > But for the 'perf sched timehist --state' the process is shown
> > > in the zombie state when it is being switched out:
> > > 
> > >     # perf sched timehist --state | grep 151541
> > >     Samples do not have callchains.
> > >       193461.410624 [0000]  sleep[151541]                       0.000      0.054      3.129      S 
> > >       193462.411107 [0000]  :151541[151541]                     0.000      0.000      0.408      Z 
> > > 
> > > Shouldn't both commands report the same result, or is there a reason
> > > why 'perf script' uses the dead state while 'perf sched' uses dead?
> 
> Hello! Thanks for reacting!
> > 
> > I remember there was a discussion related to this.
> > 
> > https://lore.kernel.org/all/20240122070859.1394479-2-zegao@tencent.com/
> > 
> > And it seems it's fixed both in perf and libtraceevent.  Maybe your
> > libtraceevent is somewhat outdated and doesn't have the update.
> >
> Yes! When we've updated libtraceevent to 1.8.3, both show Z now, which is
> probably correct.

Cool.

> 
> Then it comes into my mind whether shouldn't perf-sched and perf-script
> both take it from libtraceevent to unify the approaches, rather than
> perf-sched using its own implementation and perf-script taking it from
> libtraceevent... ?

Yeah, I think it's better to use libtraceevent for it.

> 
> > > It also seems that the 'perf sched' cannot read the name of the zombie
> > > process, but that can be a different issue.
> > 
> > Hmm.. right.  It should update thread->comm using the sched_switch event.
> 
> According to the tests, the name seems that it used to be translated correctly
> in past, so it'd be nice if it worked again, althoug it is pretty clear which
> process it was, according to the PID. Thus, the test can be adjusted to search
> for the combination "PID, status Z", instead of "command, status Z"... I.e. to
> accept the current situation...

Sounds good.  Please send the patch.

Thanks,
Namhyung