[PATCH v2] sched: introduce sched_switch_post trace event

[PATCH v2] sched: introduce sched_switch_post trace event

[Cong Wang]

Currently we only have one sched_switch trace event
for task switching, which is generated very early during
task switch. When we try to monitor per-container perf
events, this is not what we expect.

For example, we have a process A which is in the cgroup
we monitor, and process B which isn't, when kernel switches
from B to A, the sched_switch event is not recorded for this
cgroup since it belongs to B (current process is still B
util we finish the switch), but we require this event to
signal that process A in this cgroup gets scheduled. This is
crucial for calculating schedule latency (like `perf sched`).

Ideally, we need to split the sched_switch event into two:
sched_in event before we perform the switch, and sched_out
event after we perform the switch. However, for compatibility,
we can not change the sched_switch event. So before we have
trace event alias, we can just reuse sched_switch and introduce
sched_switch_post event instead.

Suggested-by: Steven Rostedt <rostedt@goodmis.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Signed-off-by: Cong Wang <xiyou.wangcong@gmail.com>
Signed-off-by: Cong Wang <cwang@twopensource.com>
---
 include/trace/events/sched.h | 43 ++++++++++++++++++++++++++++++++++++++++++-
 kernel/sched/core.c          |  1 +
 2 files changed, 43 insertions(+), 1 deletion(-)

diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h
index d57a575..4bc7db5 100644
--- a/include/trace/events/sched.h
+++ b/include/trace/events/sched.h
@@ -112,7 +112,9 @@ static inline long __trace_sched_switch_state(struct task_struct *p)
 #endif /* CREATE_TRACE_POINTS */
 
 /*
- * Tracepoint for task switches, performed by the scheduler:
+ * Tracepoints for task switches, performed by the scheduler:
+ * sched_switch is performed before task switch,
+ * sched_switch_post is performed after task switch.
  */
 TRACE_EVENT(sched_switch,
 
@@ -153,6 +155,45 @@ TRACE_EVENT(sched_switch,
 		__entry->next_comm, __entry->next_pid, __entry->next_prio)
 );
 
+TRACE_EVENT(sched_switch_post,
+
+	TP_PROTO(struct task_struct *prev,
+		 struct task_struct *curr),
+
+	TP_ARGS(prev, curr),
+
+	TP_STRUCT__entry(
+		__array(	char,	prev_comm,	TASK_COMM_LEN	)
+		__field(	pid_t,	prev_pid			)
+		__field(	int,	prev_prio			)
+		__field(	long,	prev_state			)
+		__array(	char,	curr_comm,	TASK_COMM_LEN	)
+		__field(	pid_t,	curr_pid			)
+		__field(	int,	curr_prio			)
+	),
+
+	TP_fast_assign(
+		memcpy(__entry->curr_comm, curr->comm, TASK_COMM_LEN);
+		__entry->prev_pid	= prev->pid;
+		__entry->prev_prio	= prev->prio;
+		__entry->prev_state	= __trace_sched_switch_state(prev);
+		memcpy(__entry->prev_comm, prev->comm, TASK_COMM_LEN);
+		__entry->curr_pid	= curr->pid;
+		__entry->curr_prio	= curr->prio;
+	),
+
+	TP_printk("prev_comm=%s prev_pid=%d prev_prio=%d prev_state=%s%s ==> curr_comm=%s curr_pid=%d curr_prio=%d",
+		__entry->prev_comm, __entry->prev_pid, __entry->prev_prio,
+		__entry->prev_state & (TASK_STATE_MAX-1) ?
+		  __print_flags(__entry->prev_state & (TASK_STATE_MAX-1), "|",
+				{ 1, "S"} , { 2, "D" }, { 4, "T" }, { 8, "t" },
+				{ 16, "Z" }, { 32, "X" }, { 64, "x" },
+				{ 128, "K" }, { 256, "W" }, { 512, "P" },
+				{ 1024, "N" }) : "R",
+		__entry->prev_state & TASK_STATE_MAX ? "+" : "",
+		__entry->curr_comm, __entry->curr_pid, __entry->curr_prio)
+);
+
 /*
  * Tracepoint for a task being migrated:
  */
diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 78b4bad10..3c74cf4 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -2490,6 +2490,7 @@ static struct rq *finish_task_switch(struct task_struct *prev)
 	}
 
 	tick_nohz_task_switch(current);
+	trace_sched_switch_post(prev, current);
 	return rq;
 }
 
-- 
1.8.3.1

Re: [PATCH v2] sched: introduce sched_switch_post trace event

[Steven Rostedt]

On Mon,  6 Jul 2015 12:15:45 -0700
Cong Wang <xiyou.wangcong@gmail.com> wrote:

