| Message ID | 20230801090124.8050-4-zegao@tencent.com (mailing list archive) |
|---|---|
| State | Handled Elsewhere |
| Headers | show |
| Series | add to report task state in symbolic chars from sched tracepoint | expand |
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) > ); >
diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h index fbb99a61f714..e507901bcab8 100644 --- a/include/trace/events/sched.h +++ b/include/trace/events/sched.h @@ -6,6 +6,7 @@ #define _TRACE_SCHED_H #include <linux/kthread.h> +#include <linux/sched.h> #include <linux/sched/numa_balancing.h> #include <linux/tracepoint.h> #include <linux/binfmts.h> @@ -214,6 +215,27 @@ static inline long __trace_sched_switch_state(bool preempt, return state ? (1 << (state - 1)) : state; } + +static inline char __trace_sched_switch_state_char(bool preempt, + unsigned int prev_state, + struct task_struct *p) +{ + long state; + +#ifdef CONFIG_SCHED_DEBUG + BUG_ON(p != current); +#endif /* CONFIG_SCHED_DEBUG */ + + /* + * For PREEMPT_ACTIVE, we introduce 'p' to report it and use the old + * conventions for the rest. + */ + if (preempt) + return 'p'; + + state = __task_state_index(prev_state, p->exit_state); + return task_index_to_char(state); +} #endif /* CREATE_TRACE_POINTS */ /* @@ -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 ) @@ -240,32 +263,19 @@ TRACE_EVENT(sched_switch, TP_fast_assign( 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_pid = prev->pid; + __entry->prev_prio = prev->prio; + __entry->prev_state = __trace_sched_switch_state(preempt, prev_state, prev); + __entry->prev_state_char = __trace_sched_switch_state_char(preempt, prev_state, prev); memcpy(__entry->prev_comm, prev->comm, TASK_COMM_LEN); - __entry->next_pid = next->pid; - __entry->next_prio = next->prio; + __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", - __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->next_comm, __entry->next_pid, __entry->next_prio) + TP_printk("prev_comm=%s prev_pid=%d prev_prio=%d prev_state=%c ==> next_comm=%s next_pid=%d next_prio=%d", + __entry->prev_comm, __entry->prev_pid, __entry->prev_prio, __entry->prev_state_char, __entry->next_comm, + __entry->next_pid, __entry->next_prio) ); /*