Skip to contentSkip to conversation

tracing/function-return-tracer: set a more human readable output

PATCH In review Frederic Weisbecker 3 participants 18 messages Nov 25, 2008 – Nov 26, 2008

Subsystems (3)
x86 Tracing ftrace
lore
Share & tools
lore

Frederic Weisbecker

author
#0 lore raw

PATCH 1/1 tracing/function-return-tracer: set a more human readable output

Impact: feature

This patch sets a C-like output for the function graph tracing. For this aim, we now call two handler for each function: one on the entry and one other on return. This way we can draw a well-ordered call stack.

The pid of the previous trace is loosely stored to be compared against the one of the current trace to see if there were a context switch.

Without this little feature, the call tree would seem broken at some locations.
We could use the sched_tracer to capture these sched_events but this way of processing is much more simpler.

2 spaces have been chosen for indentation to fit the screen while deep calls. The time of execution in nanosecs is printed just after closed braces, it seems more easy this way to find the corresponding function. If the time was printed as a first column, it would be not so easy to find the corresponding function if it is called on a deep depth.

I plan to output the return value but on 32 bits CPU, the return value can be 32 or 64, and its difficult to guess on which case we are. I don't know what would be the better solution on X86-32: only print eax (low-part) or even edx (high-part).

Actually it's thee same problem when a function return a 8 bits value, the high part of eax could contain junk values...

Here is an example of trace:

