Tracepoints v4 for linux-next

Add rcu_read_lock_sched() and rcu_read_unlock_sched() to rcupdate.h to match the recently added write-side call_rcu_sched() and rcu_barrier_sched(). They also match the no-so-recently-added synchronize_sched().

It will help following matching use of the update/read lock primitives. Those new read lock will replace preempt_disable()/enable() used in pair with RCU-classic synchronization.

Signed-off-by Mathieu Desnoyers <[email protected]>

CC Peter Zijlstra <[email protected]>

CC Paul E McKenney <[email protected]>

CC [email protected]

---
 include/linux/rcupdate.h |   18 ++++++++++++++++++
 1 file changed, 18 insertions(+)

Index: linux-2.6-lttng/include/linux/rcupdate.h
===================================================================

include/linux/rcupdate.h +18 -0

@@ -133,6 +133,24 @@ struct rcu_head {
 #define rcu_read_unlock_bh() __rcu_read_unlock_bh()
 
 /**
+ * rcu_read_lock_sched - mark the beginning of a RCU-classic critical section
+ *
+ * Should be used with either
+ * - synchronize_sched()
+ * or
+ * - call_rcu_sched() and rcu_barrier_sched()
+ * on the write-side to insure proper synchronization.
+ */
+#define rcu_read_lock_sched() preempt_disable()
+
+/*
+ * rcu_read_unlock_sched - marks the end of a RCU-classic critical section
+ *
+ * See rcu_read_lock_sched for more information.
+ */
+#define rcu_read_unlock_sched() preempt_enable()
+
+/**
  * rcu_dereference - fetch an RCU-protected pointer in an
  * RCU read-side critical section.  This pointer may later
  * be safely dereferenced.

Signature · 4 lines

-- 
Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Quoted 7 lines · Mathieu Desnoyers

Add rcu_read_lock_sched() and rcu_read_unlock_sched() to rcupdate.h to match the recently added write-side call_rcu_sched() and rcu_barrier_sched(). They also match the no-so-recently-added synchronize_sched().

It will help following matching use of the update/read lock primitives. Those new read lock will replace preempt_disable()/enable() used in pair with RCU-classic synchronization.

Looks good, but...

synchronize_sched(), call_rcu_sched(), and rcu_barrier_sched() can also pair up with:

o local_irq_save() and local_irq_restore()
o local_irq_disable() and local_irq_enable()

o spin_lock_irqsave() and spin_lock_irqrestore()

o etc. etc.

I do very much like the idea of marking the intent of matching with RCU, but am getting a bit queasy about adding rcu_read_lock_sched_irq() and so on.

Thoughts? Other than having an rcu_read_lock_sched_nop() or some other window-dressing macro that doesn't really do anything? (Which might really be the right thing to do...)

+++ linux-2.6-lttng/include/linux/tracepoint.h 2008-07-15 17:35:19.000000000 -0400

include/linux/tracepoint.h new file +38 -0

@@ -0,0 +1,127 @@
+#ifndef _LINUX_TRACEPOINT_H
+#define _LINUX_TRACEPOINT_H
+
+/*
+ * Kernel Tracepoint API.
+ *
+ * See Documentation/tracepoint.txt.
+ *
+ * (C) Copyright 2008 Mathieu Desnoyers <[email protected]>
+ *
+ * Heavily inspired from the Linux Kernel Markers.
+ *
+ * This file is released under the GPLv2.
+ * See the file COPYING for more details.
+ */
+
+#include <linux/types.h>
+#include <linux/rcupdate.h>
+
+struct module;
+struct tracepoint;
+
+struct tracepoint {
+	const char *name;		/* Tracepoint name */
+	int state;			/* State. */
+	void **funcs;
+} __attribute__((aligned(8)));
+
+
+#define TPPROTO(args...)	args
+#define TPARGS(args...)		args
+
+#ifdef CONFIG_TRACEPOINTS
+
+/*
+ * it_func[0] is never NULL because there is at least one element in the array
+ * when the array itself is non NULL.
+ */

include/linux/tracepoint.h new file +3 -0

+		}							\
+		rcu_read_unlock_sched();				\
+	} while (0)

[Added Paul McKenney to CC]

Quoted 46 lines · Mathieu Desnoyers

+++ linux-2.6-lttng/include/linux/tracepoint.h 2008-07-15 17:35:19.000000000 -0400

include/linux/tracepoint.h new file +44 -0

@@ -0,0 +1,127 @@
+#ifndef _LINUX_TRACEPOINT_H
+#define _LINUX_TRACEPOINT_H
+
+/*
+ * Kernel Tracepoint API.
+ *
+ * See Documentation/tracepoint.txt.
+ *
+ * (C) Copyright 2008 Mathieu Desnoyers <[email protected]>
+ *
+ * Heavily inspired from the Linux Kernel Markers.
+ *
+ * This file is released under the GPLv2.
+ * See the file COPYING for more details.
+ */
+
+#include <linux/types.h>
+#include <linux/rcupdate.h>
+
+struct module;
+struct tracepoint;
+
+struct tracepoint {
+	const char *name;		/* Tracepoint name */
+	int state;			/* State. */
+	void **funcs;
+} __attribute__((aligned(8)));
+
+
+#define TPPROTO(args...)	args
+#define TPARGS(args...)		args
+
+#ifdef CONFIG_TRACEPOINTS
+
+/*
+ * it_func[0] is never NULL because there is at least one element in the array
+ * when the array itself is non NULL.
+ */
+#define __DO_TRACE(tp, proto, args)					\
+	do {								\
+		void **it_func;						\
+									\
+		rcu_read_lock_sched();					\
+		it_func = rcu_dereference((tp)->funcs);			\

include/linux/tracepoint.h line 48

Quoted 4 lines

include/linux/tracepoint.h new file +4 -0

+		if (it_func) {						\
+			do {						\
+				((void(*)(proto))(*it_func))(args);	\
+			} while (*(++it_func));				\

OK, I still don't understand the concept of the rcu_dereference, but why is it needed for the first assignment of it_func but not the ++? Is it only needed with the (tp)->funcs?

-- Steve

Quoted 3 lines

include/linux/tracepoint.h new file +3 -0

+		}							\
+		rcu_read_unlock_sched();				\
+	} while (0)

Quoted 50 lines · * Steven Rostedt ([email protected]) wrote:

[Added Paul McKenney to CC]

Quoted 46 lines · Mathieu Desnoyers

+++ linux-2.6-lttng/include/linux/tracepoint.h 2008-07-15 17:35:19.000000000 -0400

include/linux/tracepoint.h new file +44 -0

@@ -0,0 +1,127 @@
+#ifndef _LINUX_TRACEPOINT_H
+#define _LINUX_TRACEPOINT_H
+
+/*
+ * Kernel Tracepoint API.
+ *
+ * See Documentation/tracepoint.txt.
+ *
+ * (C) Copyright 2008 Mathieu Desnoyers <[email protected]>
+ *
+ * Heavily inspired from the Linux Kernel Markers.
+ *
+ * This file is released under the GPLv2.
+ * See the file COPYING for more details.
+ */
+
+#include <linux/types.h>
+#include <linux/rcupdate.h>
+
+struct module;
+struct tracepoint;
+
+struct tracepoint {
+	const char *name;		/* Tracepoint name */
+	int state;			/* State. */
+	void **funcs;
+} __attribute__((aligned(8)));
+
+
+#define TPPROTO(args...)	args
+#define TPARGS(args...)		args
+
+#ifdef CONFIG_TRACEPOINTS
+
+/*
+ * it_func[0] is never NULL because there is at least one element in the array
+ * when the array itself is non NULL.
+ */
+#define __DO_TRACE(tp, proto, args)					\
+	do {								\
+		void **it_func;						\
+									\
+		rcu_read_lock_sched();					\
+		it_func = rcu_dereference((tp)->funcs);			\

Quoted 9 lines

include/linux/tracepoint.h line 48

Quoted 4 lines

include/linux/tracepoint.h new file +4 -0

+		if (it_func) {						\
+			do {						\
+				((void(*)(proto))(*it_func))(args);	\
+			} while (*(++it_func));				\

OK, I still don't understand the concept of the rcu_dereference, but why is it needed for the first assignment of it_func but not the ++? Is it only needed with the (tp)->funcs?

rcu_dereference copies the tp->funcs pointer on the local stack and then puts a smp_read_barrier_depends() to make sure that the tp->funcs read occurs before the actual use of the data (here, it is the array elements) where the tp->funcs pointer copy points to.

What happens here is that the tp->funcs pointer, pointing to the beginning of the array, is only read once. Afterward, the iterator is located on the stack and therefore incrementing it does not need to be protected by any other kind of barrier whatsoever because only the original tp->funcs read was a RCU pointer read.

Then, as you probably know, the update side performs a rcu_assign_pointer which does a smp_wmb before the pointer assignment to make sure the array data has been populated before the pointer assignment.

Mathieu

Quoted 7 lines

-- Steve

Quoted 3 lines

include/linux/tracepoint.h new file +3 -0

+		}							\
+		rcu_read_unlock_sched();				\
+	} while (0)

Signature · 2 lines

Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Quoted 72 lines · Mathieu Desnoyers

Quoted 50 lines · * Steven Rostedt ([email protected]) wrote:

[Added Paul McKenney to CC]

Quoted 46 lines · Mathieu Desnoyers

+++ linux-2.6-lttng/include/linux/tracepoint.h 2008-07-15 17:35:19.000000000 -0400

include/linux/tracepoint.h new file +44 -0

@@ -0,0 +1,127 @@
+#ifndef _LINUX_TRACEPOINT_H
+#define _LINUX_TRACEPOINT_H
+
+/*
+ * Kernel Tracepoint API.
+ *
+ * See Documentation/tracepoint.txt.
+ *
+ * (C) Copyright 2008 Mathieu Desnoyers <[email protected]>
+ *
+ * Heavily inspired from the Linux Kernel Markers.
+ *
+ * This file is released under the GPLv2.
+ * See the file COPYING for more details.
+ */
+
+#include <linux/types.h>
+#include <linux/rcupdate.h>
+
+struct module;
+struct tracepoint;
+
+struct tracepoint {
+	const char *name;		/* Tracepoint name */
+	int state;			/* State. */
+	void **funcs;
+} __attribute__((aligned(8)));
+
+
+#define TPPROTO(args...)	args
+#define TPARGS(args...)		args
+
+#ifdef CONFIG_TRACEPOINTS
+
+/*
+ * it_func[0] is never NULL because there is at least one element in the array
+ * when the array itself is non NULL.
+ */
+#define __DO_TRACE(tp, proto, args)					\
+	do {								\
+		void **it_func;						\
+									\
+		rcu_read_lock_sched();					\
+		it_func = rcu_dereference((tp)->funcs);			\

Quoted 9 lines

include/linux/tracepoint.h line 48

Quoted 4 lines

include/linux/tracepoint.h new file +4 -0

+		if (it_func) {						\
+			do {						\
+				((void(*)(proto))(*it_func))(args);	\
+			} while (*(++it_func));				\

OK, I still don't understand the concept of the rcu_dereference, but why is it needed for the first assignment of it_func but not the ++? Is it only needed with the (tp)->funcs?

rcu_dereference copies the tp->funcs pointer on the local stack and then puts a smp_read_barrier_depends() to make sure that the tp->funcs read occurs before the actual use of the data (here, it is the array elements) where the tp->funcs pointer copy points to.

What happens here is that the tp->funcs pointer, pointing to the beginning of the array, is only read once. Afterward, the iterator is located on the stack and therefore incrementing it does not need to be protected by any other kind of barrier whatsoever because only the original tp->funcs read was a RCU pointer read.

Quoted 4 lines

Then, as you probably know, the update side performs a rcu_assign_pointer which does a smp_wmb before the pointer assignment to make sure the array data has been populated before the pointer assignment.

So the update side inserts a whole new array, rather than just the first entry, correct? If so, I am happy.

Thanx, Paul

Quoted 13 lines

Mathieu

Quoted 7 lines

-- Steve

Quoted 3 lines

include/linux/tracepoint.h new file +3 -0

+		}							\
+		rcu_read_unlock_sched();				\
+	} while (0)

Signature · 2 lines

Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

kernel/tracepoint.c new file +19 -0