> Currently we only have one sched_switch trace event
> for task switching, which is generated very early during
> task switch. When we try to monitor per-container perf
> events, this is not what we expect.
> 
> For example, we have a process A which is in the cgroup
> we monitor, and process B which isn't, when kernel switches
> from B to A, the sched_switch event is not recorded for this
> cgroup since it belongs to B (current process is still B
> util we finish the switch), but we require this event to
> signal that process A in this cgroup gets scheduled. This is
> crucial for calculating schedule latency (like `perf sched`).

I just want to understand this correctly. Does perf sched only listen
to events that are executed by the task in a particular cgroup? There's
no way to say "check sched_switch field next"?


> 
> Ideally, we need to split the sched_switch event into two:
> sched_in event before we perform the switch, and sched_out
> event after we perform the switch. However, for compatibility,
> we can not change the sched_switch event. So before we have
> trace event alias, we can just reuse sched_switch and introduce
> sched_switch_post event instead.
> 
> Suggested-by: Steven Rostedt <rostedt@goodmis.org>
> Cc: Steven Rostedt <rostedt@goodmis.org>
> Cc: Ingo Molnar <mingo@redhat.com>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Signed-off-by: Cong Wang <xiyou.wangcong@gmail.com>
> Signed-off-by: Cong Wang <cwang@twopensource.com>
> ---
>  include/trace/events/sched.h | 43 ++++++++++++++++++++++++++++++++++++++++++-
>  kernel/sched/core.c          |  1 +
>  2 files changed, 43 insertions(+), 1 deletion(-)
> 
> diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h
> index d57a575..4bc7db5 100644
> --- a/include/trace/events/sched.h
> +++ b/include/trace/events/sched.h
> @@ -112,7 +112,9 @@ static inline long __trace_sched_switch_state(struct task_struct *p)
>  #endif /* CREATE_TRACE_POINTS */
>  
>  /*
> - * Tracepoint for task switches, performed by the scheduler:
> + * Tracepoints for task switches, performed by the scheduler:
> + * sched_switch is performed before task switch,
> + * sched_switch_post is performed after task switch.
>   */
>  TRACE_EVENT(sched_switch,
>  
> @@ -153,6 +155,45 @@ TRACE_EVENT(sched_switch,
>  		__entry->next_comm, __entry->next_pid, __entry->next_prio)
>  );
>  
> +TRACE_EVENT(sched_switch_post,
> +
> +	TP_PROTO(struct task_struct *prev,
> +		 struct task_struct *curr),
> +
> +	TP_ARGS(prev, curr),
> +
> +	TP_STRUCT__entry(
> +		__array(	char,	prev_comm,	TASK_COMM_LEN	)
> +		__field(	pid_t,	prev_pid			)
> +		__field(	int,	prev_prio			)
> +		__field(	long,	prev_state			)
> +		__array(	char,	curr_comm,	TASK_COMM_LEN	)
> +		__field(	pid_t,	curr_pid			)
> +		__field(	int,	curr_prio			)
> +	),
> +
> +	TP_fast_assign(
> +		memcpy(__entry->curr_comm, curr->comm, TASK_COMM_LEN);
> +		__entry->prev_pid	= prev->pid;
> +		__entry->prev_prio	= prev->prio;
> +		__entry->prev_state	= __trace_sched_switch_state(prev);
> +		memcpy(__entry->prev_comm, prev->comm, TASK_COMM_LEN);
> +		__entry->curr_pid	= curr->pid;
> +		__entry->curr_prio	= curr->prio;
> +	),
> +
> +	TP_printk("prev_comm=%s prev_pid=%d prev_prio=%d prev_state=%s%s ==> curr_comm=%s curr_pid=%d curr_prio=%d",
> +		__entry->prev_comm, __entry->prev_pid, __entry->prev_prio,
> +		__entry->prev_state & (TASK_STATE_MAX-1) ?
> +		  __print_flags(__entry->prev_state & (TASK_STATE_MAX-1), "|",
> +				{ 1, "S"} , { 2, "D" }, { 4, "T" }, { 8, "t" },
> +				{ 16, "Z" }, { 32, "X" }, { 64, "x" },
> +				{ 128, "K" }, { 256, "W" }, { 512, "P" },
> +				{ 1024, "N" }) : "R",
> +		__entry->prev_state & TASK_STATE_MAX ? "+" : "",
> +		__entry->curr_comm, __entry->curr_pid, __entry->curr_prio)
> +);
> +

This looks identical to trace_sched_switch. Please convert both to a
DECLARE_EVENT_CLASS() and DEFINE_EVENT()s.

-- Steve

>  /*
>   * Tracepoint for a task being migrated:
>   */
> diff --git a/kernel/sched/core.c b/kernel/sched/core.c
> index 78b4bad10..3c74cf4 100644
> --- a/kernel/sched/core.c
> +++ b/kernel/sched/core.c
> @@ -2490,6 +2490,7 @@ static struct rq *finish_task_switch(struct task_struct *prev)
>  	}
>  
>  	tick_nohz_task_switch(current);
> +	trace_sched_switch_post(prev, current);
>  	return rq;
>  }
>  