sys_read() {
fget_light() {
} 526

  vfs_read() {
    rw_verify_area() {
      security_file_permission() {
        cap_file_permission() {
        } 519
      } 1564
    } 2640
    do_sync_read() {
      pipe_read() {
        __might_sleep() {
        } 511
        pipe_wait() {
          prepare_to_wait() {
          } 760
          deactivate_task() {
            dequeue_task() {
              dequeue_task_fair() {
                dequeue_entity() {
                  update_curr() {
                    update_min_vruntime() {
                    } 504
                  } 1587
                  clear_buddies() {
                  } 512
                  add_cfs_task_weight() {
                  } 519
                  update_min_vruntime() {
                  } 511
                } 5602
                dequeue_entity() {
                  update_curr() {
                    update_min_vruntime() {
                    } 496
                  } 1631
                  clear_buddies() {
                  } 496
                  update_min_vruntime() {
                  } 527
                } 4580
                hrtick_update() {
                  hrtick_start_fair() {
                  } 488
                } 1489
              } 13700
            } 14949
          } 16016
          msecs_to_jiffies() {
          } 496
          put_prev_task_fair() {
          } 504
          pick_next_task_fair() {
          } 489
          pick_next_task_rt() {
          } 496
          pick_next_task_fair() {
          } 489
          pick_next_task_idle() {
          } 489

------------8<---------- thread 4 ------------8<----------

finish_task_switch() {
} 1203
do_softirq() {

  __do_softirq() {
    __local_bh_disable() {
    } 669
    rcu_process_callbacks() {
      __rcu_process_callbacks() {
        cpu_quiet() {
          rcu_start_batch() {
          } 503
        } 1647
      } 3128
      __rcu_process_callbacks() {
      } 542
    } 5362
    _local_bh_enable() {
    } 587

} 8880
} 9986
kthread_should_stop() {
} 669
deactivate_task() {

  dequeue_task() {
    dequeue_task_fair() {
      dequeue_entity() {
        update_curr() {
          calc_delta_mine() {
          } 511
          update_min_vruntime() {
          } 511
        } 2813
Signed-off-by Frederic Weisbecker <[email protected]>
---
 arch/x86/kernel/ftrace.c              |   32 +++++++----
 include/linux/ftrace.h                |   25 ++++++--
 kernel/trace/ftrace.c                 |   30 +++++-----
 kernel/trace/trace.c                  |   67 +++++++++++++++++----
 kernel/trace/trace.h                  |   28 +++++----
 kernel/trace/trace_functions_graph.c  |  104 +++++++++++++++++++++++++--------
 kernel/trace/trace_functions_return.c |   98 -------------------------------
 7 files changed, 208 insertions(+), 176 deletions(-)
arch/x86/kernel/ftrace.c +21 -11
index 3595a4c..26b2d92 100644
@@ -347,7 +347,7 @@ void ftrace_nmi_exit(void)
 
 /* Add a function return address to the trace stack on thread info.*/
 static int push_return_trace(unsigned long ret, unsigned long long time,
-				unsigned long func)
+				unsigned long func, int *depth)
 {
 	int index;
 

@@ -365,21 +365,22 @@ static int push_return_trace(unsigned long ret, unsigned long long time,
 	current->ret_stack[index].ret = ret;
 	current->ret_stack[index].func = func;
 	current->ret_stack[index].calltime = time;
+	*depth = index;
 
 	return 0;
 }
 
 /* Retrieve a function return address to the trace stack on thread info.*/
-static void pop_return_trace(unsigned long *ret, unsigned long long *time,
-				unsigned long *func, unsigned long *overrun)
+static void pop_return_trace(struct ftrace_graph_ret *trace, unsigned long *ret)
 {
 	int index;
 
 	index = current->curr_ret_stack;
 	*ret = current->ret_stack[index].ret;
-	*func = current->ret_stack[index].func;
-	*time = current->ret_stack[index].calltime;
-	*overrun = atomic_read(&current->trace_overrun);
+	trace->func = current->ret_stack[index].func;
+	trace->calltime = current->ret_stack[index].calltime;
+	trace->overrun = atomic_read(&current->trace_overrun);
+	trace->depth = index;
 	current->curr_ret_stack--;
 }
 

@@ -390,12 +391,13 @@ static void pop_return_trace(unsigned long *ret, unsigned long long *time,
 unsigned long ftrace_return_to_handler(void)
 {
 	struct ftrace_graph_ret trace;
-	pop_return_trace(&trace.ret, &trace.calltime, &trace.func,
-			&trace.overrun);
+	unsigned long ret;
+
+	pop_return_trace(&trace, &ret);
 	trace.rettime = cpu_clock(raw_smp_processor_id());
-	ftrace_graph_function(&trace);
+	ftrace_graph_return(&trace);
 
-	return trace.ret;
+	return ret;
 }
 
 /*

@@ -407,6 +409,7 @@ void prepare_ftrace_return(unsigned long *parent, unsigned long self_addr)
 	unsigned long old;
 	unsigned long long calltime;
 	int faulted;
+	struct ftrace_graph_ent trace;
 	unsigned long return_hooker = (unsigned long)
 				&return_to_handler;
 

@@ -452,8 +455,15 @@ void prepare_ftrace_return(unsigned long *parent, unsigned long self_addr)
 
 	calltime = cpu_clock(raw_smp_processor_id());
 
-	if (push_return_trace(old, calltime, self_addr) == -EBUSY)
+	if (push_return_trace(old, calltime,
+				self_addr, &trace.depth) == -EBUSY) {
 		*parent = old;
+		return;
+	}
+
+	trace.func = self_addr;
+	ftrace_graph_entry(&trace);
+
 }
 
 #endif /* CONFIG_FUNCTION_GRAPH_TRACER */
include/linux/ftrace.h +19 -6
index b4ac734..fc2d549 100644
@@ -313,26 +313,39 @@ ftrace_init_module(struct module *mod,
 
 
 /*
+ * Structure that defines an entry function trace.
+ */
+struct ftrace_graph_ent {
+	unsigned long func; /* Current function */
+	int depth;
+};
+
+/*
  * Structure that defines a return function trace.
  */
 struct ftrace_graph_ret {
-	unsigned long ret; /* Return address */
 	unsigned long func; /* Current function */
 	unsigned long long calltime;
 	unsigned long long rettime;
 	/* Number of functions that overran the depth limit for current task */
 	unsigned long overrun;
+	int depth;
 };
 
 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
 #define FTRACE_RETFUNC_DEPTH 50
 #define FTRACE_RETSTACK_ALLOC_SIZE 32
-/* Type of a callback handler of tracing return function */
-typedef void (*trace_function_graph_t)(struct ftrace_graph_ret *);
+/* Type of the callback handlers for tracing function graph*/
+typedef void (*trace_func_graph_ret_t)(struct ftrace_graph_ret *); /* return */
+typedef void (*trace_func_graph_ent_t)(struct ftrace_graph_ent *); /* entry */
+
+extern int register_ftrace_graph(trace_func_graph_ret_t retfunc,
+				trace_func_graph_ent_t entryfunc);
+
+/* The current handlers in use */
+extern trace_func_graph_ret_t ftrace_graph_return;
+extern trace_func_graph_ent_t ftrace_graph_entry;
 
-extern int register_ftrace_graph(trace_function_graph_t func);
-/* The current handler in use */
-extern trace_function_graph_t ftrace_graph_function;
 extern void unregister_ftrace_graph(void);
 
 extern void ftrace_graph_init_task(struct task_struct *t);
kernel/trace/ftrace.c +16 -14
index 9e19976..7e2d3b9 100644
@@ -1498,12 +1498,13 @@ ftrace_enable_sysctl(struct ctl_table *table, int write,
 
 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
 
-static atomic_t ftrace_retfunc_active;
-
-/* The callback that hooks the return of a function */
-trace_function_graph_t ftrace_graph_function =
-			(trace_function_graph_t)ftrace_stub;
+static atomic_t ftrace_graph_active;
 
+/* The callbacks that hook a function */
+trace_func_graph_ret_t ftrace_graph_return =
+			(trace_func_graph_ret_t)ftrace_stub;
+trace_func_graph_ent_t ftrace_graph_entry =
+			(trace_func_graph_ent_t)ftrace_stub;
 
 /* Try to assign a return stack array on FTRACE_RETSTACK_ALLOC_SIZE tasks. */
 static int alloc_retstack_tasklist(struct ftrace_ret_stack **ret_stack_list)

@@ -1569,7 +1570,8 @@ static int start_graph_tracing(void)
 	return ret;
 }
 
-int register_ftrace_graph(trace_function_graph_t func)
+int register_ftrace_graph(trace_func_graph_ret_t retfunc,
+			trace_func_graph_ent_t entryfunc)
 {
 	int ret = 0;
 

@@ -1583,14 +1585,15 @@ int register_ftrace_graph(trace_function_graph_t func)
 		ret = -EBUSY;
 		goto out;
 	}
-	atomic_inc(&ftrace_retfunc_active);
+	atomic_inc(&ftrace_graph_active);
 	ret = start_graph_tracing();
 	if (ret) {
-		atomic_dec(&ftrace_retfunc_active);
+		atomic_dec(&ftrace_graph_active);
 		goto out;
 	}
 	ftrace_tracing_type = FTRACE_TYPE_RETURN;
-	ftrace_graph_function = func;
+	ftrace_graph_return = retfunc;
+	ftrace_graph_entry = entryfunc;
 	ftrace_startup();
 
 out:

@@ -1602,8 +1605,9 @@ void unregister_ftrace_graph(void)
 {
 	mutex_lock(&ftrace_sysctl_lock);
 
-	atomic_dec(&ftrace_retfunc_active);
-	ftrace_graph_function = (trace_function_graph_t)ftrace_stub;
+	atomic_dec(&ftrace_graph_active);
+	ftrace_graph_return = (trace_func_graph_ret_t)ftrace_stub;
+	ftrace_graph_entry = (trace_func_graph_ent_t)ftrace_stub;
 	ftrace_shutdown();
 	/* Restore normal tracing type */
 	ftrace_tracing_type = FTRACE_TYPE_ENTER;

@@ -1614,7 +1618,7 @@ void unregister_ftrace_graph(void)
 /* Allocate a return stack for newly created task */
 void ftrace_graph_init_task(struct task_struct *t)
 {
-	if (atomic_read(&ftrace_retfunc_active)) {
+	if (atomic_read(&ftrace_graph_active)) {
 		t->ret_stack = kmalloc(FTRACE_RETFUNC_DEPTH
 				* sizeof(struct ftrace_ret_stack),
 				GFP_KERNEL);

@@ -1638,5 +1642,3 @@ void ftrace_graph_exit_task(struct task_struct *t)
 }
 #endif
 
-
-
kernel/trace/trace.c +55 -12

104 lines not on this page · raw message

kernel/trace/trace.h +17 -11
index 72b5ef8..ffe1bb1 100644
@@ -25,7 +25,8 @@ enum trace_type {
 	TRACE_BRANCH,
 	TRACE_BOOT_CALL,
 	TRACE_BOOT_RET,
-	TRACE_FN_RET,
+	TRACE_GRAPH_RET,
+	TRACE_GRAPH_ENT,
 	TRACE_USER_STACK,
 	TRACE_BTS,
 

@@ -56,14 +57,16 @@ struct ftrace_entry {
 	unsigned long		parent_ip;
 };
 
+/* Function call entry */
+struct ftrace_graph_ent_entry {
+	struct trace_entry			ent;
+	struct ftrace_graph_ent		graph_ent;
+};
+
 /* Function return entry */
-struct ftrace_graph_entry {
-	struct trace_entry	ent;
-	unsigned long		ip;
-	unsigned long		parent_ip;
-	unsigned long long	calltime;
-	unsigned long long	rettime;
-	unsigned long		overrun;
+struct ftrace_graph_ret_entry {
+	struct trace_entry			ent;
+	struct ftrace_graph_ret		ret;
 };
 extern struct tracer boot_tracer;
 

@@ -264,7 +267,10 @@ extern void __ftrace_bad_type(void);
 		IF_ASSIGN(var, ent, struct trace_boot_call, TRACE_BOOT_CALL);\
 		IF_ASSIGN(var, ent, struct trace_boot_ret, TRACE_BOOT_RET);\
 		IF_ASSIGN(var, ent, struct trace_branch, TRACE_BRANCH); \
-		IF_ASSIGN(var, ent, struct ftrace_graph_entry, TRACE_FN_RET);\
+		IF_ASSIGN(var, ent, struct ftrace_graph_ent_entry,	\
+			  TRACE_GRAPH_ENT);		\
+		IF_ASSIGN(var, ent, struct ftrace_graph_ret_entry,	\
+			  TRACE_GRAPH_RET);		\
 		IF_ASSIGN(var, ent, struct bts_entry, TRACE_BTS);\
 		__ftrace_bad_type();					\
 	} while (0)

@@ -397,9 +403,9 @@ void trace_function(struct trace_array *tr,
 		    unsigned long ip,
 		    unsigned long parent_ip,
 		    unsigned long flags, int pc);
-void
-trace_function_graph(struct ftrace_graph_ret *trace);
 
+void trace_graph_return(struct ftrace_graph_ret *trace);
+void trace_graph_entry(struct ftrace_graph_ent *trace);
 void trace_bts(struct trace_array *tr,
 	       unsigned long from,
 	       unsigned long to);
kernel/trace/trace_functions_graph.c +80 -24

144 lines not on this page · raw message

kernel/trace/trace_functions_return.c deleted +0 -98

98 lines not on this page · raw message

Signature · 1 line
1.5.2.5
#1 lore raw
Quoted 64 lines · Frederic Weisbecker

Here is an example of trace:

sys_read() {
fget_light() {
} 526

  vfs_read() {
    rw_verify_area() {
      security_file_permission() {
        cap_file_permission() {
        } 519
      } 1564
    } 2640
    do_sync_read() {
      pipe_read() {
        __might_sleep() {
        } 511
        pipe_wait() {
          prepare_to_wait() {
          } 760
          deactivate_task() {
            dequeue_task() {
              dequeue_task_fair() {
                dequeue_entity() {
                  update_curr() {
                    update_min_vruntime() {
                    } 504
                  } 1587
                  clear_buddies() {
                  } 512
                  add_cfs_task_weight() {
                  } 519
                  update_min_vruntime() {
                  } 511
                } 5602
                dequeue_entity() {
                  update_curr() {
                    update_min_vruntime() {
                    } 496
                  } 1631
                  clear_buddies() {
                  } 496
                  update_min_vruntime() {
                  } 527
                } 4580
                hrtick_update() {
                  hrtick_start_fair() {
                  } 488
                } 1489
              } 13700
            } 14949
          } 16016
          msecs_to_jiffies() {
          } 496
          put_prev_task_fair() {
          } 504
          pick_next_task_fair() {
          } 489
          pick_next_task_rt() {
          } 496
          pick_next_task_fair() {
          } 489
          pick_next_task_idle() {
          } 489
Quoted 1 line

------------8<---------- thread 4 ------------8<----------

Wow, very nice output! :-)

I've applied them, will comment and test on them as well.

Ingo

#2 lore raw
Quoted 3 lines · Ingo Molnar

Wow, very nice output! :-)

I've applied them, will comment and test on them as well.

I kept playing with this for almost an hour and kept looking at pages and pages of tracer output - it really shows the kernel's flow in a completely different dimension!

Talked to Steve about it and we have a few minor suggestions regarding the default output:

I think we should optimize the visual qualities of the output some more.

Instead of:

pick_next_task() {

   pick_next_task_fair() {   
     wakeup_preempt_entity() { 
     } 301
     set_next_entity() {    
       update_stats_wait_end() { 
       } 281
       __dequeue_entity() { 
       } 319
     } 1990
     hrtick_start_fair() { 
     } 276

} 4524
} 5341

We should print such traces [mockup]:

pick_next_task() { -

     pick_next_task_fair() {                -
       wakeup_preempt_entity();               + 0.301 us
       set_next_entity() {                    -
         update_stats_wait_end();               + 0.281 us
         __dequeue_entity();                    + 0.319 us
       }                                      + 1.990 us
       hrtick_start_fair();                   + 0.276 us

+ } + 10.524 us
! } + 100.341 us
switch_mm(); + 0.494 us

The changes would be:

1) Compression of non-nested calls into a single line.

Implementing this probably necessiates some trickery with the
ring-buffer: we'd have to look at the next entry as well and see whether it closes the function call.

2) Adding a closing ';' semicolon to single-line calls. It's the C syntax and i'm missing it :-)

3) The first column: single-character visual shortcuts for "overhead". This is a concept we used in the -rt tracer and it still lives in the latency tracer bits of ftrace and is quite useful:

'+' means "overhead spike": overhead is above 10 usecs. '!' means "large overhead": overhead is above 100 usecs.

These give at-a-glance hotspot analysis - hotspots are easier to miss as pure numbers.

4) Printing out in units of microseconds, with a decimal point and by explicitly mentioning the 'us' unit.

All of these are important properties: microseconds is still the most common 'overhead' unit in kernel circles. It also gives rather human single-digit or two-digit results. Nanoseconds is three or- four-digit - which is too much. Repeating 'us' so many times is not a problem - these lines will be grepped, quoted, etc - constant reminder about the unit is just fine.

5) Nesting the overhead numbers aligned to the right end of the graph.

This cleans up the view of the source code printout, but not cluttering it with numbers. It also structures the numbers some more. Visual cues are given via '-' and '+' signs, to follow nesting. This nesting aligns up with the function nesting levels on the left side - so it's easy to pair up number and function name. It also separates the numbers from the symbol length effects in the single-line case. (which is the most common trace line)

What do you think? It's lots of work (sorry! :-), but it would produce even more stunning graph-tracer output IMO.

Ingo

#3 lore raw

PATCH 1/1 tracing: function graph tracer, fix

small fixlet.

------------->

Quoted 1 line

From c2324b694fa8ffee382a124198c68754088e483c Mon Sep 17 00:00:00 2001

From: Ingo Molnar <[email protected]>
Date: Wed, 26 Nov 2008 03:10:01 +0100
Subject: [PATCH] tracing: function graph tracer, fix

fix return-tracer => graph-tracer namespace rename fallout.

Signed-off-by Ingo Molnar <[email protected]>
---
 arch/x86/kernel/entry_32.S |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)
arch/x86/kernel/entry_32.S +1 -1
index 2b1f0f0..7def9fd 100644
@@ -1189,7 +1189,7 @@ ENTRY(mcount)
 	cmpl $ftrace_stub, ftrace_trace_function
 	jnz trace
 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
-	cmpl $ftrace_stub, ftrace_graph_function
+	cmpl $ftrace_stub, ftrace_graph_return
 	jnz ftrace_graph_caller
 #endif
 .globl ftrace_stub
#10 lore raw
In reply to Ingo Molnar

there's a small inconsistency here:

# cat available_tracers 
function-graph function sched_switch nop

note the '-' versus '_' separators. I wouldnt mind renaming the sched tracer to sched-switch. (and some of the other tracers as well)

Ingo

#12 lore raw
In reply to Ingo Molnar

the regex filter doesnt work well yet when used with the graph tracer:

[ 2994.079079] ------------[ cut here ]------------
[ 2994.079079] WARNING: at kernel/trace/ftrace.c:373 ftrace_bug+0x8c/0x1ce()
[ 2994.079079] Modules linked in:
[ 2994.079079] Pid: 12, comm: kstop/0 Not tainted 2.6.28-rc6-tip #2056
[ 2994.079079] Call Trace:
[ 2994.079079]  [<c02273dd>] warn_on_slowpath+0x46/0x60
[ 2994.079079]  [<c0268308>] ? trace_graph_return+0x89/0xa7
[ 2994.079079]  [<c0268308>] ? trace_graph_return+0x89/0xa7
[ 2994.079079]  [<c0213e85>] ? ftrace_return_to_handler+0x6b/0x74
[ 2994.079079]  [<c0357f66>] ? memcpy+0xe/0x31
[ 2994.079079]  [<c02633e6>] ? rb_commit+0x29/0x2d
[ 2994.079079]  [<c0264c8b>] ? ring_buffer_unlock_commit+0x15/0x1a
[ 2994.079079]  [<c0213ece>] ? ftrace_modify_code+0x21/0xa3
[ 2994.079079]  [<c0213e85>] ? ftrace_return_to_handler+0x6b/0x74
[ 2994.079079]  [<c026c3ce>] ? probe_kernel_read+0xe/0x5c
[ 2994.079079]  [<c0261ec7>] ? trace_selftest_dynamic_test_func+0x3/0xc
[ 2994.079079]  [<c0203926>] ? return_to_handler+0xa/0x14
[ 2994.079079]  [<c0261ec7>] ? trace_selftest_dynamic_test_func+0x3/0xc
[ 2994.079079]  [<c0213ee5>] ? ftrace_modify_code+0x38/0xa3
[ 2994.079079]  [<c0261ec7>] ? trace_selftest_dynamic_test_func+0x3/0xc
[ 2994.079079]  [<c0262749>] ftrace_bug+0x8c/0x1ce
[ 2994.079079]  [<c026299c>] ftrace_replace_code+0x111/0x13d
[ 2994.079079]  [<c0253b53>] ? stop_cpu+0x0/0xa5
[ 2994.079079]  [<c02629e6>] __ftrace_modify_code+0x1e/0x32
[ 2994.079079]  [<c0253bbe>] stop_cpu+0x6b/0xa5
[ 2994.079079]  [<c020391c>] return_to_handler+0x0/0x14
[ 2994.079079]  [<c020391c>] return_to_handler+0x0/0x14
[ 2994.079079]  [<c0237fc1>] ? autoremove_wake_function+0x0/0x35
[ 2994.079079]  [<c023584b>] ? worker_thread+0x0/0xc7
[ 2994.079079]  [<c0237eba>] kthread+0x40/0x66
[ 2994.079079]  [<c0237e7a>] ? kthread+0x0/0x66
[ 2994.079079]  [<c02038cb>] kernel_thread_helper+0x7/0x10
[ 2994.079079] ---[ end trace bff97d149b80ecde ]---
[ 2994.079079] ftrace failed to modify [<c0261ec7>] trace_selftest_dynamic_test_func+0x3/0xc
[ 2994.079079]  actual: e8:0c:1a:fa:ff

produced via:

 # cd /debug/tracing/
 # cat set_ftrace_filter
 # echo schedule > set_ftrace_filter
 # cat set_ftrace_filter
 cat: set_ftrace_filter: No such device

Ingo

maintainer
#4 lore raw
In reply to Ingo Molnar
Quoted 8 lines · Ingo Molnar

The changes would be:

1) Compression of non-nested calls into a single line.

Implementing this probably necessiates some trickery with the
ring-buffer: we'd have to look at the next entry as well and see whether it closes the function call.

The latency_trace file does this already:

You can look into the trace buffer without moving it with:

  entry = ring_buffer_iter_peek(iter->buffer_iter[iter->cpu], &ts);

where, ts will give you the time stamp, it can be NULL if you do not care.

When your print function is called, the item in the ring buffer has already been consumed. So the peek will give you the next item in the ring buffer.

Quoted 8 lines

2) Adding a closing ';' semicolon to single-line calls. It's the C syntax and i'm missing it :-)

3) The first column: single-character visual shortcuts for "overhead". This is a concept we used in the -rt tracer and it still lives in the latency tracer bits of ftrace and is quite useful:

Quoted 5 lines

'+' means "overhead spike": overhead is above 10 usecs. '!' means "large overhead": overhead is above 100 usecs.

These give at-a-glance hotspot analysis - hotspots are easier to miss as pure numbers.

The latency_trace file has this too. And it uses the above peek to figure it out ;-)

Quoted 21 lines

4) Printing out in units of microseconds, with a decimal point and by explicitly mentioning the 'us' unit.

All of these are important properties: microseconds is still the most common 'overhead' unit in kernel circles. It also gives rather human single-digit or two-digit results. Nanoseconds is three or- four-digit - which is too much. Repeating 'us' so many times is not a problem - these lines will be grepped, quoted, etc - constant reminder about the unit is just fine.

5) Nesting the overhead numbers aligned to the right end of the graph.

This cleans up the view of the source code printout, but not cluttering it with numbers. It also structures the numbers some more. Visual cues are given via '-' and '+' signs, to follow nesting. This nesting aligns up with the function nesting levels on the left side - so it's easy to pair up number and function name. It also separates the numbers from the symbol length effects in the single-line case. (which is the most common trace line)

Quoted 2 lines

What do you think? It's lots of work (sorry! :-), but it would produce even more stunning graph-tracer output IMO.

I like it, and I hope Frederic has enough time on his hands to do it ;)

-- Steve

maintainer
#13 lore raw
In reply to Ingo Molnar
Quoted 39 lines · Ingo Molnar

the regex filter doesnt work well yet when used with the graph tracer:

[ 2994.079079] ------------[ cut here ]------------
[ 2994.079079] WARNING: at kernel/trace/ftrace.c:373 ftrace_bug+0x8c/0x1ce()
[ 2994.079079] Modules linked in:
[ 2994.079079] Pid: 12, comm: kstop/0 Not tainted 2.6.28-rc6-tip #2056
[ 2994.079079] Call Trace:
[ 2994.079079]  [<c02273dd>] warn_on_slowpath+0x46/0x60
[ 2994.079079]  [<c0268308>] ? trace_graph_return+0x89/0xa7
[ 2994.079079]  [<c0268308>] ? trace_graph_return+0x89/0xa7
[ 2994.079079]  [<c0213e85>] ? ftrace_return_to_handler+0x6b/0x74
[ 2994.079079]  [<c0357f66>] ? memcpy+0xe/0x31
[ 2994.079079]  [<c02633e6>] ? rb_commit+0x29/0x2d
[ 2994.079079]  [<c0264c8b>] ? ring_buffer_unlock_commit+0x15/0x1a
[ 2994.079079]  [<c0213ece>] ? ftrace_modify_code+0x21/0xa3
[ 2994.079079]  [<c0213e85>] ? ftrace_return_to_handler+0x6b/0x74
[ 2994.079079]  [<c026c3ce>] ? probe_kernel_read+0xe/0x5c
[ 2994.079079]  [<c0261ec7>] ? trace_selftest_dynamic_test_func+0x3/0xc
[ 2994.079079]  [<c0203926>] ? return_to_handler+0xa/0x14
[ 2994.079079]  [<c0261ec7>] ? trace_selftest_dynamic_test_func+0x3/0xc
[ 2994.079079]  [<c0213ee5>] ? ftrace_modify_code+0x38/0xa3
[ 2994.079079]  [<c0261ec7>] ? trace_selftest_dynamic_test_func+0x3/0xc
[ 2994.079079]  [<c0262749>] ftrace_bug+0x8c/0x1ce
[ 2994.079079]  [<c026299c>] ftrace_replace_code+0x111/0x13d
[ 2994.079079]  [<c0253b53>] ? stop_cpu+0x0/0xa5
[ 2994.079079]  [<c02629e6>] __ftrace_modify_code+0x1e/0x32
[ 2994.079079]  [<c0253bbe>] stop_cpu+0x6b/0xa5
[ 2994.079079]  [<c020391c>] return_to_handler+0x0/0x14
[ 2994.079079]  [<c020391c>] return_to_handler+0x0/0x14
[ 2994.079079]  [<c0237fc1>] ? autoremove_wake_function+0x0/0x35
[ 2994.079079]  [<c023584b>] ? worker_thread+0x0/0xc7
[ 2994.079079]  [<c0237eba>] kthread+0x40/0x66
[ 2994.079079]  [<c0237e7a>] ? kthread+0x0/0x66
[ 2994.079079]  [<c02038cb>] kernel_thread_helper+0x7/0x10
[ 2994.079079] ---[ end trace bff97d149b80ecde ]---
[ 2994.079079] ftrace failed to modify [<c0261ec7>] trace_selftest_dynamic_test_func+0x3/0xc
[ 2994.079079]  actual: e8:0c:1a:fa:ff
Quoted 7 lines

produced via:

 # cd /debug/tracing/
 # cat set_ftrace_filter
 # echo schedule > set_ftrace_filter
 # cat set_ftrace_filter
 cat: set_ftrace_filter: No such device

This is probably fixed with my patch set.

-- Steve

#14 lore raw
Quoted 44 lines · Steven Rostedt
Quoted 41 lines · Ingo Molnar

the regex filter doesnt work well yet when used with the graph tracer:

[ 2994.079079] ------------[ cut here ]------------
[ 2994.079079] WARNING: at kernel/trace/ftrace.c:373 ftrace_bug+0x8c/0x1ce()
[ 2994.079079] Modules linked in:
[ 2994.079079] Pid: 12, comm: kstop/0 Not tainted 2.6.28-rc6-tip #2056
[ 2994.079079] Call Trace:
[ 2994.079079]  [<c02273dd>] warn_on_slowpath+0x46/0x60
[ 2994.079079]  [<c0268308>] ? trace_graph_return+0x89/0xa7
[ 2994.079079]  [<c0268308>] ? trace_graph_return+0x89/0xa7
[ 2994.079079]  [<c0213e85>] ? ftrace_return_to_handler+0x6b/0x74
[ 2994.079079]  [<c0357f66>] ? memcpy+0xe/0x31
[ 2994.079079]  [<c02633e6>] ? rb_commit+0x29/0x2d
[ 2994.079079]  [<c0264c8b>] ? ring_buffer_unlock_commit+0x15/0x1a
[ 2994.079079]  [<c0213ece>] ? ftrace_modify_code+0x21/0xa3
[ 2994.079079]  [<c0213e85>] ? ftrace_return_to_handler+0x6b/0x74
[ 2994.079079]  [<c026c3ce>] ? probe_kernel_read+0xe/0x5c
[ 2994.079079]  [<c0261ec7>] ? trace_selftest_dynamic_test_func+0x3/0xc
[ 2994.079079]  [<c0203926>] ? return_to_handler+0xa/0x14
[ 2994.079079]  [<c0261ec7>] ? trace_selftest_dynamic_test_func+0x3/0xc
[ 2994.079079]  [<c0213ee5>] ? ftrace_modify_code+0x38/0xa3
[ 2994.079079]  [<c0261ec7>] ? trace_selftest_dynamic_test_func+0x3/0xc
[ 2994.079079]  [<c0262749>] ftrace_bug+0x8c/0x1ce
[ 2994.079079]  [<c026299c>] ftrace_replace_code+0x111/0x13d
[ 2994.079079]  [<c0253b53>] ? stop_cpu+0x0/0xa5
[ 2994.079079]  [<c02629e6>] __ftrace_modify_code+0x1e/0x32
[ 2994.079079]  [<c0253bbe>] stop_cpu+0x6b/0xa5
[ 2994.079079]  [<c020391c>] return_to_handler+0x0/0x14
[ 2994.079079]  [<c020391c>] return_to_handler+0x0/0x14
[ 2994.079079]  [<c0237fc1>] ? autoremove_wake_function+0x0/0x35
[ 2994.079079]  [<c023584b>] ? worker_thread+0x0/0xc7
[ 2994.079079]  [<c0237eba>] kthread+0x40/0x66
[ 2994.079079]  [<c0237e7a>] ? kthread+0x0/0x66
[ 2994.079079]  [<c02038cb>] kernel_thread_helper+0x7/0x10
[ 2994.079079] ---[ end trace bff97d149b80ecde ]---
[ 2994.079079] ftrace failed to modify [<c0261ec7>] trace_selftest_dynamic_test_func+0x3/0xc
[ 2994.079079]  actual: e8:0c:1a:fa:ff

produced via:

Quoted 7 lines
Quoted 5 lines
 # cd /debug/tracing/
 # cat set_ftrace_filter
 # echo schedule > set_ftrace_filter
 # cat set_ftrace_filter
 cat: set_ftrace_filter: No such device

This is probably fixed with my patch set.

yeah - but note that the graph-tracer rename came in the way of them. Mind redoing your two patches ontop of latest tip/master?

Ingo

maintainer
#15 lore raw
Quoted 4 lines · Ingo Molnar
Quoted 1 line

This is probably fixed with my patch set.

yeah - but note that the graph-tracer rename came in the way of them. Mind redoing your two patches ontop of latest tip/master?

I expected this. I'll rebase them again.

-- Steve

author
#16 lore raw
In reply to Ingo Molnar

2008/11/26 Ingo Molnar <[email protected]>:

Quoted 39 lines

the regex filter doesnt work well yet when used with the graph tracer:

[ 2994.079079] ------------[ cut here ]------------
[ 2994.079079] WARNING: at kernel/trace/ftrace.c:373 ftrace_bug+0x8c/0x1ce()
[ 2994.079079] Modules linked in:
[ 2994.079079] Pid: 12, comm: kstop/0 Not tainted 2.6.28-rc6-tip #2056
[ 2994.079079] Call Trace:
[ 2994.079079]  [<c02273dd>] warn_on_slowpath+0x46/0x60
[ 2994.079079]  [<c0268308>] ? trace_graph_return+0x89/0xa7
[ 2994.079079]  [<c0268308>] ? trace_graph_return+0x89/0xa7
[ 2994.079079]  [<c0213e85>] ? ftrace_return_to_handler+0x6b/0x74
[ 2994.079079]  [<c0357f66>] ? memcpy+0xe/0x31
[ 2994.079079]  [<c02633e6>] ? rb_commit+0x29/0x2d
[ 2994.079079]  [<c0264c8b>] ? ring_buffer_unlock_commit+0x15/0x1a
[ 2994.079079]  [<c0213ece>] ? ftrace_modify_code+0x21/0xa3
[ 2994.079079]  [<c0213e85>] ? ftrace_return_to_handler+0x6b/0x74
[ 2994.079079]  [<c026c3ce>] ? probe_kernel_read+0xe/0x5c
[ 2994.079079]  [<c0261ec7>] ? trace_selftest_dynamic_test_func+0x3/0xc
[ 2994.079079]  [<c0203926>] ? return_to_handler+0xa/0x14
[ 2994.079079]  [<c0261ec7>] ? trace_selftest_dynamic_test_func+0x3/0xc
[ 2994.079079]  [<c0213ee5>] ? ftrace_modify_code+0x38/0xa3
[ 2994.079079]  [<c0261ec7>] ? trace_selftest_dynamic_test_func+0x3/0xc
[ 2994.079079]  [<c0262749>] ftrace_bug+0x8c/0x1ce
[ 2994.079079]  [<c026299c>] ftrace_replace_code+0x111/0x13d
[ 2994.079079]  [<c0253b53>] ? stop_cpu+0x0/0xa5
[ 2994.079079]  [<c02629e6>] __ftrace_modify_code+0x1e/0x32
[ 2994.079079]  [<c0253bbe>] stop_cpu+0x6b/0xa5
[ 2994.079079]  [<c020391c>] return_to_handler+0x0/0x14
[ 2994.079079]  [<c020391c>] return_to_handler+0x0/0x14
[ 2994.079079]  [<c0237fc1>] ? autoremove_wake_function+0x0/0x35
[ 2994.079079]  [<c023584b>] ? worker_thread+0x0/0xc7
[ 2994.079079]  [<c0237eba>] kthread+0x40/0x66
[ 2994.079079]  [<c0237e7a>] ? kthread+0x0/0x66
[ 2994.079079]  [<c02038cb>] kernel_thread_helper+0x7/0x10
[ 2994.079079] ---[ end trace bff97d149b80ecde ]---
[ 2994.079079] ftrace failed to modify [<c0261ec7>] trace_selftest_dynamic_test_func+0x3/0xc
[ 2994.079079]  actual: e8:0c:1a:fa:ff
Quoted 7 lines

produced via:

 # cd /debug/tracing/
 # cat set_ftrace_filter
 # echo schedule > set_ftrace_filter
 # cat set_ftrace_filter
 cat: set_ftrace_filter: No such device

I didn't met this problem by the past with dynamic filtering on return tracer. Did it occur only with schedule ?
Do the last patches from Steve correct the issue?

author
#8 lore raw
In reply to Ingo Molnar

2008/11/26 Ingo Molnar <[email protected]>:

Quoted 5 lines

1) Compression of non-nested calls into a single line.

Implementing this probably necessiates some trickery with the
ring-buffer: we'd have to look at the next entry as well and see whether it closes the function call.

I wanted to do so. That's not so easy, I guess I will not only have to read the next entry. I'll have to modify it to avoid the next entry to print a closing brace.
But I don't think that would be a problem.
Note with this method that if there is a context switch or an interrupt between the entry and
the return of a leaf function, it will not anymore be considered as a non-nested function on its output.
But the case would be rare enough, so I will apply this.

Quoted 2 lines

2) Adding a closing ';' semicolon to single-line calls. It's the C syntax and i'm missing it :-)

