[RFC,v3,3/6] sched, tracing: add to report task state in symbolic chars

  Internal representations of task state are likely to be changed
or ordered, and reporting them to userspace without exporting
them as part of API is basically wrong, which can easily break
a userspace observability tool as kernel evolves. For example,
perf suffers from this and still reports wrong states as of this
writing.

OTOH, some masqueraded states like TASK_REPORT_IDLE and
TASK_REPORT_MAX are also reported inadvertently, which confuses
things even more and most userspace tools do not even take them
into consideration.

So add a new variable in company with the old raw value to
report task state in symbolic chars, which are self-explaining
and no further translation is needed. Of course this does not
break any userspace tool.

Note for PREEMPT_ACTIVE, we introduce 'p' to report it and use
the old conventions for the rest.

Signed-off-by: Ze Gao <zegao@tencent.com>
Reviewed-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
Acked-by: Ian Rogers <irogers@google.com>
---
 include/trace/events/sched.h | 54 +++++++++++++++++++++---------------
 1 file changed, 32 insertions(+), 22 deletions(-)
  

On Tue, Aug 01, 2023 at 05:01:21PM +0800, Ze Gao wrote:
> Internal representations of task state are likely to be changed
> or ordered, and reporting them to userspace without exporting
> them as part of API is basically wrong, which can easily break
> a userspace observability tool as kernel evolves. For example,
> perf suffers from this and still reports wrong states as of this
> writing.
> 
> OTOH, some masqueraded states like TASK_REPORT_IDLE and
> TASK_REPORT_MAX are also reported inadvertently, which confuses
> things even more and most userspace tools do not even take them
> into consideration.
> 
> So add a new variable in company with the old raw value to
> report task state in symbolic chars, which are self-explaining
> and no further translation is needed. Of course this does not
> break any userspace tool.
> 
> Note for PREEMPT_ACTIVE, we introduce 'p' to report it and use
> the old conventions for the rest.

*sigh*... just because userspace if daft, we need to change the kernel?

Why do we need this character anyway, why not just print the state in
hex and leave it at that? These single character state things are a
relic, please just let them die.
  