Re: [PATCH v2] sched: introduce sched_switch_post trace event

[Peter Zijlstra]

On Mon, Jul 06, 2015 at 12:15:45PM -0700, Cong Wang wrote:
> Currently we only have one sched_switch trace event
> for task switching, which is generated very early during
> task switch. When we try to monitor per-container perf
> events, this is not what we expect.
> 
> For example, we have a process A which is in the cgroup
> we monitor, and process B which isn't, when kernel switches
> from B to A, the sched_switch event is not recorded for this
> cgroup since it belongs to B (current process is still B
> util we finish the switch), but we require this event to
> signal that process A in this cgroup gets scheduled. This is
> crucial for calculating schedule latency (like `perf sched`).
> 
> Ideally, we need to split the sched_switch event into two:
> sched_in event before we perform the switch, and sched_out
> event after we perform the switch. However, for compatibility,
> we can not change the sched_switch event. So before we have
> trace event alias, we can just reuse sched_switch and introduce
> sched_switch_post event instead.

No.. its still horrible.

You're trying to solve perf problems with ftrace; this cannot work.

Does this patch by Adrian work for you? I think it solves this problem
and a bunch of others.

lkml.kernel.org/r/1435927962-32417-2-git-send-email-adrian.hunter@intel.com

Re: [PATCH v2] sched: introduce sched_switch_post trace event

[Cong Wang]

On Mon, Jul 6, 2015 at 5:15 PM, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Mon,  6 Jul 2015 12:15:45 -0700
> Cong Wang <xiyou.wangcong@gmail.com> wrote:
>
>> Currently we only have one sched_switch trace event
>> for task switching, which is generated very early during
>> task switch. When we try to monitor per-container perf
>> events, this is not what we expect.
>>
>> For example, we have a process A which is in the cgroup
>> we monitor, and process B which isn't, when kernel switches
>> from B to A, the sched_switch event is not recorded for this
>> cgroup since it belongs to B (current process is still B
>> util we finish the switch), but we require this event to
>> signal that process A in this cgroup gets scheduled. This is
>> crucial for calculating schedule latency (like `perf sched`).
>
> I just want to understand this correctly. Does perf sched only listen
> to events that are executed by the task in a particular cgroup? There's
> no way to say "check sched_switch field next"?
>

perf_event cgroup needs to be specified in cmdline and `perf sched`
doesn't support that currently, I wrote my own tool to do this.
(I have some patch to add it to `perf sched`)

As I replied in the previous thread, we can certainly check if a process
belongs to a cgroup by tracking the PID's, but that is not easy.

>
> This looks identical to trace_sched_switch. Please convert both to a
> DECLARE_EVENT_CLASS() and DEFINE_EVENT()s.
>

Not identical, I rename 'next' to 'curr' since switch is done 'next'
becomes meaningless.

Thanks.

Re: [PATCH v2] sched: introduce sched_switch_post trace event

[Cong Wang]

On Mon, Jul 6, 2015 at 11:45 PM, Peter Zijlstra <peterz@infradead.org> wrote:
> On Mon, Jul 06, 2015 at 12:15:45PM -0700, Cong Wang wrote:
>> Currently we only have one sched_switch trace event
>> for task switching, which is generated very early during
>> task switch. When we try to monitor per-container perf
>> events, this is not what we expect.
>>
>> For example, we have a process A which is in the cgroup
>> we monitor, and process B which isn't, when kernel switches
>> from B to A, the sched_switch event is not recorded for this
>> cgroup since it belongs to B (current process is still B
>> util we finish the switch), but we require this event to
>> signal that process A in this cgroup gets scheduled. This is
>> crucial for calculating schedule latency (like `perf sched`).
>>
>> Ideally, we need to split the sched_switch event into two:
>> sched_in event before we perform the switch, and sched_out
>> event after we perform the switch. However, for compatibility,
>> we can not change the sched_switch event. So before we have
>> trace event alias, we can just reuse sched_switch and introduce
>> sched_switch_post event instead.
>
> No.. its still horrible.
>
> You're trying to solve perf problems with ftrace; this cannot work.

It works for tools like `perf sched` which only listens to trace events. :)

>
> Does this patch by Adrian work for you? I think it solves this problem
> and a bunch of others.
>
> lkml.kernel.org/r/1435927962-32417-2-git-send-email-adrian.hunter@intel.com

Ah, probably, as long as we have some event after sched switch,
no matter it's perf event trace event, it should work for me too.

The downside of using a perf event is that it is _a bit_ harder to parse
a new perf event than reusing the current code to parse a new trace
event.

On the other hand, only perf events have cgroup, trace events
AFAIK don't have cgroup. So in this aspect, it is right to generate
a perf event after switch.

Thanks.