Yeah :-)

Quoted 22 lines

3) The first column: single-character visual shortcuts for "overhead". This is a concept we used in the -rt tracer and it still lives in the latency tracer bits of ftrace and is quite useful:

'+' means "overhead spike": overhead is above 10 usecs. '!' means "large overhead": overhead is above 100 usecs.

These give at-a-glance hotspot analysis - hotspots are easier to miss as pure numbers.

4) Printing out in units of microseconds, with a decimal point and by explicitly mentioning the 'us' unit.

All of these are important properties: microseconds is still the most common 'overhead' unit in kernel circles. It also gives rather human single-digit or two-digit results. Nanoseconds is three or- four-digit - which is too much. Repeating 'us' so many times is not a problem - these lines will be grepped, quoted, etc - constant reminder about the unit is just fine.

5) Nesting the overhead numbers aligned to the right end of the graph.

Quoted 7 lines

This cleans up the view of the source code printout, but not cluttering it with numbers. It also structures the numbers some more. Visual cues are given via '-' and '+' signs, to follow nesting. This nesting aligns up with the function nesting levels on the left side - so it's easy to pair up number and function name. It also separates the numbers from the symbol length effects in the single-line case. (which is the most common trace line)

Totally agree!

Quoted 2 lines

What do you think? It's lots of work (sorry! :-), but it would produce even more stunning graph-tracer output IMO.

