Re: [patch 06/17] LTTng instrumentation - scheduler

From: Peter Zijlstra
Date: Wed Jul 16 2008 - 04:31:00 EST


On Tue, 2008-07-15 at 18:26 -0400, Mathieu Desnoyers wrote:
> plain text document attachment (lttng-instrumentation-scheduler.patch)
> Instrument the scheduler activity (sched_switch, migration, wakeups, wait for a
> task, signal delivery) and process/thread creation/destruction (fork, exit,
> kthread stop). Actually, kthread creation is not instrumented in this patch
> because it is architecture dependent. It allows to connect tracers such as
> ftrace which detects scheduling latencies, good/bad scheduler decisions. Tools
> like LTTng can export this scheduler information along with instrumentation of
> the rest of the kernel activity to perform post-mortem analysis on the scheduler
> activity.
>
> About the performance impact of tracepoints (which is comparable to markers),
> even without immediate values optimizations, tests done by Hideo Aoki on ia64
> show no regression. His test case was using hackbench on a kernel where
> scheduler instrumentation (about 5 events in code scheduler code) was added.
> See the "Tracepoints" patch header for performance result detail.
>
> Changelog :
> - Change instrumentation location and parameter to match ftrace instrumentation,
> previously done with kernel markers.
>
> Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@xxxxxxxxxx>
> CC: 'Peter Zijlstra' <peterz@xxxxxxxxxxxxx>
> CC: 'Steven Rostedt' <rostedt@xxxxxxxxxxx>
> CC: Thomas Gleixner <tglx@xxxxxxxxxxxxx>
> CC: Masami Hiramatsu <mhiramat@xxxxxxxxxx>
> CC: "Frank Ch. Eigler" <fche@xxxxxxxxxx>
> CC: 'Ingo Molnar' <mingo@xxxxxxx>
> CC: 'Hideo AOKI' <haoki@xxxxxxxxxx>
> CC: Takashi Nishiie <t-nishiie@xxxxxxxxxxxxxxxxxx>
> CC: Eduard - Gabriel Munteanu <eduard.munteanu@xxxxxxxxxxx>
> ---
> include/trace/sched.h | 45 +++++++++++++++++++++++++++++++++++++++++++++
> kernel/exit.c | 6 ++++++
> kernel/fork.c | 3 +++
> kernel/kthread.c | 5 +++++
> kernel/sched.c | 17 ++++++-----------
> kernel/signal.c | 3 +++
> 6 files changed, 68 insertions(+), 11 deletions(-)
>
> Index: linux-2.6-lttng/kernel/kthread.c
> ===================================================================
> --- linux-2.6-lttng.orig/kernel/kthread.c 2008-07-15 14:51:49.000000000 -0400
> +++ linux-2.6-lttng/kernel/kthread.c 2008-07-15 15:12:54.000000000 -0400
> @@ -13,6 +13,7 @@
> #include <linux/file.h>
> #include <linux/module.h>
> #include <linux/mutex.h>
> +#include <trace/sched.h>
>
> #define KTHREAD_NICE_LEVEL (-5)
>
> @@ -187,6 +188,8 @@ int kthread_stop(struct task_struct *k)
> /* It could exit after stop_info.k set, but before wake_up_process. */
> get_task_struct(k);
>
> + trace_sched_kthread_stop(k);
> +
> /* Must init completion *before* thread sees kthread_stop_info.k */
> init_completion(&kthread_stop_info.done);
> smp_wmb();
> @@ -202,6 +205,8 @@ int kthread_stop(struct task_struct *k)
> ret = kthread_stop_info.err;
> mutex_unlock(&kthread_stop_lock);
>
> + trace_sched_kthread_stop_ret(ret);
> +
> return ret;
> }
> EXPORT_SYMBOL(kthread_stop);

Why do we need two trace points in this function?