+static void *
+tracepoint_entry_remove_probe(struct tracepoint_entry *entry, void *probe)
+{
+	int nr_probes = 0, nr_del = 0, i;
+	void **old, **new;
+
+	old = entry->funcs;
+
+	debug_print_probes(entry);
+	/* (N -> M), (N > 1, M >= 0) probes */
+	for (nr_probes = 0; old[nr_probes]; nr_probes++) {
+		if ((!probe || old[nr_probes] == probe))
+			nr_del++;
+	}
+
+	if (nr_probes - nr_del == 0) {
+		/* N -> 0, (N > 1) */
+		entry->funcs = NULL;
+		entry->refcount = 0;

kernel/tracepoint.c new file +10 -0

+		for (i = 0; old[i]; i++)
+			if ((probe && old[i] != probe))
+				new[j++] = old[i];
+		entry->refcount = nr_probes - nr_del;
+		entry->funcs = new;
+	}
+	debug_print_probes(entry);
+	return old;
+}
+

Quoted 24 lines · Mathieu Desnoyers

kernel/tracepoint.c new file +24 -0

+static void *
+tracepoint_entry_remove_probe(struct tracepoint_entry *entry, void *probe)
+{
+	int nr_probes = 0, nr_del = 0, i;
+	void **old, **new;
+
+	old = entry->funcs;
+
+	debug_print_probes(entry);
+	/* (N -> M), (N > 1, M >= 0) probes */
+	for (nr_probes = 0; old[nr_probes]; nr_probes++) {
+		if ((!probe || old[nr_probes] == probe))
+			nr_del++;
+	}
+
+	if (nr_probes - nr_del == 0) {
+		/* N -> 0, (N > 1) */
+		entry->funcs = NULL;
+		entry->refcount = 0;
+		debug_print_probes(entry);
+		return old;
+	} else {
+		int j = 0;
+		/* N -> M, (N > 1, M > 0) */

kernel/tracepoint.c line 154

Quoted 5 lines

kernel/tracepoint.c new file +5 -0

+		/* + 1 for NULL */
+		new = kzalloc((nr_probes - nr_del + 1)
+			* sizeof(void *), GFP_KERNEL);
+		if (new == NULL)
+			return ERR_PTR(-ENOMEM);

Hmm, on failure of allocating a new array, we could simply use the old array, and remove the one probe from it instead of just failing.

-- Steve

Quoted 10 lines

kernel/tracepoint.c new file +10 -0

+		for (i = 0; old[i]; i++)
+			if ((probe && old[i] != probe))
+				new[j++] = old[i];
+		entry->refcount = nr_probes - nr_del;
+		entry->funcs = new;
+	}
+	debug_print_probes(entry);
+	return old;
+}
+

Quoted 10 lines

Quoted 10 lines

kernel/tracepoint.c new file +10 -0

+
+	if (nr_probes - nr_del == 0) {
+		/* N -> 0, (N > 1) */
+		entry->funcs = NULL;
+		entry->refcount = 0;
+		debug_print_probes(entry);
+		return old;
+	} else {
+		int j = 0;
+		/* N -> M, (N > 1, M > 0) */

Quoted 9 lines

kernel/tracepoint.c line 154

Quoted 5 lines

kernel/tracepoint.c new file +5 -0

+		/* + 1 for NULL */
+		new = kzalloc((nr_probes - nr_del + 1)
+			* sizeof(void *), GFP_KERNEL);
+		if (new == NULL)
+			return ERR_PTR(-ENOMEM);

Hmm, on failure of allocating a new array, we could simply use the old array, and remove the one probe from it instead of just failing.

Nay, because of RCU constraints. So we have the readers in the current RCU window who need to see the old version, and readers of the following window who need to see the next version. Both can live at the same time on the system. We cannot reuse the same memory to perform the array shrink without corrupting the data seen by the previous readers. We really have to perform a copy here.

Index: linux-2.6-lttng/kernel/tracepoint.c
===================================================================

kernel/tracepoint.c new file +0 -0

kernel/tracepoint.c new file +7 -0

+/*
+ * Tracepoint hash table, containing the active tracepoints.
+ * Protected by tracepoints_mutex.
+ */
+#define TRACEPOINT_HASH_BITS 6
+#define TRACEPOINT_TABLE_SIZE (1 << TRACEPOINT_HASH_BITS)
+

kernel/tracepoint.c new file +10 -0

+	hlist_for_each_entry(e, node, head, hlist) {
+		if (!strcmp(name, e->name))
+			return e;
+	}
+	return NULL;
+}
+
+/*
+ * Add the tracepoint to the tracepoint hash table. Must be called with
+ * tracepoints_mutex held.

kernel/tracepoint.c new file +26 -0

+	hlist_for_each_entry(e, node, head, hlist) {
+		if (!strcmp(name, e->name)) {
+			printk(KERN_NOTICE
+				"tracepoint %s busy\n", name);
+			return ERR_PTR(-EEXIST);	/* Already there */
+		}
+	}
+	/*
+	 * Using kmalloc here to allocate a variable length element. Could
+	 * cause some memory fragmentation if overused.
+	 */
+	e = kmalloc(sizeof(struct tracepoint_entry) + name_len, GFP_KERNEL);
+	if (!e)
+		return ERR_PTR(-ENOMEM);
+	memcpy(&e->name[0], name, name_len);
+	e->funcs = NULL;
+	e->refcount = 0;
+	e->rcu_pending = 0;
+	hlist_add_head(&e->hlist, head);
+	return e;
+}
+
+/*
+ * Remove the tracepoint from the tracepoint hash table. Must be called with
+ * mutex_lock held.
+ */

kernel/tracepoint.c new file +7 -0

+	hlist_for_each_entry(e, node, head, hlist) {
+		if (!strcmp(name, e->name)) {
+			found = 1;
+			break;
+		}
+	}
+	if (!found)

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 <[email protected]>

CC 'Peter Zijlstra' <[email protected]>

CC 'Steven Rostedt' <[email protected]>

CC Thomas Gleixner <[email protected]>

CC Masami Hiramatsu <[email protected]>

CC "Frank Ch. Eigler" <[email protected]>

CC 'Ingo Molnar' <[email protected]>

CC 'Hideo AOKI' <[email protected]>

CC Takashi Nishiie <[email protected]>

CC Eduard - Gabriel Munteanu <[email protected]>

---
 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
===================================================================

kernel/kthread.c +3 -0

@@ -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();

Index: linux-2.6-lttng/kernel/sched.c
===================================================================

kernel/sched.c +6 -11