Yes, I knew this was only a first try when I submitted it :-) I will apply these suggestions.

Thanks!

author
#11 lore raw
In reply to Ingo Molnar

2008/11/26 Ingo Molnar <[email protected]>:

Quoted 11 lines

there's a small inconsistency here:

# cat available_tracers
function-graph function sched_switch nop

note the '-' versus '_' separators. I wouldnt mind renaming the sched tracer to sched-switch. (and some of the other tracers as well)

Ingo

Will correct it too.

author
#5 lore raw
In reply to Steven Rostedt

2008/11/26 Steven Rostedt <[email protected]>:

Quoted 30 lines · Ingo Molnar
Quoted 8 lines

The changes would be:

1) Compression of non-nested calls into a single line.

Implementing this probably necessiates some trickery with the
ring-buffer: we'd have to look at the next entry as well and see whether it closes the function call.

The latency_trace file does this already:

You can look into the trace buffer without moving it with:

entry = ring_buffer_iter_peek(iter->buffer_iter[iter->cpu], &ts);

where, ts will give you the time stamp, it can be NULL if you do not care.

When your print function is called, the item in the ring buffer has already been consumed. So the peek will give you the next item in the ring buffer.

Quoted 8 lines

2) Adding a closing ';' semicolon to single-line calls. It's the C syntax and i'm missing it :-)