On Tue, Aug 01, 2023 at 05:01:21PM +0800, Ze Gao wrote:
> @@ -233,6 +255,7 @@ TRACE_EVENT(sched_switch,
>  		__field(	pid_t,	prev_pid			)
>  		__field(	int,	prev_prio			)
>  		__field(	long,	prev_state			)
> +		__field(	char,	prev_state_char			)
>  		__array(	char,	next_comm,	TASK_COMM_LEN	)
>  		__field(	pid_t,	next_pid			)
>  		__field(	int,	next_prio			)

And this again will wreck everybody that consumes the raw tracepoint
without looking at tracefs.
  

On Tue, Aug 1, 2023 at 7:34 PM Peter Zijlstra <peterz@infradead.org> wrote:
>
> On Tue, Aug 01, 2023 at 05:01:21PM +0800, Ze Gao wrote:
> > Internal representations of task state are likely to be changed
> > or ordered, and reporting them to userspace without exporting
> > them as part of API is basically wrong, which can easily break
> > a userspace observability tool as kernel evolves. For example,
> > perf suffers from this and still reports wrong states as of this
> > writing.
> >
> > OTOH, some masqueraded states like TASK_REPORT_IDLE and
> > TASK_REPORT_MAX are also reported inadvertently, which confuses
> > things even more and most userspace tools do not even take them
> > into consideration.
> >
> > So add a new variable in company with the old raw value to
> > report task state in symbolic chars, which are self-explaining
> > and no further translation is needed. Of course this does not
> > break any userspace tool.
> >
> > Note for PREEMPT_ACTIVE, we introduce 'p' to report it and use
> > the old conventions for the rest.
>
> *sigh*... just because userspace if daft, we need to change the kernel?

Hi Peter,

Sorry that I don't quite agree with you on this one.

It's just the design that exporting internal details is fundamentally wrong.
And even worse,  I did not see any userspace tool is aware of masqueraded
states like TASK_REPORT_IDLE and TASK_REPORT_MAX and let alone
parse it correctly.  This confused me a lot when I decided to write my own bpf
version of sched-latency analysis tool and only after I figured out everything
underneath, I started to make things right here.

Again, I mean it's not me that deliberately "breaks" ABI here and I am
never meant
to upset anyone.  My confusion is why did people forget to update in-tree perf
the very last time they decide to rearrange the task state mapping
since we all agree
this is important "ABI" here.  I don't think it's the tool's fault.
And that's my initiative
to request this RFC.

> Why do we need this character anyway, why not just print the state in
> hex and leave it at that? These single character state things are a
> relic, please just let them die.

I believe hex is ok only after having the reported task state mapping
appear in the
uapi headers, otherwise it's still useless to userspace especially for
value like
TASK_REPORT_IDLE and TASK_REPORT_MAX, which need to dig into the
kernel to see what the hell is going on here.

Thoughts?

Regards,
Ze
  

Sorry that I don't get this one, did you mean kernel subsystems like
bpf or third party modules?  Honestly I don't know how it works here
for userspace to consume the raw tracepoint without looking at
tracefs.

Regards,
Ze

On Tue, Aug 1, 2023 at 7:46 PM Peter Zijlstra <peterz@infradead.org> wrote:
>
> On Tue, Aug 01, 2023 at 05:01:21PM +0800, Ze Gao wrote:
> > @@ -233,6 +255,7 @@ TRACE_EVENT(sched_switch,
> >               __field(        pid_t,  prev_pid                        )
> >               __field(        int,    prev_prio                       )
> >               __field(        long,   prev_state                      )
> > +             __field(        char,   prev_state_char                 )
> >               __array(        char,   next_comm,      TASK_COMM_LEN   )
> >               __field(        pid_t,  next_pid                        )
> >               __field(        int,    next_prio                       )
>
> And this again will wreck everybody that consumes the raw tracepoint
> without looking at tracefs.
  

On Tue, Aug 01, 2023 at 09:03:51PM +0800, Ze Gao wrote:

> It's just the design that exporting internal details is fundamentally wrong.

This is tracing... it wasn't supposed to be ABI (although it somehow
ended up being one). But even then, things like PF_foo get exposed in
procfs but even that we change.

The whole point of tracing is to see internals in order to figure out
wth is going wrong.

> And even worse,  I did not see any userspace tool is aware of masqueraded
> states like TASK_REPORT_IDLE and TASK_REPORT_MAX and let alone
> parse it correctly.

That's probably because I never use tools, I just look at the raw trace
output -- sometimes an impromptu awk script. I'm pretty sure I ran with
something like the below when I did the freezer rewrite -- or perhaps I
just stuck in trace_printk() and didn't even bother with the
tracepoints, I can't remember.

> > Why do we need this character anyway, why not just print the state in
> > hex and leave it at that? These single character state things are a
> > relic, please just let them die.
> 
> I believe hex is ok only after having the reported task state mapping
> appear in the uapi headers, otherwise it's still useless to userspace
> especially for value like TASK_REPORT_IDLE and TASK_REPORT_MAX, which
> need to dig into the kernel to see what the hell is going on here.
> 
> Thoughts?

If you're tracing the kernel, you had better know what the kernel is
doing, otherwise you get to keep the pieces.

Anyway, if you're doing BPF then why do you care about the trace event
at all, just attach to the raw tracepoint and consume @preemt, @prev,
@next and @prev_state.

---
diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h
index fbb99a61f714..cb0c1251729e 100644
--- a/include/trace/events/sched.h
+++ b/include/trace/events/sched.h
@@ -186,36 +186,6 @@ DEFINE_EVENT(sched_wakeup_template, sched_wakeup_new,
 	     TP_PROTO(struct task_struct *p),
 	     TP_ARGS(p));
 
-#ifdef CREATE_TRACE_POINTS
-static inline long __trace_sched_switch_state(bool preempt,
-					      unsigned int prev_state,
-					      struct task_struct *p)
-{
-	unsigned int state;
-
-#ifdef CONFIG_SCHED_DEBUG
-	BUG_ON(p != current);
-#endif /* CONFIG_SCHED_DEBUG */
-
-	/*
-	 * Preemption ignores task state, therefore preempted tasks are always
-	 * RUNNING (we will not have dequeued if state != RUNNING).
-	 */
-	if (preempt)
-		return TASK_REPORT_MAX;
-
-	/*
-	 * task_state_index() uses fls() and returns a value from 0-8 range.
-	 * Decrement it by 1 (except TASK_RUNNING state i.e 0) before using
-	 * it for left shift operation to get the correct task->state
-	 * mapping.
-	 */
-	state = __task_state_index(prev_state, p->exit_state);
-
-	return state ? (1 << (state - 1)) : state;
-}
-#endif /* CREATE_TRACE_POINTS */
-
 /*
  * Tracepoint for task switches, performed by the scheduler:
  */
@@ -242,29 +212,16 @@ TRACE_EVENT(sched_switch,
 		memcpy(__entry->next_comm, next->comm, TASK_COMM_LEN);
 		__entry->prev_pid	= prev->pid;
 		__entry->prev_prio	= prev->prio;
-		__entry->prev_state	= __trace_sched_switch_state(preempt, prev_state, prev);
+		__entry->prev_state	= prev_state | (preempt * TASK_STATE_MAX);
 		memcpy(__entry->prev_comm, prev->comm, TASK_COMM_LEN);
 		__entry->next_pid	= next->pid;
 		__entry->next_prio	= next->prio;
 		/* XXX SCHED_DEADLINE */
 	),
 
-	TP_printk("prev_comm=%s prev_pid=%d prev_prio=%d prev_state=%s%s ==> next_comm=%s next_pid=%d next_prio=%d",
+	TP_printk("prev_comm=%s prev_pid=%d prev_prio=%d prev_state=%x ==> next_comm=%s next_pid=%d next_prio=%d",
 		__entry->prev_comm, __entry->prev_pid, __entry->prev_prio,
-
-		(__entry->prev_state & (TASK_REPORT_MAX - 1)) ?
-		  __print_flags(__entry->prev_state & (TASK_REPORT_MAX - 1), "|",
-				{ TASK_INTERRUPTIBLE, "S" },
-				{ TASK_UNINTERRUPTIBLE, "D" },
-				{ __TASK_STOPPED, "T" },
-				{ __TASK_TRACED, "t" },
-				{ EXIT_DEAD, "X" },
-				{ EXIT_ZOMBIE, "Z" },
-				{ TASK_PARKED, "P" },
-				{ TASK_DEAD, "I" }) :
-		  "R",
-
-		__entry->prev_state & TASK_REPORT_MAX ? "+" : "",
+		__entry->prev_state,
 		__entry->next_comm, __entry->next_pid, __entry->next_prio)
 );
  

On Tue, 1 Aug 2023 13:45:45 +0200
Peter Zijlstra <peterz@infradead.org> wrote:

> On Tue, Aug 01, 2023 at 05:01:21PM +0800, Ze Gao wrote:
> > @@ -233,6 +255,7 @@ TRACE_EVENT(sched_switch,
> >  		__field(	pid_t,	prev_pid			)
> >  		__field(	int,	prev_prio			)
> >  		__field(	long,	prev_state			)
> > +		__field(	char,	prev_state_char			)
> >  		__array(	char,	next_comm,	TASK_COMM_LEN	)
> >  		__field(	pid_t,	next_pid			)
> >  		__field(	int,	next_prio			)  
> 
> And this again will wreck everybody that consumes the raw tracepoint
> without looking at tracefs.

Nobody does that anymore, as the events change constantly, and are
different on different kernels. Powertop (the tool that caused us pain
before by using raw values) had to break down and use libtraceevent,
because it would break if there was a 32 bit version running on a 64 bit
kernel.

I've changed the offsets of raw events a few times and nobody has
complained since.

-- Steve
  

On Tue, Aug 1, 2023 at 9:42 PM Peter Zijlstra <peterz@infradead.org> wrote:
>
> On Tue, Aug 01, 2023 at 09:03:51PM +0800, Ze Gao wrote:
>
> > It's just the design that exporting internal details is fundamentally wrong.
>
> This is tracing... it wasn't supposed to be ABI (although it somehow

Sorry, I'm confused. And it sounds contradicting here
because you said this change is abi break before.

> ended up being one). But even then, things like PF_foo get exposed in
> procfs but even that we change.
>
> The whole point of tracing is to see internals in order to figure out
> wth is going wrong.

Fair point, but I think tracepoints are somewhat different from
kprobes/raw_tracepoints due to their stable nature. And I think
at least more and more observability tools use them in this way.

With all due respect, If it was for kernel developers only, what's the
point of leaking this since now we have raw tracepoints support?
Does that mean all tracepoints are useless now? Apparently the
answer is no. So I'm not convinced by this "for internal inspecting"
defense to not ignore what the problem is.

Honestly, I would've never thought to change this if I I got the correct
meaning for values I captured like 0x80/0x100  when I tried to look it up
in include/linux/sched.h the first time. But it really annoyed me to
figure out what it is only after I dived into the kernel and collected all
the pieces.  And you know what, when I turned to the famous in-tree perf
for possible help, only to find out it's horribly broken and still uses an
outdated state char array to interpret this weird raw value.

Anyway, we have to accept the fact that prev_state leaves a huge burden
on its users to make things right.  And I'm open and glad to see any
solutions (possibly better than this one) or efforts or suggestions to improve
this.

Regards,
Ze

> > And even worse,  I did not see any userspace tool is aware of masqueraded
> > states like TASK_REPORT_IDLE and TASK_REPORT_MAX and let alone
> > parse it correctly.
>
> That's probably because I never use tools, I just look at the raw trace
> output -- sometimes an impromptu awk script. I'm pretty sure I ran with
> something like the below when I did the freezer rewrite -- or perhaps I
> just stuck in trace_printk() and didn't even bother with the
> tracepoints, I can't remember.
>
> > > Why do we need this character anyway, why not just print the state in
> > > hex and leave it at that? These single character state things are a
> > > relic, please just let them die.
> >
> > I believe hex is ok only after having the reported task state mapping
> > appear in the uapi headers, otherwise it's still useless to userspace
> > especially for value like TASK_REPORT_IDLE and TASK_REPORT_MAX, which
> > need to dig into the kernel to see what the hell is going on here.
> >
> > Thoughts?
>
> If you're tracing the kernel, you had better know what the kernel is
> doing, otherwise you get to keep the pieces.
>
> Anyway, if you're doing BPF then why do you care about the trace event
> at all, just attach to the raw tracepoint and consume @preemt, @prev,
> @next and @prev_state.
>
> ---
> diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h
> index fbb99a61f714..cb0c1251729e 100644
> --- a/include/trace/events/sched.h
> +++ b/include/trace/events/sched.h
> @@ -186,36 +186,6 @@ DEFINE_EVENT(sched_wakeup_template, sched_wakeup_new,
>              TP_PROTO(struct task_struct *p),
>              TP_ARGS(p));
>
> -#ifdef CREATE_TRACE_POINTS
> -static inline long __trace_sched_switch_state(bool preempt,
> -                                             unsigned int prev_state,
> -                                             struct task_struct *p)
> -{
> -       unsigned int state;
> -
> -#ifdef CONFIG_SCHED_DEBUG
> -       BUG_ON(p != current);
> -#endif /* CONFIG_SCHED_DEBUG */
> -
> -       /*
> -        * Preemption ignores task state, therefore preempted tasks are always
> -        * RUNNING (we will not have dequeued if state != RUNNING).
> -        */
> -       if (preempt)
> -               return TASK_REPORT_MAX;
> -
> -       /*
> -        * task_state_index() uses fls() and returns a value from 0-8 range.
> -        * Decrement it by 1 (except TASK_RUNNING state i.e 0) before using
> -        * it for left shift operation to get the correct task->state
> -        * mapping.
> -        */
> -       state = __task_state_index(prev_state, p->exit_state);
> -
> -       return state ? (1 << (state - 1)) : state;
> -}
> -#endif /* CREATE_TRACE_POINTS */
> -
>  /*
>   * Tracepoint for task switches, performed by the scheduler:
>   */
> @@ -242,29 +212,16 @@ TRACE_EVENT(sched_switch,
>                 memcpy(__entry->next_comm, next->comm, TASK_COMM_LEN);
>                 __entry->prev_pid       = prev->pid;
>                 __entry->prev_prio      = prev->prio;
> -               __entry->prev_state     = __trace_sched_switch_state(preempt, prev_state, prev);
> +               __entry->prev_state     = prev_state | (preempt * TASK_STATE_MAX);
>                 memcpy(__entry->prev_comm, prev->comm, TASK_COMM_LEN);
>                 __entry->next_pid       = next->pid;
>                 __entry->next_prio      = next->prio;
>                 /* XXX SCHED_DEADLINE */
>         ),
>
> -       TP_printk("prev_comm=%s prev_pid=%d prev_prio=%d prev_state=%s%s ==> next_comm=%s next_pid=%d next_prio=%d",
> +       TP_printk("prev_comm=%s prev_pid=%d prev_prio=%d prev_state=%x ==> next_comm=%s next_pid=%d next_prio=%d",
>                 __entry->prev_comm, __entry->prev_pid, __entry->prev_prio,
> -
> -               (__entry->prev_state & (TASK_REPORT_MAX - 1)) ?
> -                 __print_flags(__entry->prev_state & (TASK_REPORT_MAX - 1), "|",
> -                               { TASK_INTERRUPTIBLE, "S" },
> -                               { TASK_UNINTERRUPTIBLE, "D" },
> -                               { __TASK_STOPPED, "T" },
> -                               { __TASK_TRACED, "t" },
> -                               { EXIT_DEAD, "X" },
> -                               { EXIT_ZOMBIE, "Z" },
> -                               { TASK_PARKED, "P" },
> -                               { TASK_DEAD, "I" }) :
> -                 "R",
> -
> -               __entry->prev_state & TASK_REPORT_MAX ? "+" : "",
> +               __entry->prev_state,
>                 __entry->next_comm, __entry->next_pid, __entry->next_prio)
>  );
>