@@ -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
===================================================================

kernel/exit.c +1 -0

@@ -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>

kernel/exit.c +4 -0

@@ -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
===================================================================

kernel/fork.c +3 -0

@@ -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
===================================================================

kernel/signal.c +1 -0

@@ -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>

Index: linux-2.6-lttng/include/trace/sched.h
===================================================================

include/trace/sched.h new file +45 -0

@@ -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

Quoted 64 lines · Mathieu Desnoyers

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 <[email protected]>

CC 'Peter Zijlstra' <[email protected]>

CC 'Steven Rostedt' <[email protected]>

CC Thomas Gleixner <[email protected]>

CC Masami Hiramatsu <[email protected]>

CC "Frank Ch. Eigler" <[email protected]>

CC 'Ingo Molnar' <[email protected]>

CC 'Hideo AOKI' <[email protected]>

CC Takashi Nishiie <[email protected]>

CC Eduard - Gabriel Munteanu <[email protected]>

---
 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
===================================================================

kernel/kthread.c +3 -0

@@ -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);
 

kernel/kthread.c int kthread_stop(struct task_struct *k) · line 212

Quoted 5 lines

kernel/kthread.c +2 -0

+	trace_sched_kthread_stop_ret(ret);
+
 	return ret;
 }
 EXPORT_SYMBOL(kthread_stop);

Why do we need two trace points in this function?

Quoted 76 lines

Index: linux-2.6-lttng/kernel/sched.c
===================================================================

kernel/sched.c +6 -11

@@ -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
===================================================================

kernel/exit.c +1 -0

@@ -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>

kernel/exit.c static void __exit_signal(struct task_st · line 155

Quoted 6 lines

kernel/exit.c +1 -0

@@ -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);
}

Quoted 52 lines

kernel/exit.c +4 -0

@@ -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
===================================================================

kernel/fork.c +3 -0

@@ -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
===================================================================

kernel/signal.c +1 -0

@@ -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>