3) The first column: single-character visual shortcuts for "overhead". This is a concept we used in the -rt tracer and it still lives in the latency tracer bits of ftrace and is quite useful:

Quoted 8 lines
Quoted 5 lines

'+' means "overhead spike": overhead is above 10 usecs. '!' means "large overhead": overhead is above 100 usecs.

These give at-a-glance hotspot analysis - hotspots are easier to miss as pure numbers.

The latency_trace file has this too. And it uses the above peek to figure it out ;-)

That's right, the latency_trace does it. But it is based on a ring-buffer entry timestamp.
I wanted to use ring-buffer entry timestamp, but it would be hard to calculate the duration
since the return trace of a function doesn't often follow immediately its entry trace.
And I can't reuse lat_print_timestamp() because I need the nsec remaining part....

This is too specific to reuse latency_trace...

#17 lore raw
In reply to Frédéric Weisbecker
Quoted 49 lines · Frédéric Weisbecker

2008/11/26 Ingo Molnar <[email protected]>:

Quoted 39 lines

the regex filter doesnt work well yet when used with the graph tracer:

[ 2994.079079] ------------[ cut here ]------------
[ 2994.079079] WARNING: at kernel/trace/ftrace.c:373 ftrace_bug+0x8c/0x1ce()
[ 2994.079079] Modules linked in:
[ 2994.079079] Pid: 12, comm: kstop/0 Not tainted 2.6.28-rc6-tip #2056
[ 2994.079079] Call Trace:
[ 2994.079079]  [<c02273dd>] warn_on_slowpath+0x46/0x60
[ 2994.079079]  [<c0268308>] ? trace_graph_return+0x89/0xa7
[ 2994.079079]  [<c0268308>] ? trace_graph_return+0x89/0xa7
[ 2994.079079]  [<c0213e85>] ? ftrace_return_to_handler+0x6b/0x74
[ 2994.079079]  [<c0357f66>] ? memcpy+0xe/0x31
[ 2994.079079]  [<c02633e6>] ? rb_commit+0x29/0x2d
[ 2994.079079]  [<c0264c8b>] ? ring_buffer_unlock_commit+0x15/0x1a
[ 2994.079079]  [<c0213ece>] ? ftrace_modify_code+0x21/0xa3
[ 2994.079079]  [<c0213e85>] ? ftrace_return_to_handler+0x6b/0x74
[ 2994.079079]  [<c026c3ce>] ? probe_kernel_read+0xe/0x5c
[ 2994.079079]  [<c0261ec7>] ? trace_selftest_dynamic_test_func+0x3/0xc
[ 2994.079079]  [<c0203926>] ? return_to_handler+0xa/0x14
[ 2994.079079]  [<c0261ec7>] ? trace_selftest_dynamic_test_func+0x3/0xc
[ 2994.079079]  [<c0213ee5>] ? ftrace_modify_code+0x38/0xa3
[ 2994.079079]  [<c0261ec7>] ? trace_selftest_dynamic_test_func+0x3/0xc
[ 2994.079079]  [<c0262749>] ftrace_bug+0x8c/0x1ce
[ 2994.079079]  [<c026299c>] ftrace_replace_code+0x111/0x13d
[ 2994.079079]  [<c0253b53>] ? stop_cpu+0x0/0xa5
[ 2994.079079]  [<c02629e6>] __ftrace_modify_code+0x1e/0x32
[ 2994.079079]  [<c0253bbe>] stop_cpu+0x6b/0xa5
[ 2994.079079]  [<c020391c>] return_to_handler+0x0/0x14
[ 2994.079079]  [<c020391c>] return_to_handler+0x0/0x14
[ 2994.079079]  [<c0237fc1>] ? autoremove_wake_function+0x0/0x35
[ 2994.079079]  [<c023584b>] ? worker_thread+0x0/0xc7
[ 2994.079079]  [<c0237eba>] kthread+0x40/0x66
[ 2994.079079]  [<c0237e7a>] ? kthread+0x0/0x66
[ 2994.079079]  [<c02038cb>] kernel_thread_helper+0x7/0x10
[ 2994.079079] ---[ end trace bff97d149b80ecde ]---
[ 2994.079079] ftrace failed to modify [<c0261ec7>] trace_selftest_dynamic_test_func+0x3/0xc
[ 2994.079079]  actual: e8:0c:1a:fa:ff
Quoted 7 lines

