Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1490329 > unrolled thread

[RFC PATCH v2 0/5] Additional scheduling information in tracepoints

Back to article view | Back to linux.kernel

Contents

  [RFC PATCH v2 0/5] Additional scheduling information in tracepoints Julien Desfossez <jdesfossez@efficios.com> - 2016-09-23 19:00 +0200
    [RFC PATCH v2 4/5] tracing: extend sched_pi_setprio Julien Desfossez <jdesfossez@efficios.com> - 2016-09-23 19:00 +0200
    Re: [RFC PATCH v2 0/5] Additional scheduling information in  tracepoints Peter Zijlstra <peterz@infradead.org> - 2016-09-26 14:30 +0200
      Re: [RFC PATCH v2 0/5] Additional scheduling information in  tracepoints Mathieu Desnoyers <mathieu.desnoyers@efficios.com> - 2016-09-26 21:40 +0200

#1490329 — [RFC PATCH v2 0/5] Additional scheduling information in tracepoints

This patchset is a proposal to extract more accurate scheduling information in
the kernel trace. The existing scheduling tracepoints currently expose the
"prio" field which is an internal detail of the kernel and is not enough to
understand the behaviour of the scheduler. In order to get more accurate
information, we need the nice value, rt_priority, the policy and deadline
parameters (period, runtime and deadline).

The problem is that adding all these fields to the existing tracepoints will
quickly bloat the traces, especially for users who do not need these fields.
Moreover, removing the "prio" field might break existing tools.

This patchset, proposes a way to connect new probes to existing tracepoints
with the introduction of the TRACE_EVENT_MAP macro so that the instrumented
code does not have to change and we can create alternative versions of the
existing tracepoints.

With this macro, we propose new versions of the sched_switch, sched_waking,
sched_process_fork and sched_pi_setprio tracepoint probes that contain more
scheduling information and get rid of the "prio" field. We also add the PI
information to these tracepoints, so if a process is currently boosted, we show
the name and PID of the top waiter. This allows to quickly see the blocking
chain even if some of the trace background is missing.

In addition, we also propose a new tracepoint (sched_update_prio) that is
called whenever the scheduling configuration of a process is explicitly
changed.

Changes from v1:
 - Add a cover letter
 - Fix the signed-off-by chain
 - Remove an effect-less fix that was proposed
 - Move the effective_policy/rt_prio helpers to sched/core.c
 - Reorder the patchset so that the new TP sched_update_prio is the last one

Julien Desfossez (5):
  sched: get effective policy and rt_prio
  tracing: add TRACE_EVENT_MAP
  tracing: extend scheduling tracepoints
  tracing: extend sched_pi_setprio
  tracing: add sched_update_prio

 include/linux/sched.h        |   2 +
 include/linux/trace_events.h |  14 +-
 include/linux/tracepoint.h   |  11 +-
 include/trace/define_trace.h |   4 +
 include/trace/events/sched.h | 386 +++++++++++++++++++++++++++++++++++++++++++
 include/trace/perf.h         |   7 +
 include/trace/trace_events.h |  50 ++++++
 kernel/sched/core.c          |  39 +++++
 kernel/trace/trace_events.c  |  15 +-
 9 files changed, 522 insertions(+), 6 deletions(-)

-- 
1.9.1

[toc] | [next] | [standalone]

#1490335 — [RFC PATCH v2 4/5] tracing: extend sched_pi_setprio

Use the TRACE_EVENT_MAP macro to extend the sched_pi_setprio into
sched_pi_update_prio. The pre-existing event is untouched. This gets rid
of the old/new prio fields, and instead outputs the scheduling update
based on the top waiter of the rtmutex.

Boosting:
sched_pi_update_prio: comm=lowprio1, pid=3818, old_policy=SCHED_NORMAL,
	old_nice=0, old_rt_priority=0, old_dl_runtime=0,
	old_dl_deadline=0, old_dl_period=0, top_waiter_comm=highprio0,
	top_waiter_pid=3820, new_policy=SCHED_FIFO, new_nice=0,
	new_rt_priority=90, new_dl_runtime=0, new_dl_deadline=0,
	new_dl_period=0

Unboosting:
sched_pi_update_prio: comm=lowprio1, pid=3818, old_policy=SCHED_FIFO,
	old_nice=0, old_rt_priority=90, old_dl_runtime=0, old_dl_deadline=0,
	old_dl_period=0, top_waiter_comm=, top_waiter_pid=-1,
	new_policy=SCHED_NORMAL, new_nice=0, new_rt_priority=0,
	new_dl_runtime=0, new_dl_deadline=0, new_dl_period=0

Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Steven Rostedt (Red Hat) <rostedt@goodmis.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Ingo Molnar <mingo@redhat.com>
Reviewed-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Julien Desfossez <jdesfossez@efficios.com>
---
 include/trace/events/sched.h | 96 ++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 96 insertions(+)

diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h
index 6880682..582357d 100644
--- a/include/trace/events/sched.h
+++ b/include/trace/events/sched.h
@@ -658,6 +658,102 @@ static inline long __trace_sched_switch_state(bool preempt, struct task_struct *
 			__entry->oldprio, __entry->newprio)
 );
 
+/*
+ * Extract the complete scheduling information from the before
+ * and after the change of priority.
+ */
+TRACE_EVENT_MAP(sched_pi_setprio, sched_pi_update_prio,
+
+	TP_PROTO(struct task_struct *tsk, int newprio),
+
+	TP_ARGS(tsk, newprio),
+
+	TP_STRUCT__entry(
+		__array( char,	comm,	TASK_COMM_LEN	)
+		__field( pid_t,	pid			)
+		__field( unsigned int,	old_policy	)
+		__field( int,	old_nice		)
+		__field( unsigned int,	old_rt_priority	)
+		__field( u64,	old_dl_runtime		)
+		__field( u64,	old_dl_deadline		)
+		__field( u64,	old_dl_period		)
+		__array( char,	top_waiter_comm,	TASK_COMM_LEN	)
+		__field( pid_t,	top_waiter_pid		)
+		__field( unsigned int,	new_policy	)
+		__field( int,	new_nice		)
+		__field( unsigned int,	new_rt_priority	)
+		__field( u64,	new_dl_runtime		)
+		__field( u64,	new_dl_deadline		)
+		__field( u64,	new_dl_period		)
+	),
+
+	TP_fast_assign(
+		struct task_struct *top_waiter = rt_mutex_get_top_task(tsk);
+
+		memcpy(__entry->comm, tsk->comm, TASK_COMM_LEN);
+		__entry->pid			= tsk->pid;
+		__entry->old_policy		= effective_policy(
+							tsk->policy, tsk->prio);
+		__entry->old_nice		= task_nice(tsk);
+		__entry->old_rt_priority	= effective_rt_prio(
+							tsk->prio);
+		__entry->old_dl_runtime	= dl_prio(tsk->prio) ?
+							tsk->dl.dl_runtime : 0;
+		__entry->old_dl_deadline	= dl_prio(tsk->prio) ?
+							tsk->dl.dl_deadline : 0;
+		__entry->old_dl_period		= dl_prio(tsk->prio) ?
+							tsk->dl.dl_period : 0;
+		if (top_waiter) {
+			memcpy(__entry->top_waiter_comm, top_waiter->comm, TASK_COMM_LEN);
+			__entry->top_waiter_pid		= top_waiter->pid;
+			/*
+			 * The effective policy depends on the current policy of
+			 * the target task.
+			 */
+			__entry->new_policy		= effective_policy(
+								tsk->policy, top_waiter->prio);
+			__entry->new_nice		= task_nice(top_waiter);
+			__entry->new_rt_priority	= effective_rt_prio(
+								top_waiter->prio);
+			__entry->new_dl_runtime	= dl_prio(top_waiter->prio) ?
+								top_waiter->dl.dl_runtime : 0;
+			__entry->new_dl_deadline	= dl_prio(top_waiter->prio) ?
+								top_waiter->dl.dl_deadline : 0;
+			__entry->new_dl_period	= dl_prio(top_waiter->prio) ?
+								top_waiter->dl.dl_period : 0;
+		} else {
+			__entry->top_waiter_comm[0]	= '\0';
+			__entry->top_waiter_pid		= -1;
+			__entry->new_policy		= 0;
+			__entry->new_nice		= 0;
+			__entry->new_rt_priority	= 0;
+			__entry->new_dl_runtime	= 0;
+			__entry->new_dl_deadline	= 0;
+			__entry->new_dl_period	= 0;
+		}
+	),
+
+	TP_printk("comm=%s, pid=%d, old_policy=%s, old_nice=%d, "
+			"old_rt_priority=%u, old_dl_runtime=%Lu, "
+			"old_dl_deadline=%Lu, old_dl_period=%Lu, "
+			"top_waiter_comm=%s, top_waiter_pid=%d, new_policy=%s, "
+			"new_nice=%d, new_rt_priority=%u, "
+			"new_dl_runtime=%Lu, new_dl_deadline=%Lu, "
+			"new_dl_period=%Lu",
+		__entry->comm, __entry->pid,
+		__print_symbolic(__entry->old_policy, SCHEDULING_POLICY),
+		__entry->old_nice, __entry->old_rt_priority,
+		__entry->old_dl_runtime, __entry->old_dl_deadline,
+		__entry->old_dl_period,
+		__entry->top_waiter_comm, __entry->top_waiter_pid,
+		__entry->new_policy >= 0 ?
+			__print_symbolic(__entry->new_policy,
+				SCHEDULING_POLICY) : "",
+		__entry->new_nice, __entry->new_rt_priority,
+		__entry->new_dl_runtime, __entry->new_dl_deadline,
+		__entry->new_dl_period)
+);
+
 #ifdef CONFIG_DETECT_HUNG_TASK
 TRACE_EVENT(sched_process_hang,
 	TP_PROTO(struct task_struct *tsk),
-- 
1.9.1

[toc] | [prev] | [next] | [standalone]

#1491255 — Re: [RFC PATCH v2 0/5] Additional scheduling information in tracepoints

On Fri, Sep 23, 2016 at 12:49:30PM -0400, Julien Desfossez wrote:
> With this macro, we propose new versions of the sched_switch, sched_waking,
> sched_process_fork and sched_pi_setprio tracepoint probes that contain more
> scheduling information and get rid of the "prio" field. We also add the PI
> information to these tracepoints, so if a process is currently boosted, we show
> the name and PID of the top waiter. This allows to quickly see the blocking
> chain even if some of the trace background is missing.

Urgh.. bigger mess than ever :-(

So I thought the initial idea was to provide a 'blocked-on' tracepoint,
along with with the 'prio-changed' tracepoint, so you can reconstruct
the entire PI chain.

The only problem with that was initial state; when you start tracing (or
miss the start of a trace) its hard (impossible) to know what the
current state is.

But now you send a patch-set that just adds a metric ton of tracepoints.

This doesn't fix the current mess, it makes it worse :-(

[toc] | [prev] | [next] | [standalone]

#1491526 — Re: [RFC PATCH v2 0/5] Additional scheduling information in tracepoints

----- On Sep 26, 2016, at 8:27 AM, Peter Zijlstra peterz@infradead.org wrote:

> On Fri, Sep 23, 2016 at 12:49:30PM -0400, Julien Desfossez wrote:
>> With this macro, we propose new versions of the sched_switch, sched_waking,
>> sched_process_fork and sched_pi_setprio tracepoint probes that contain more
>> scheduling information and get rid of the "prio" field. We also add the PI
>> information to these tracepoints, so if a process is currently boosted, we show
>> the name and PID of the top waiter. This allows to quickly see the blocking
>> chain even if some of the trace background is missing.
> 
> Urgh.. bigger mess than ever :-(
> 
> So I thought the initial idea was to provide a 'blocked-on' tracepoint,
> along with with the 'prio-changed' tracepoint, so you can reconstruct
> the entire PI chain.
> 
> The only problem with that was initial state; when you start tracing (or
> miss the start of a trace) its hard (impossible) to know what the
> current state is.
> 
> But now you send a patch-set that just adds a metric ton of tracepoints.
> 
> This doesn't fix the current mess, it makes it worse :-(

There are actually four problems we try to tackle here with this
patchset:

1) Missing explicit priority change instrumentation

We're covering it by adding a new "sched_update_prio" callsite
and user-visible tracepoint.


2) Missing "blocked-on" information for PI

We're covering it by adding a new user-visible tracepoint to
the sched_pi_setprio callsite. The following fields provide
the blocked-on info:

top_waiter_comm, top_waiter_pid

We chose to add it in a new user-visible tracepoint rather
than the current sched_pi_setprio so the new event would not
expose the internal "prio" task struct field, which is an internal
implementation detail of the scheduler AFAIU, and could
go away eventually.

We could move those fields to the preexisting sched_pi_setprio
event if you prefer, but then we would have to keep the "oldprio"
and "newprio" fields forever.

I would not call this a "blocked-on" tracepoint, because it is
specific to PI. The general "blocking" concept imply blocking
on a resource (e.g. waitqueue), and we only know which PID we
were waiting for when we are later awakened. In the PI case,
we know which PID owns the resource we are blocked on.


3) Missing deadline scheduler instrumentation

We understood that exposing "prio" really does not cover the
deadline scheduler, as is clearly pointed out in your patchset.
We have added deadline scheduler info to a new set of user-visible
tracepoints, which are connected to the pre-existing tracepoint
callsites in the scheduler. We're therefore not "adding" scheduler
tracepoints in the fast-path source-code wise. We have named those
alternative versions with a "_prio" suffix.


4) Missing initial state

The sched_switch_prio tracepoint deals with the problem of missing
initial state: it's a tracepoint that occurs periodically, and we
can therefore get the initial state of a running thread when it
is scheduled. We chose to present it as an alternative tracepoint
from a user POV because we did not want to bloat the current
sched_switch event with lots of extra fields when prio information
is not needed.

Do you recommend that we bring those new extra fields into the
pre-existing tracepoints instead, even considering the extra
bloat ?

Thanks,

Mathieu

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web