kernel/signal.c static int send_signal(int sig, struct s · line 815

Quoted 8 lines

kernel/signal.c +2 -0

@@ -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.

Quoted 51 lines

Index: linux-2.6-lttng/include/trace/sched.h
===================================================================

include/trace/sched.h new file +45 -0

@@ -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

plain text document attachment (lttng-instrumentation-timer.patch) Instrument timer activity (timer set, expired, current time updates) to keep information about the "real time" flow within the kernel. It can be used by a trace analysis tool to synchronize information coming from various sources, e.g. to merge traces with system logs.

Those tracepoints are used by LTTng.

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.

Signed-off-by Mathieu Desnoyers <[email protected]>

CC 'Ingo Molnar' <[email protected]>

CC "David S. Miller" <[email protected]>

CC Masami Hiramatsu <[email protected]>

CC 'Peter Zijlstra' <[email protected]>

CC "Frank Ch. Eigler" <[email protected]>

CC 'Hideo AOKI' <[email protected]>

CC Takashi Nishiie <[email protected]>

CC 'Steven Rostedt' <[email protected]>

CC Eduard - Gabriel Munteanu <[email protected]>

---
 include/trace/timer.h |   24 ++++++++++++++++++++++++
 kernel/itimer.c       |    5 +++++
 kernel/timer.c        |    8 +++++++-
 3 files changed, 36 insertions(+), 1 deletion(-)

Index: linux-2.6-lttng/kernel/itimer.c
===================================================================

kernel/itimer.c +5 -0

@@ -12,6 +12,7 @@
 #include <linux/time.h>
 #include <linux/posix-timers.h>
 #include <linux/hrtimer.h>
+#include <trace/timer.h>
 
 #include <asm/uaccess.h>
 

@@ -132,6 +133,8 @@ enum hrtimer_restart it_real_fn(struct h
 	struct signal_struct *sig =
 		container_of(timer, struct signal_struct, real_timer);
 
+	trace_timer_itimer_expired(sig);
+
 	kill_pid_info(SIGALRM, SEND_SIG_PRIV, sig->leader_pid);
 
 	return HRTIMER_NORESTART;

@@ -157,6 +160,8 @@ int do_setitimer(int which, struct itime
 	    !timeval_valid(&value->it_interval))
 		return -EINVAL;
 
+	trace_timer_itimer_set(which, value);
+
 	switch (which) {
 	case ITIMER_REAL:
 again:

Index: linux-2.6-lttng/kernel/timer.c
===================================================================

kernel/timer.c +3 -0

@@ -37,12 +37,14 @@
 #include <linux/delay.h>
 #include <linux/tick.h>
 #include <linux/kallsyms.h>
+#include <trace/timer.h>
 
 #include <asm/uaccess.h>
 #include <asm/unistd.h>
 #include <asm/div64.h>
 #include <asm/timex.h>
 #include <asm/io.h>
+#include <asm/irq_regs.h>
 
 u64 jiffies_64 __cacheline_aligned_in_smp = INITIAL_JIFFIES;
 

@@ -288,6 +290,7 @@ static void internal_add_timer(struct tv
 		i = (expires >> (TVR_BITS + 3 * TVN_BITS)) & TVN_MASK;
 		vec = base->tv5.vec + i;
 	}
+	trace_timer_set(timer);
 	/*
 	 * Timers are FIFO:
 	 */

kernel/timer.c +3 -1

 #ifdef __ARCH_WANT_SYS_ALARM

@@ -1147,7 +1151,9 @@ asmlinkage long sys_getegid(void)
 
 static void process_timeout(unsigned long __data)
 {
-	wake_up_process((struct task_struct *)__data);
+	struct task_struct *task = (struct task_struct *)__data;
+	trace_timer_timeout(task);
+	wake_up_process(task);
 }
 
 /**

Index: linux-2.6-lttng/include/trace/timer.h
===================================================================

include/trace/timer.h new file +24 -0

@@ -0,0 +1,24 @@
+#ifndef _TRACE_TIMER_H
+#define _TRACE_TIMER_H
+
+#include <linux/tracepoint.h>
+
+DEFINE_TRACE(timer_itimer_expired,
+	TPPROTO(struct signal_struct *sig),
+	TPARGS(sig));
+DEFINE_TRACE(timer_itimer_set,
+	TPPROTO(int which, struct itimerval *value),
+	TPARGS(which, value));
+DEFINE_TRACE(timer_set,
+	TPPROTO(struct timer_list *timer),
+	TPARGS(timer));
+/*
+ * xtime_lock is taken when kernel_timer_update_time tracepoint is reached.
+ */
+DEFINE_TRACE(timer_update_time,
+	TPPROTO(struct timespec *_xtime, struct timespec *_wall_to_monotonic),
+	TPARGS(_xtime, _wall_to_monotonic));
+DEFINE_TRACE(timer_timeout,
+	TPPROTO(struct task_struct *p),
+	TPARGS(p));
+#endif

Quoted 88 lines · Mathieu Desnoyers

plain text document attachment (lttng-instrumentation-timer.patch) Instrument timer activity (timer set, expired, current time updates) to keep information about the "real time" flow within the kernel. It can be used by a trace analysis tool to synchronize information coming from various sources, e.g. to merge traces with system logs.

Those tracepoints are used by LTTng.

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.

Signed-off-by Mathieu Desnoyers <[email protected]>

CC 'Ingo Molnar' <[email protected]>

CC "David S. Miller" <[email protected]>

CC Masami Hiramatsu <[email protected]>

CC 'Peter Zijlstra' <[email protected]>

CC "Frank Ch. Eigler" <[email protected]>

CC 'Hideo AOKI' <[email protected]>

CC Takashi Nishiie <[email protected]>

CC 'Steven Rostedt' <[email protected]>

CC Eduard - Gabriel Munteanu <[email protected]>

---
 include/trace/timer.h |   24 ++++++++++++++++++++++++
 kernel/itimer.c       |    5 +++++
 kernel/timer.c        |    8 +++++++-
 3 files changed, 36 insertions(+), 1 deletion(-)

Index: linux-2.6-lttng/kernel/itimer.c
===================================================================

kernel/itimer.c +5 -0

@@ -12,6 +12,7 @@
 #include <linux/time.h>
 #include <linux/posix-timers.h>
 #include <linux/hrtimer.h>
+#include <trace/timer.h>
 
 #include <asm/uaccess.h>
 

@@ -132,6 +133,8 @@ enum hrtimer_restart it_real_fn(struct h
 	struct signal_struct *sig =
 		container_of(timer, struct signal_struct, real_timer);
 
+	trace_timer_itimer_expired(sig);
+
 	kill_pid_info(SIGALRM, SEND_SIG_PRIV, sig->leader_pid);
 
 	return HRTIMER_NORESTART;

@@ -157,6 +160,8 @@ int do_setitimer(int which, struct itime
 	    !timeval_valid(&value->it_interval))
 		return -EINVAL;
 
+	trace_timer_itimer_set(which, value);
+
 	switch (which) {
 	case ITIMER_REAL:
 again:

Index: linux-2.6-lttng/kernel/timer.c
===================================================================

kernel/timer.c +3 -0

@@ -37,12 +37,14 @@
 #include <linux/delay.h>
 #include <linux/tick.h>
 #include <linux/kallsyms.h>
+#include <trace/timer.h>
 
 #include <asm/uaccess.h>
 #include <asm/unistd.h>
 #include <asm/div64.h>
 #include <asm/timex.h>
 #include <asm/io.h>
+#include <asm/irq_regs.h>
 
 u64 jiffies_64 __cacheline_aligned_in_smp = INITIAL_JIFFIES;
 

@@ -288,6 +290,7 @@ static void internal_add_timer(struct tv
 		i = (expires >> (TVR_BITS + 3 * TVN_BITS)) & TVN_MASK;
 		vec = base->tv5.vec + i;
 	}
+	trace_timer_set(timer);
 	/*
 	 * Timers are FIFO:
 	 */

kernel/timer.c void do_timer(unsigned long ticks) · line 1073

Quoted 5 lines

kernel/timer.c +1 -0

@@ -1066,6 +1069,7 @@ void do_timer(unsigned long ticks)
 {
 	jiffies_64 += ticks;
 	update_times(ticks);
+	trace_timer_update_time(&xtime, &wall_to_monotonic);
 }

This is a very dangerous trace point - we're holding xtime lock here.

Ah, I see you make that comment below too, are you sure you want to do this?

Thomas, any input?

Quoted 42 lines

kernel/timer.c +3 -1

 #ifdef __ARCH_WANT_SYS_ALARM

@@ -1147,7 +1151,9 @@ asmlinkage long sys_getegid(void)
 
 static void process_timeout(unsigned long __data)
 {
-	wake_up_process((struct task_struct *)__data);
+	struct task_struct *task = (struct task_struct *)__data;
+	trace_timer_timeout(task);
+	wake_up_process(task);
 }
 
 /**

Index: linux-2.6-lttng/include/trace/timer.h
===================================================================

include/trace/timer.h new file +24 -0

@@ -0,0 +1,24 @@
+#ifndef _TRACE_TIMER_H
+#define _TRACE_TIMER_H
+
+#include <linux/tracepoint.h>
+
+DEFINE_TRACE(timer_itimer_expired,
+	TPPROTO(struct signal_struct *sig),
+	TPARGS(sig));
+DEFINE_TRACE(timer_itimer_set,
+	TPPROTO(int which, struct itimerval *value),
+	TPARGS(which, value));
+DEFINE_TRACE(timer_set,
+	TPPROTO(struct timer_list *timer),
+	TPARGS(timer));
+/*
+ * xtime_lock is taken when kernel_timer_update_time tracepoint is reached.
+ */
+DEFINE_TRACE(timer_update_time,
+	TPPROTO(struct timespec *_xtime, struct timespec *_wall_to_monotonic),
+	TPARGS(_xtime, _wall_to_monotonic));
+DEFINE_TRACE(timer_timeout,
+	TPPROTO(struct task_struct *p),
+	TPARGS(p));
+#endif

Quoted 6 lines · Mathieu Desnoyers

/*
* Low level drivers may need that to know if they can schedule in

(quoted diff) +0 -0

@@ -601,6 +603,7 @@ asmlinkage int printk(const char *fmt, .
 	int r;
 

kernel/printk.c asmlinkage int printk(const char *fmt, . · line 606

Quoted 2 lines

kernel/printk.c +1 -0

 	va_start(args, fmt);
+	trace_kernel_printk(__builtin_return_address(0));

BTW, ftrace.h has macros that let you use CALLER_ADDR0 for __builtin_return_address. It also converts it from a pointer to a long, but makes the code look prettier.

Quoted 5 lines

kernel/printk.c +0 -0

 	r = vprintk(fmt, args);
 	va_end(args);
 

kernel/printk.c asmlinkage int vprintk(const char *fmt, · line 688

Quoted 9 lines

kernel/printk.c +3 -0

@@ -677,6 +680,9 @@ asmlinkage int vprintk(const char *fmt,
 	raw_local_irq_save(flags);
 	this_cpu = smp_processor_id();
 
+	trace_kernel_vprintk(__builtin_return_address(0),
+		printk_buf, printed_len);
+
 	/*
 	 * Ouch, printk recursed into itself!
 	 */

-- Steve

Quoted 9 lines · * Steven Rostedt ([email protected]) wrote:

Quoted 6 lines · Mathieu Desnoyers

/*
* Low level drivers may need that to know if they can schedule in

(quoted diff) +0 -0

@@ -601,6 +603,7 @@ asmlinkage int printk(const char *fmt, .
 	int r;
 

Quoted 7 lines

kernel/printk.c asmlinkage int printk(const char *fmt, . · line 606

Quoted 2 lines

kernel/printk.c +1 -0

 	va_start(args, fmt);
+	trace_kernel_printk(__builtin_return_address(0));

BTW, ftrace.h has macros that let you use CALLER_ADDR0 for __builtin_return_address. It also converts it from a pointer to a long, but makes the code look prettier.

include/linux/kernel.h:#define _RET_IP_ (unsigned long)__builtin_return_address(0)

Hrm, did not see this one. So I guess we can both switch to it ?

Thanks for pointing this out,

plain text document attachment (lttng-instrumentation-filemap.patch) Instrumentation of waits caused by memory accesses on mmap regions.

Those tracepoints are used by LTTng.

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.

Signed-off-by Mathieu Desnoyers <[email protected]>

CC [email protected]

CC Dave Hansen <[email protected]>

CC Masami Hiramatsu <[email protected]>

CC 'Peter Zijlstra' <[email protected]>

CC "Frank Ch. Eigler" <[email protected]>

CC 'Ingo Molnar' <[email protected]>

CC 'Hideo AOKI' <[email protected]>

CC Takashi Nishiie <[email protected]>

CC 'Steven Rostedt' <[email protected]>

CC Eduard - Gabriel Munteanu <[email protected]>

---
 include/trace/filemap.h |   13 +++++++++++++
 mm/filemap.c            |    3 +++
 2 files changed, 16 insertions(+)

Index: linux-2.6-lttng/mm/filemap.c
===================================================================

mm/filemap.c +1 -0

@@ -33,6 +33,7 @@
 #include <linux/cpuset.h>
 #include <linux/hardirq.h> /* for BUG_ON(!in_atomic()) only */
 #include <linux/memcontrol.h>
+#include <trace/filemap.h>
 #include "internal.h"
 
 /*

Index: linux-2.6-lttng/include/trace/filemap.h
===================================================================

include/trace/filemap.h new file +13 -0

@@ -0,0 +1,13 @@
+#ifndef _TRACE_FILEMAP_H
+#define _TRACE_FILEMAP_H
+
+#include <linux/tracepoint.h>
+
+DEFINE_TRACE(filemap_wait_start,
+	TPPROTO(struct page *page, int bit_nr),
+	TPARGS(page, bit_nr));
+DEFINE_TRACE(filemap_wait_end,
+	TPPROTO(struct page *page, int bit_nr),
+	TPARGS(page, bit_nr));
+
+#endif

Quoted 43 lines · Mathieu Desnoyers

plain text document attachment (lttng-instrumentation-filemap.patch) Instrumentation of waits caused by memory accesses on mmap regions.

Those tracepoints are used by LTTng.

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.

Signed-off-by Mathieu Desnoyers <[email protected]>

CC [email protected]

CC Dave Hansen <[email protected]>

CC Masami Hiramatsu <[email protected]>

CC 'Peter Zijlstra' <[email protected]>

CC "Frank Ch. Eigler" <[email protected]>

CC 'Ingo Molnar' <[email protected]>

CC 'Hideo AOKI' <[email protected]>

CC Takashi Nishiie <[email protected]>

CC 'Steven Rostedt' <[email protected]>

CC Eduard - Gabriel Munteanu <[email protected]>

---
 include/trace/filemap.h |   13 +++++++++++++
 mm/filemap.c            |    3 +++
 2 files changed, 16 insertions(+)

Index: linux-2.6-lttng/mm/filemap.c
===================================================================

mm/filemap.c +1 -0

@@ -33,6 +33,7 @@
 #include <linux/cpuset.h>
 #include <linux/hardirq.h> /* for BUG_ON(!in_atomic()) only */
 #include <linux/memcontrol.h>
+#include <trace/filemap.h>
 #include "internal.h"
 
 /*

@@ -541,9 +542,11 @@ void wait_on_page_bit(struct page *page,
 {
 	DEFINE_WAIT_BIT(wait, &page->flags, bit_nr);
 

mm/filemap.c void wait_on_page_bit(struct page *page, · line 551

Quoted 7 lines

mm/filemap.c +2 -0

+	trace_filemap_wait_start(page, bit_nr);
 	if (test_bit(bit_nr, &page->flags))
 		__wait_on_bit(page_waitqueue(page), &wait, sync_page,
 							TASK_UNINTERRUPTIBLE);
+	trace_filemap_wait_end(page, bit_nr);
 }
 EXPORT_SYMBOL(wait_on_page_bit);

I don't like the trace_filemap_wait_* naming..

trace_wait_on_page_* might make more sense

Quoted 19 lines

Index: linux-2.6-lttng/include/trace/filemap.h
===================================================================

include/trace/filemap.h new file +13 -0

@@ -0,0 +1,13 @@
+#ifndef _TRACE_FILEMAP_H
+#define _TRACE_FILEMAP_H
+
+#include <linux/tracepoint.h>
+
+DEFINE_TRACE(filemap_wait_start,
+	TPPROTO(struct page *page, int bit_nr),
+	TPARGS(page, bit_nr));
+DEFINE_TRACE(filemap_wait_end,
+	TPPROTO(struct page *page, int bit_nr),
+	TPARGS(page, bit_nr));
+
+#endif

Instrumentation of waits caused by memory accesses on mmap regions.

Those tracepoints are used by LTTng.

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.

Quoted 10 lines · Mathieu Desnoyers

Instrumentation of waits caused by memory accesses on mmap regions.

Those tracepoints are used by LTTng.

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.

BTW. this sort of test is practically useless to measure overhead. If a modern CPU is executing out of primed insn/data and branch prediction cache, then yes this sort of thing is pretty well free.

I see *real* workloads that have got continually and incrementally slower eg from 2.6.5 to 2.6.20+ as "features" get added. Surprisingly, none of them ever showed up individually on a microbenchmark.

OK, for this case if you can configure it out, I guess that's fine. But let's not pretend that adding code and branches and function calls are ever free.

Quoted 20 lines · * Nick Piggin ([email protected]) wrote:

Quoted 10 lines · Mathieu Desnoyers

Instrumentation of waits caused by memory accesses on mmap regions.

Those tracepoints are used by LTTng.

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.

BTW. this sort of test is practically useless to measure overhead. If a modern CPU is executing out of primed insn/data and branch prediction cache, then yes this sort of thing is pretty well free.

I see *real* workloads that have got continually and incrementally slower eg from 2.6.5 to 2.6.20+ as "features" get added. Surprisingly, none of them ever showed up individually on a microbenchmark.

Quoted 3 lines

OK, for this case if you can configure it out, I guess that's fine. But let's not pretend that adding code and branches and function calls are ever free.

I never pretended anything like that. Actually, that's what the

"immediate values" are for : they allow to patch load immediate value instead of a memory read to decrease d-cache impact. They now allow to patch a jump instead of the memory read/immediate value read + test + conditional branch to skip the function call with fairly minimal impact. I agree with you that eating precious d-cache and jump prediction buffer entries can eventually slow down the system. But this will be _hard_ to show on a single macro benchmark, and the microbenchmark showing it will have to be taken in conditions which will exacerbate the d-cache and BPB impact.

plain text document attachment (lttng-instrumentation-swap.patch) Instrumentation of waits caused by swap activity. Also instrumentation swapon/swapoff events to keep track of active swap partitions.

Those tracepoints are used by LTTng.

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.

Signed-off-by Mathieu Desnoyers <[email protected]>

CC [email protected]

CC Dave Hansen <[email protected]>

CC Masami Hiramatsu <[email protected]>

CC 'Peter Zijlstra' <[email protected]>

CC "Frank Ch. Eigler" <[email protected]>

CC 'Ingo Molnar' <[email protected]>

CC 'Hideo AOKI' <[email protected]>

CC Takashi Nishiie <[email protected]>

CC 'Steven Rostedt' <[email protected]>

CC Eduard - Gabriel Munteanu <[email protected]>

---
 include/trace/swap.h |   20 ++++++++++++++++++++
 mm/memory.c          |    2 ++
 mm/page_io.c         |    2 ++
 mm/swapfile.c        |    4 ++++
 4 files changed, 28 insertions(+)

Index: linux-2.6-lttng/mm/memory.c
===================================================================

mm/memory.c +2 -0

@@ -51,6 +51,7 @@
 #include <linux/init.h>
 #include <linux/writeback.h>
 #include <linux/memcontrol.h>
+#include <trace/swap.h>
 
 #include <asm/pgalloc.h>
 #include <asm/uaccess.h>

@@ -2213,6 +2214,7 @@ static int do_swap_page(struct mm_struct
 		/* Had to read the page from swap area: Major fault */
 		ret = VM_FAULT_MAJOR;
 		count_vm_event(PGMAJFAULT);
+		trace_swap_in(page, entry);
 	}
 
 	if (mem_cgroup_charge(page, mm, GFP_KERNEL)) {

Index: linux-2.6-lttng/mm/page_io.c
===================================================================

mm/page_io.c +2 -0

@@ -17,6 +17,7 @@
 #include <linux/bio.h>
 #include <linux/swapops.h>
 #include <linux/writeback.h>
+#include <trace/swap.h>
 #include <asm/pgtable.h>
 
 static struct bio *get_swap_bio(gfp_t gfp_flags, pgoff_t index,

@@ -114,6 +115,7 @@ int swap_writepage(struct page *page, st
 		rw |= (1 << BIO_RW_SYNC);
 	count_vm_event(PSWPOUT);
 	set_page_writeback(page);
+	trace_swap_out(page);
 	unlock_page(page);
 	submit_bio(rw, bio);
 out:

Index: linux-2.6-lttng/mm/swapfile.c
===================================================================

mm/swapfile.c +3 -0

@@ -32,6 +32,7 @@
 #include <asm/pgtable.h>
 #include <asm/tlbflush.h>
 #include <linux/swapops.h>
+#include <trace/swap.h>
 
 DEFINE_SPINLOCK(swap_lock);
 unsigned int nr_swapfiles;

@@ -1310,6 +1311,7 @@ asmlinkage long sys_swapoff(const char _
 	swap_map = p->swap_map;
 	p->swap_map = NULL;
 	p->flags = 0;
+	trace_swap_file_close(swap_file);
 	spin_unlock(&swap_lock);
 	mutex_unlock(&swapon_mutex);
 	vfree(swap_map);

@@ -1695,6 +1697,7 @@ asmlinkage long sys_swapon(const char __
 	} else {
 		swap_info[prev].next = p - swap_info;
 	}
+	trace_swap_file_open(swap_file, name);
 	spin_unlock(&swap_lock);
 	mutex_unlock(&swapon_mutex);
 	error = 0;

mm/swapfile.c +0 -0

 /*
  * swap_lock prevents swap_map being freed. Don't grab an extra

Index: linux-2.6-lttng/include/trace/swap.h
===================================================================

include/trace/swap.h new file +10 -0

@@ -0,0 +1,20 @@
+#ifndef _TRACE_SWAP_H
+#define _TRACE_SWAP_H
+
+#include <linux/swap.h>
+#include <linux/tracepoint.h>
+
+DEFINE_TRACE(swap_in,
+	TPPROTO(struct page *page, swp_entry_t entry),
+	TPARGS(page, entry));
+DEFINE_TRACE(swap_out,

Quoted 97 lines · Mathieu Desnoyers

plain text document attachment (lttng-instrumentation-swap.patch) Instrumentation of waits caused by swap activity. Also instrumentation swapon/swapoff events to keep track of active swap partitions.

Those tracepoints are used by LTTng.

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.

Signed-off-by Mathieu Desnoyers <[email protected]>

CC [email protected]

CC Dave Hansen <[email protected]>

CC Masami Hiramatsu <[email protected]>

CC 'Peter Zijlstra' <[email protected]>

CC "Frank Ch. Eigler" <[email protected]>

CC 'Ingo Molnar' <[email protected]>

CC 'Hideo AOKI' <[email protected]>

CC Takashi Nishiie <[email protected]>

CC 'Steven Rostedt' <[email protected]>

CC Eduard - Gabriel Munteanu <[email protected]>

---
 include/trace/swap.h |   20 ++++++++++++++++++++
 mm/memory.c          |    2 ++
 mm/page_io.c         |    2 ++
 mm/swapfile.c        |    4 ++++
 4 files changed, 28 insertions(+)

Index: linux-2.6-lttng/mm/memory.c
===================================================================

mm/memory.c +2 -0

@@ -51,6 +51,7 @@
 #include <linux/init.h>
 #include <linux/writeback.h>
 #include <linux/memcontrol.h>
+#include <trace/swap.h>
 
 #include <asm/pgalloc.h>
 #include <asm/uaccess.h>

@@ -2213,6 +2214,7 @@ static int do_swap_page(struct mm_struct
 		/* Had to read the page from swap area: Major fault */
 		ret = VM_FAULT_MAJOR;
 		count_vm_event(PGMAJFAULT);
+		trace_swap_in(page, entry);
 	}
 
 	if (mem_cgroup_charge(page, mm, GFP_KERNEL)) {

Index: linux-2.6-lttng/mm/page_io.c
===================================================================

mm/page_io.c +2 -0

@@ -17,6 +17,7 @@
 #include <linux/bio.h>
 #include <linux/swapops.h>
 #include <linux/writeback.h>
+#include <trace/swap.h>
 #include <asm/pgtable.h>
 
 static struct bio *get_swap_bio(gfp_t gfp_flags, pgoff_t index,

@@ -114,6 +115,7 @@ int swap_writepage(struct page *page, st
 		rw |= (1 << BIO_RW_SYNC);
 	count_vm_event(PSWPOUT);
 	set_page_writeback(page);
+	trace_swap_out(page);
 	unlock_page(page);
 	submit_bio(rw, bio);
 out:

Index: linux-2.6-lttng/mm/swapfile.c
===================================================================

mm/swapfile.c +3 -0

@@ -32,6 +32,7 @@
 #include <asm/pgtable.h>
 #include <asm/tlbflush.h>
 #include <linux/swapops.h>
+#include <trace/swap.h>
 
 DEFINE_SPINLOCK(swap_lock);
 unsigned int nr_swapfiles;

@@ -1310,6 +1311,7 @@ asmlinkage long sys_swapoff(const char _
 	swap_map = p->swap_map;
 	p->swap_map = NULL;
 	p->flags = 0;
+	trace_swap_file_close(swap_file);
 	spin_unlock(&swap_lock);
 	mutex_unlock(&swapon_mutex);
 	vfree(swap_map);

@@ -1695,6 +1697,7 @@ asmlinkage long sys_swapon(const char __
 	} else {
 		swap_info[prev].next = p - swap_info;
 	}
+	trace_swap_file_open(swap_file, name);
 	spin_unlock(&swap_lock);
 	mutex_unlock(&swapon_mutex);

mm/swapfile.c get_swap_info_struct(unsigned type) · line 1802

Quoted 6 lines

mm/swapfile.c +1 -0

 	error = 0;

@@ -1796,6 +1799,7 @@ get_swap_info_struct(unsigned type)
 {
 	return &swap_info[type];
 }
+EXPORT_SYMBOL_GPL(get_swap_info_struct);

I'm not too happy with this export.

Quoted 29 lines

mm/swapfile.c +0 -0

 /*
  * swap_lock prevents swap_map being freed. Don't grab an extra

Index: linux-2.6-lttng/include/trace/swap.h
===================================================================

include/trace/swap.h new file +20 -0

@@ -0,0 +1,20 @@
+#ifndef _TRACE_SWAP_H
+#define _TRACE_SWAP_H
+
+#include <linux/swap.h>
+#include <linux/tracepoint.h>
+
+DEFINE_TRACE(swap_in,
+	TPPROTO(struct page *page, swp_entry_t entry),
+	TPARGS(page, entry));
+DEFINE_TRACE(swap_out,
+	TPPROTO(struct page *page),
+	TPARGS(page));
+DEFINE_TRACE(swap_file_open,
+	TPPROTO(struct file *file, char *filename),
+	TPARGS(file, filename));
+DEFINE_TRACE(swap_file_close,
+	TPPROTO(struct file *file),
+	TPARGS(file));
+
+#endif

Quoted 10 lines · * Peter Zijlstra ([email protected]) wrote:

mm/swapfile.c get_swap_info_struct(unsigned type) · line 1802

Quoted 5 lines · Mathieu Desnoyers

mm/swapfile.c +1 -0

@@ -1796,6 +1799,7 @@ get_swap_info_struct(unsigned type)
 {
 	return &swap_info[type];
 }
+EXPORT_SYMBOL_GPL(get_swap_info_struct);

I'm not too happy with this export.

Would it make more sense to turn get_swap_info_struct into a static inline in swap.h ?

Quoted 12 lines · Mathieu Desnoyers

Quoted 10 lines · * Peter Zijlstra ([email protected]) wrote:

mm/swapfile.c get_swap_info_struct(unsigned type) · line 1802

Quoted 5 lines · Mathieu Desnoyers

mm/swapfile.c +1 -0

@@ -1796,6 +1799,7 @@ get_swap_info_struct(unsigned type)
 {
 	return &swap_info[type];
 }
+EXPORT_SYMBOL_GPL(get_swap_info_struct);

I'm not too happy with this export.

Quoted 2 lines

Would it make more sense to turn get_swap_info_struct into a static inline in swap.h ?

Seeing a consumer of it would go a long way towards discussing it ;-)

Quoted 4 lines

Quoted 2 lines

Would it make more sense to turn get_swap_info_struct into a static inline in swap.h ?

Seeing a consumer of it would go a long way towards discussing it ;-)

The LTTng probe which connects to this tracepoint looks like :