produced via:

 # cd /debug/tracing/
 # cat set_ftrace_filter
 # echo schedule > set_ftrace_filter
 # cat set_ftrace_filter
 cat: set_ftrace_filter: No such device
Quoted 3 lines

I didn't met this problem by the past with dynamic filtering on return tracer. Did it occur only with schedule ? Do the last patches from Steve correct the issue?

yep. Will re-report it if it occurs again.

Ingo

maintainer
#6 lore raw
In reply to Frédéric Weisbecker
Quoted 24 lines · Fr?d?ric Weisbecker
Quoted 5 lines
Quoted 5 lines

3) The first column: single-character visual shortcuts for "overhead". This is a concept we used in the -rt tracer and it still lives in the latency tracer bits of ftrace and is quite useful:

Quoted 8 lines
Quoted 5 lines

'+' means "overhead spike": overhead is above 10 usecs. '!' means "large overhead": overhead is above 100 usecs.

These give at-a-glance hotspot analysis - hotspots are easier to miss as pure numbers.

The latency_trace file has this too. And it uses the above peek to figure it out ;-)

That's right, the latency_trace does it. But it is based on a ring-buffer entry timestamp.
I wanted to use ring-buffer entry timestamp, but it would be hard to calculate the duration
since the return trace of a function doesn't often follow immediately its entry trace.
And I can't reuse lat_print_timestamp() because I need the nsec remaining part....