> Index: linux-2.6-lttng/kernel/sched.c
> ===================================================================
> --- linux-2.6-lttng.orig/kernel/sched.c 2008-07-15 14:51:50.000000000 -0400
> +++ linux-2.6-lttng/kernel/sched.c 2008-07-15 15:13:49.000000000 -0400
> @@ -71,6 +71,7 @@
> #include <linux/debugfs.h>
> #include <linux/ctype.h>
> #include <linux/ftrace.h>
> +#include <trace/sched.h>
>
> #include <asm/tlb.h>
> #include <asm/irq_regs.h>
> @@ -1987,6 +1988,7 @@ void wait_task_inactive(struct task_stru
> * just go back and repeat.
> */
> rq = task_rq_lock(p, &flags);
> + trace_sched_wait_task(rq, p);
> running = task_running(rq, p);
> on_rq = p->se.on_rq;
> task_rq_unlock(rq, &flags);
> @@ -2337,9 +2339,7 @@ out_activate:
> success = 1;
>
> out_running:
> - trace_mark(kernel_sched_wakeup,
> - "pid %d state %ld ## rq %p task %p rq->curr %p",
> - p->pid, p->state, rq, p, rq->curr);
> + trace_sched_wakeup(rq, p);
> check_preempt_curr(rq, p);
>
> p->state = TASK_RUNNING;
> @@ -2472,9 +2472,7 @@ void wake_up_new_task(struct task_struct
> p->sched_class->task_new(rq, p);
> inc_nr_running(rq);
> }
> - trace_mark(kernel_sched_wakeup_new,
> - "pid %d state %ld ## rq %p task %p rq->curr %p",
> - p->pid, p->state, rq, p, rq->curr);
> + trace_sched_wakeup_new(rq, p);
> check_preempt_curr(rq, p);
> #ifdef CONFIG_SMP
> if (p->sched_class->task_wake_up)
> @@ -2647,11 +2645,7 @@ context_switch(struct rq *rq, struct tas
> struct mm_struct *mm, *oldmm;
>
> prepare_task_switch(rq, prev, next);
> - trace_mark(kernel_sched_schedule,
> - "prev_pid %d next_pid %d prev_state %ld "
> - "## rq %p prev %p next %p",
> - prev->pid, next->pid, prev->state,
> - rq, prev, next);
> + trace_sched_switch(rq, prev, next);
> mm = next->mm;
> oldmm = prev->active_mm;
> /*
> @@ -2884,6 +2878,7 @@ static void sched_migrate_task(struct ta
> || unlikely(cpu_is_offline(dest_cpu)))
> goto out;
>
> + trace_sched_migrate_task(rq, p, dest_cpu);
> /* force the process onto the specified CPU */
> if (migrate_task(p, dest_cpu, &req)) {
> /* Need to wait for migration thread (might exit: take ref). */
> Index: linux-2.6-lttng/kernel/exit.c
> ===================================================================
> --- linux-2.6-lttng.orig/kernel/exit.c 2008-07-15 14:51:49.000000000 -0400
> +++ linux-2.6-lttng/kernel/exit.c 2008-07-15 15:12:54.000000000 -0400
> @@ -46,6 +46,7 @@
> #include <linux/resource.h>
> #include <linux/blkdev.h>
> #include <linux/task_io_accounting_ops.h>
> +#include <trace/sched.h>
>
> #include <asm/uaccess.h>
> #include <asm/unistd.h>
> @@ -149,6 +150,7 @@ static void __exit_signal(struct task_st
>
> static void delayed_put_task_struct(struct rcu_head *rhp)
> {
> + trace_sched_process_free(container_of(rhp, struct task_struct, rcu));
> put_task_struct(container_of(rhp, struct task_struct, rcu));
> }

It might make sense to write it like:

static void delayed_put_task_struct(struct rcu_head *rhp)
{
struct task_struct *tsk = container_of(rhp, struct task_struct, rcu);

trace_sched_process_free(tsk);
put_task_struct(tsk);
}

> @@ -1040,6 +1042,8 @@ NORET_TYPE void do_exit(long code)
>
> if (group_dead)
> acct_process();
> + trace_sched_process_exit(tsk);
> +
> exit_sem(tsk);
> exit_files(tsk);
> exit_fs(tsk);
> @@ -1524,6 +1528,8 @@ static long do_wait(enum pid_type type,
> struct task_struct *tsk;
> int flag, retval;
>
> + trace_sched_process_wait(pid);
> +
> add_wait_queue(&current->signal->wait_chldexit,&wait);
> repeat:
> /* If there is nothing that can match our critier just get out */
> Index: linux-2.6-lttng/kernel/fork.c
> ===================================================================
> --- linux-2.6-lttng.orig/kernel/fork.c 2008-07-15 14:51:49.000000000 -0400
> +++ linux-2.6-lttng/kernel/fork.c 2008-07-15 15:14:23.000000000 -0400
> @@ -56,6 +56,7 @@
> #include <linux/proc_fs.h>
> #include <linux/blkdev.h>
> #include <linux/magic.h>
> +#include <trace/sched.h>
>
> #include <asm/pgtable.h>
> #include <asm/pgalloc.h>
> @@ -1362,6 +1363,8 @@ long do_fork(unsigned long clone_flags,
> if (!IS_ERR(p)) {
> struct completion vfork;
>
> + trace_sched_process_fork(current, p);
> +
> nr = task_pid_vnr(p);
>
> if (clone_flags & CLONE_PARENT_SETTID)
> Index: linux-2.6-lttng/kernel/signal.c
> ===================================================================
> --- linux-2.6-lttng.orig/kernel/signal.c 2008-07-15 14:49:14.000000000 -0400
> +++ linux-2.6-lttng/kernel/signal.c 2008-07-15 15:12:54.000000000 -0400
> @@ -26,6 +26,7 @@
> #include <linux/freezer.h>
> #include <linux/pid_namespace.h>
> #include <linux/nsproxy.h>
> +#include <trace/sched.h>
>
> #include <asm/param.h>
> #include <asm/uaccess.h>
> @@ -807,6 +808,8 @@ static int send_signal(int sig, struct s
> struct sigpending *pending;
> struct sigqueue *q;
>
> + trace_sched_signal_send(sig, t);
> +
> assert_spin_locked(&t->sighand->siglock);
> if (!prepare_signal(sig, t))
> return 0;

Would it make sense to also put a trace point on receiveing a signal?

/me utterly clueless about the whole signal stuff.

> Index: linux-2.6-lttng/include/trace/sched.h
> ===================================================================
> --- /dev/null 1970-01-01 00:00:00.000000000 +0000
> +++ linux-2.6-lttng/include/trace/sched.h 2008-07-15 15:12:54.000000000 -0400
> @@ -0,0 +1,45 @@
> +#ifndef _TRACE_SCHED_H
> +#define _TRACE_SCHED_H
> +
> +#include <linux/sched.h>
> +#include <linux/tracepoint.h>
> +
> +DEFINE_TRACE(sched_kthread_stop,
> + TPPROTO(struct task_struct *t),
> + TPARGS(t));
> +DEFINE_TRACE(sched_kthread_stop_ret,
> + TPPROTO(int ret),
> + TPARGS(ret));
> +DEFINE_TRACE(sched_wait_task,
> + TPPROTO(struct rq *rq, struct task_struct *p),
> + TPARGS(rq, p));
> +DEFINE_TRACE(sched_wakeup,
> + TPPROTO(struct rq *rq, struct task_struct *p),
> + TPARGS(rq, p));
> +DEFINE_TRACE(sched_wakeup_new,
> + TPPROTO(struct rq *rq, struct task_struct *p),
> + TPARGS(rq, p));
> +DEFINE_TRACE(sched_switch,
> + TPPROTO(struct rq *rq, struct task_struct *prev,
> + struct task_struct *next),
> + TPARGS(rq, prev, next));
> +DEFINE_TRACE(sched_migrate_task,
> + TPPROTO(struct rq *rq, struct task_struct *p, int dest_cpu),
> + TPARGS(rq, p, dest_cpu));
> +DEFINE_TRACE(sched_process_free,
> + TPPROTO(struct task_struct *p),
> + TPARGS(p));
> +DEFINE_TRACE(sched_process_exit,
> + TPPROTO(struct task_struct *p),
> + TPARGS(p));
> +DEFINE_TRACE(sched_process_wait,
> + TPPROTO(struct pid *pid),
> + TPARGS(pid));
> +DEFINE_TRACE(sched_process_fork,
> + TPPROTO(struct task_struct *parent, struct task_struct *child),
> + TPARGS(parent, child));
> +DEFINE_TRACE(sched_signal_send,
> + TPPROTO(int sig, struct task_struct *p),
> + TPARGS(sig, p));
> +
> +#endif
>

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/