Quoted 1 line

This is too specific to reuse latency_trace...

I'd suggest just looking at how those are implemented, and use your own. One note, the latency tracer looks at the next entry, even if it is on another CPU. This is incorrect, and will definitely be incorrect for you. Just use the ring_buffer_iter_peek, that will get you what you want. Well, for leaf functions.

-- Steve

author
#7 lore raw

2008/11/26 Steven Rostedt <[email protected]>:

Quoted 9 lines

I'd suggest just looking at how those are implemented, and use your own. One note, the latency tracer looks at the next entry, even if it is on another CPU. This is incorrect, and will definitely be incorrect for you. Just use the ring_buffer_iter_peek, that will get you what you want. Well, for leaf functions.

-- Steve

Ok, thanks for your tips!

maintainer
#9 lore raw
In reply to Frédéric Weisbecker
Quoted 11 lines · Fr?d?ric Weisbecker

2008/11/26 Ingo Molnar <[email protected]>:

Quoted 5 lines

1) Compression of non-nested calls into a single line.

Implementing this probably necessiates some trickery with the
ring-buffer: we'd have to look at the next entry as well and see whether it closes the function call.

I wanted to do so. That's not so easy, I guess I will not only have to read the next entry. I'll have to modify it to avoid the next entry to print a closing brace.

You could run a ring_buffer_read(iter->buffer_iter[iter->cpu], NULL) and that will consume the next entry, so it will not print.

Quoted 6 lines

But I don't think that would be a problem.
Note with this method that if there is a context switch or an interrupt between the entry and
the return of a leaf function, it will not anymore be considered as a non-nested function on its output.
But the case would be rare enough, so I will apply this.

Yeah, we would not care about that case. In fact it may be best to keep it as is.

-- Steve