* [PATCH] tracing/function-branch-tracer: enhancements for the trace output
@ 2008-11-27 0:46 Frederic Weisbecker
2008-11-27 0:57 ` Frédéric Weisbecker
` (2 more replies)
0 siblings, 3 replies; 25+ messages in thread
From: Frederic Weisbecker @ 2008-11-27 0:46 UTC (permalink / raw)
To: Ingo Molnar; +Cc: Steven Rostedt, Tim Bird, Linux Kernel
Impact: enhancement
This patch applies some ideas of Ingo Molnar and Steven Rostedt.
* Output leaf functions in one line with parenthesis, semicolon and duration
output.
* Add a second column (after cpu) for an overhead sign.
if duration > 100 us, "!"
if duration > 10 us, "+"
else " "
* Print output in us with remaining nanosec: u.n
* Print duration on the right end, following the indentation of the functions.
Use also visual clues: "-" on entry call (no duration to output) and "+" on
return (duration output).
The name of the tracer has been fixed as well: function-branch becomes
function_branch.
Here is an example of the new output:
CPU[000] dequeue_entity() { -
CPU[000] update_curr() { -
CPU[000] update_min_vruntime(); + 0.512 us
CPU[000] } + 1.504 us
CPU[000] clear_buddies(); + 0.481 us
CPU[000] update_min_vruntime(); + 0.504 us
CPU[000] } + 4.557 us
CPU[000] hrtick_update() { -
CPU[000] hrtick_start_fair(); + 0.489 us
CPU[000] } + 1.443 us
CPU[000] + } + 14.655 us
CPU[000] + } + 15.678 us
CPU[000] + } + 16.686 us
CPU[000] msecs_to_jiffies(); + 0.481 us
CPU[000] put_prev_task_fair(); + 0.504 us
CPU[000] pick_next_task_fair(); + 0.482 us
CPU[000] pick_next_task_rt(); + 0.504 us
CPU[000] pick_next_task_fair(); + 0.481 us
CPU[000] pick_next_task_idle(); + 0.489 us
CPU[000] _spin_trylock(); + 0.655 us
CPU[000] _spin_unlock(); + 0.609 us
CPU[000] ------------8<---------- thread bash-2794 ------------8<----------
CPU[000] finish_task_switch() { -
CPU[000] _spin_unlock_irq(); + 0.722 us
CPU[000] } + 2.369 us
CPU[000] ! } + 501972.605 us
CPU[000] ! } + 501973.763 us
CPU[000] copy_from_read_buf() { -
CPU[000] _spin_lock_irqsave(); + 0.670 us
CPU[000] _spin_unlock_irqrestore(); + 0.699 us
CPU[000] copy_to_user() { -
CPU[000] might_fault() { -
CPU[000] __might_sleep(); + 0.503 us
CPU[000] } + 1.632 us
CPU[000] __copy_to_user_ll(); + 0.542 us
CPU[000] } + 3.858 us
CPU[000] tty_audit_add_data() { -
CPU[000] _spin_lock_irq(); + 0.609 us
CPU[000] _spin_unlock_irq(); + 0.624 us
CPU[000] } + 3.196 us
CPU[000] _spin_lock_irqsave(); + 0.624 us
CPU[000] _spin_unlock_irqrestore(); + 0.625 us
CPU[000] + } + 13.611 us
CPU[000] copy_from_read_buf() { -
CPU[000] _spin_lock_irqsave(); + 0.624 us
CPU[000] _spin_unlock_irqrestore(); + 0.616 us
CPU[000] } + 2.820 us
CPU[000]
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
kernel/trace/trace_functions_graph.c | 168 ++++++++++++++++++++++++++++++++--
1 files changed, 159 insertions(+), 9 deletions(-)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index d31d695..b958d60 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -14,6 +14,10 @@
#include "trace.h"
#define TRACE_GRAPH_INDENT 2
+/* Spaces between function call and time duration */
+#define TRACE_GRAPH_TIMESPACE_ENTRY " "
+/* Spaces between function call and closing braces */
+#define TRACE_GRAPH_TIMESPACE_RET " "
#define TRACE_GRAPH_PRINT_OVERRUN 0x1
static struct tracer_opt trace_opts[] = {
@@ -63,26 +67,130 @@ static int verif_pid(struct trace_seq *s, pid_t pid, int cpu)
last_pid[cpu] = pid;
comm = trace_find_cmdline(pid);
- return trace_seq_printf(s, "\nCPU[%03d]"
+ return trace_seq_printf(s, "\nCPU[%03d] "
" ------------8<---------- thread %s-%d"
" ------------8<----------\n\n",
cpu, comm, pid);
}
+static bool
+trace_branch_is_leaf(struct trace_iterator *iter,
+ struct ftrace_graph_ent_entry *curr)
+{
+ struct ring_buffer_iter *ring_iter;
+ struct ring_buffer_event *event;
+ struct ftrace_graph_ret_entry *next;
+
+ ring_iter = iter->buffer_iter[iter->cpu];
+
+ if (!ring_iter)
+ return false;
+
+ event = ring_buffer_iter_peek(iter->buffer_iter[iter->cpu], NULL);
+
+ if (!event)
+ return false;
+
+ next = ring_buffer_event_data(event);
+
+ if (next->ent.type != TRACE_GRAPH_RET)
+ return false;
+
+ if (curr->ent.pid != next->ent.pid ||
+ curr->graph_ent.func != next->ret.func)
+ return false;
+
+ return true;
+}
+
+
+static inline int
+print_graph_duration(unsigned long long duration, struct trace_seq *s)
+{
+ unsigned long nsecs_rem = do_div(duration, 1000);
+ return trace_seq_printf(s, "+ %llu.%lu us\n", duration, nsecs_rem);
+}
+
+/* Signal a overhead of time execution to the output */
+static int
+print_graph_overhead(unsigned long long duration, struct trace_seq *s)
+{
+ /* Duration exceeded 100 msecs */
+ if (duration > 100000ULL)
+ return trace_seq_printf(s, "! ");
+
+ /* Duration exceeded 10 msecs */
+ if (duration > 10000ULL)
+ return trace_seq_printf(s, "+ ");
+
+ return trace_seq_printf(s, " ");
+}
+
+/* Case of a leaf function on its call entry */
static enum print_line_t
-print_graph_entry(struct ftrace_graph_ent *call, struct trace_seq *s,
- struct trace_entry *ent, int cpu)
+print_graph_entry_leaf(struct trace_iterator *iter,
+ struct ftrace_graph_ent_entry *entry, struct trace_seq *s)
{
+ struct ftrace_graph_ret_entry *ret_entry;
+ struct ftrace_graph_ret *graph_ret;
+ struct ring_buffer_event *event;
+ struct ftrace_graph_ent *call;
+ unsigned long long duration;
int i;
int ret;
- if (!verif_pid(s, ent->pid, cpu))
+ event = ring_buffer_read(iter->buffer_iter[iter->cpu], NULL);
+ ret_entry = ring_buffer_event_data(event);
+ graph_ret = &ret_entry->ret;
+ call = &entry->graph_ent;
+ duration = graph_ret->rettime - graph_ret->calltime;
+
+ /* Overhead */
+ ret = print_graph_overhead(duration, s);
+ if (!ret)
return TRACE_TYPE_PARTIAL_LINE;
- ret = trace_seq_printf(s, "CPU[%03d] ", cpu);
+ /* Function */
+ for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
+ ret = trace_seq_printf(s, " ");
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
+ }
+
+ ret = seq_print_ip_sym(s, call->func, 0);
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
+
+ ret = trace_seq_printf(s, "();");
if (!ret)
return TRACE_TYPE_PARTIAL_LINE;
+ /* Duration */
+ ret = trace_seq_printf(s, TRACE_GRAPH_TIMESPACE_ENTRY);
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
+
+ ret = print_graph_duration(duration, s);
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
+
+ return TRACE_TYPE_HANDLED;
+}
+
+static enum print_line_t
+print_graph_entry_nested(struct ftrace_graph_ent_entry *entry,
+ struct trace_seq *s)
+{
+ int i;
+ int ret;
+ struct ftrace_graph_ent *call = &entry->graph_ent;
+
+ /* No overhead */
+ ret = trace_seq_printf(s, " ");
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
+
+ /* Function */
for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
ret = trace_seq_printf(s, " ");
if (!ret)
@@ -93,26 +201,62 @@ print_graph_entry(struct ftrace_graph_ent *call, struct trace_seq *s,
if (!ret)
return TRACE_TYPE_PARTIAL_LINE;
- ret = trace_seq_printf(s, "() {\n");
+ ret = trace_seq_printf(s, "() {");
if (!ret)
return TRACE_TYPE_PARTIAL_LINE;
+
+ /* No duration to print at this state */
+ ret = trace_seq_printf(s, TRACE_GRAPH_TIMESPACE_ENTRY "-\n");
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
+
return TRACE_TYPE_HANDLED;
}
static enum print_line_t
+print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
+ struct trace_iterator *iter, int cpu)
+{
+ int ret;
+ struct trace_entry *ent = iter->ent;
+
+ if (!verif_pid(s, ent->pid, cpu))
+ return TRACE_TYPE_PARTIAL_LINE;
+
+ ret = trace_seq_printf(s, "CPU[%03d] ", cpu);
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
+
+ if (trace_branch_is_leaf(iter, field))
+ return print_graph_entry_leaf(iter, field, s);
+ else
+ return print_graph_entry_nested(field, s);
+
+}
+
+static enum print_line_t
print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
struct trace_entry *ent, int cpu)
{
int i;
int ret;
+ unsigned long long duration = trace->rettime - trace->calltime;
+ /* Pid */
if (!verif_pid(s, ent->pid, cpu))
return TRACE_TYPE_PARTIAL_LINE;
+ /* Cpu */
ret = trace_seq_printf(s, "CPU[%03d] ", cpu);
if (!ret)
return TRACE_TYPE_PARTIAL_LINE;
+ /* Overhead */
+ ret = print_graph_overhead(duration, s);
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
+
+ /* Closing brace */
for (i = 0; i < trace->depth * TRACE_GRAPH_INDENT; i++) {
ret = trace_seq_printf(s, " ");
if (!ret)
@@ -123,10 +267,16 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
if (!ret)
return TRACE_TYPE_PARTIAL_LINE;
- ret = trace_seq_printf(s, "%llu\n", trace->rettime - trace->calltime);
+ /* Duration */
+ ret = trace_seq_printf(s, TRACE_GRAPH_TIMESPACE_RET);
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
+
+ ret = print_graph_duration(duration, s);
if (!ret)
return TRACE_TYPE_PARTIAL_LINE;
+ /* Overrun */
if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERRUN) {
ret = trace_seq_printf(s, " (Overruns: %lu)\n",
trace->overrun);
@@ -146,7 +296,7 @@ print_graph_function(struct trace_iterator *iter)
case TRACE_GRAPH_ENT: {
struct ftrace_graph_ent_entry *field;
trace_assign_type(field, entry);
- return print_graph_entry(&field->graph_ent, s, entry,
+ return print_graph_entry(field, s, iter,
iter->cpu);
}
case TRACE_GRAPH_RET: {
@@ -160,7 +310,7 @@ print_graph_function(struct trace_iterator *iter)
}
static struct tracer graph_trace __read_mostly = {
- .name = "function-graph",
+ .name = "function_graph",
.init = graph_trace_init,
.reset = graph_trace_reset,
.print_line = print_graph_function,
--
1.5.2.5
^ permalink raw reply related [flat|nested] 25+ messages in thread* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 0:46 [PATCH] tracing/function-branch-tracer: enhancements for the trace output Frederic Weisbecker
@ 2008-11-27 0:57 ` Frédéric Weisbecker
2008-11-27 1:08 ` Steven Rostedt
2008-11-27 10:19 ` Peter Zijlstra
2008-11-27 10:34 ` Ingo Molnar
2 siblings, 1 reply; 25+ messages in thread
From: Frédéric Weisbecker @ 2008-11-27 0:57 UTC (permalink / raw)
To: Ingo Molnar; +Cc: Steven Rostedt, Tim Bird, Linux Kernel
2008/11/27 Frederic Weisbecker <fweisbec@gmail.com>:
> Impact: enhancement
>
> This patch applies some ideas of Ingo Molnar and Steven Rostedt.
>
> * Output leaf functions in one line with parenthesis, semicolon and duration
> output.
>
> * Add a second column (after cpu) for an overhead sign.
> if duration > 100 us, "!"
> if duration > 10 us, "+"
> else " "
>
> * Print output in us with remaining nanosec: u.n
>
> * Print duration on the right end, following the indentation of the functions.
> Use also visual clues: "-" on entry call (no duration to output) and "+" on
> return (duration output).
>
> The name of the tracer has been fixed as well: function-branch becomes
> function_branch.
>
> Here is an example of the new output:
>
> CPU[000] dequeue_entity() { -
> CPU[000] update_curr() { -
> CPU[000] update_min_vruntime(); + 0.512 us
> CPU[000] } + 1.504 us
> CPU[000] clear_buddies(); + 0.481 us
> CPU[000] update_min_vruntime(); + 0.504 us
> CPU[000] } + 4.557 us
> CPU[000] hrtick_update() { -
> CPU[000] hrtick_start_fair(); + 0.489 us
> CPU[000] } + 1.443 us
> CPU[000] + } + 14.655 us
> CPU[000] + } + 15.678 us
> CPU[000] + } + 16.686 us
> CPU[000] msecs_to_jiffies(); + 0.481 us
> CPU[000] put_prev_task_fair(); + 0.504 us
> CPU[000] pick_next_task_fair(); + 0.482 us
> CPU[000] pick_next_task_rt(); + 0.504 us
> CPU[000] pick_next_task_fair(); + 0.481 us
> CPU[000] pick_next_task_idle(); + 0.489 us
> CPU[000] _spin_trylock(); + 0.655 us
> CPU[000] _spin_unlock(); + 0.609 us
>
> CPU[000] ------------8<---------- thread bash-2794 ------------8<----------
>
> CPU[000] finish_task_switch() { -
> CPU[000] _spin_unlock_irq(); + 0.722 us
> CPU[000] } + 2.369 us
> CPU[000] ! } + 501972.605 us
> CPU[000] ! } + 501973.763 us
> CPU[000] copy_from_read_buf() { -
> CPU[000] _spin_lock_irqsave(); + 0.670 us
> CPU[000] _spin_unlock_irqrestore(); + 0.699 us
> CPU[000] copy_to_user() { -
> CPU[000] might_fault() { -
> CPU[000] __might_sleep(); + 0.503 us
> CPU[000] } + 1.632 us
> CPU[000] __copy_to_user_ll(); + 0.542 us
> CPU[000] } + 3.858 us
> CPU[000] tty_audit_add_data() { -
> CPU[000] _spin_lock_irq(); + 0.609 us
> CPU[000] _spin_unlock_irq(); + 0.624 us
> CPU[000] } + 3.196 us
> CPU[000] _spin_lock_irqsave(); + 0.624 us
> CPU[000] _spin_unlock_irqrestore(); + 0.625 us
> CPU[000] + } + 13.611 us
> CPU[000] copy_from_read_buf() { -
> CPU[000] _spin_lock_irqsave(); + 0.624 us
> CPU[000] _spin_unlock_irqrestore(); + 0.616 us
> CPU[000] } + 2.820 us
> CPU[000]
>
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> ---
> kernel/trace/trace_functions_graph.c | 168 ++++++++++++++++++++++++++++++++--
> 1 files changed, 159 insertions(+), 9 deletions(-)
>
> diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
> index d31d695..b958d60 100644
> --- a/kernel/trace/trace_functions_graph.c
> +++ b/kernel/trace/trace_functions_graph.c
> @@ -14,6 +14,10 @@
> #include "trace.h"
>
> #define TRACE_GRAPH_INDENT 2
> +/* Spaces between function call and time duration */
> +#define TRACE_GRAPH_TIMESPACE_ENTRY " "
> +/* Spaces between function call and closing braces */
> +#define TRACE_GRAPH_TIMESPACE_RET " "
>
> #define TRACE_GRAPH_PRINT_OVERRUN 0x1
> static struct tracer_opt trace_opts[] = {
> @@ -63,26 +67,130 @@ static int verif_pid(struct trace_seq *s, pid_t pid, int cpu)
> last_pid[cpu] = pid;
> comm = trace_find_cmdline(pid);
>
> - return trace_seq_printf(s, "\nCPU[%03d]"
> + return trace_seq_printf(s, "\nCPU[%03d] "
> " ------------8<---------- thread %s-%d"
> " ------------8<----------\n\n",
> cpu, comm, pid);
> }
>
> +static bool
> +trace_branch_is_leaf(struct trace_iterator *iter,
> + struct ftrace_graph_ent_entry *curr)
> +{
> + struct ring_buffer_iter *ring_iter;
> + struct ring_buffer_event *event;
> + struct ftrace_graph_ret_entry *next;
> +
> + ring_iter = iter->buffer_iter[iter->cpu];
> +
> + if (!ring_iter)
> + return false;
> +
> + event = ring_buffer_iter_peek(iter->buffer_iter[iter->cpu], NULL);
> +
> + if (!event)
> + return false;
> +
> + next = ring_buffer_event_data(event);
> +
> + if (next->ent.type != TRACE_GRAPH_RET)
> + return false;
> +
> + if (curr->ent.pid != next->ent.pid ||
> + curr->graph_ent.func != next->ret.func)
> + return false;
> +
> + return true;
> +}
> +
> +
> +static inline int
> +print_graph_duration(unsigned long long duration, struct trace_seq *s)
> +{
> + unsigned long nsecs_rem = do_div(duration, 1000);
> + return trace_seq_printf(s, "+ %llu.%lu us\n", duration, nsecs_rem);
> +}
> +
> +/* Signal a overhead of time execution to the output */
> +static int
> +print_graph_overhead(unsigned long long duration, struct trace_seq *s)
> +{
> + /* Duration exceeded 100 msecs */
> + if (duration > 100000ULL)
> + return trace_seq_printf(s, "! ");
> +
> + /* Duration exceeded 10 msecs */
> + if (duration > 10000ULL)
> + return trace_seq_printf(s, "+ ");
> +
> + return trace_seq_printf(s, " ");
> +}
> +
> +/* Case of a leaf function on its call entry */
> static enum print_line_t
> -print_graph_entry(struct ftrace_graph_ent *call, struct trace_seq *s,
> - struct trace_entry *ent, int cpu)
> +print_graph_entry_leaf(struct trace_iterator *iter,
> + struct ftrace_graph_ent_entry *entry, struct trace_seq *s)
> {
> + struct ftrace_graph_ret_entry *ret_entry;
> + struct ftrace_graph_ret *graph_ret;
> + struct ring_buffer_event *event;
> + struct ftrace_graph_ent *call;
> + unsigned long long duration;
> int i;
> int ret;
>
> - if (!verif_pid(s, ent->pid, cpu))
> + event = ring_buffer_read(iter->buffer_iter[iter->cpu], NULL);
> + ret_entry = ring_buffer_event_data(event);
> + graph_ret = &ret_entry->ret;
> + call = &entry->graph_ent;
> + duration = graph_ret->rettime - graph_ret->calltime;
> +
> + /* Overhead */
> + ret = print_graph_overhead(duration, s);
> + if (!ret)
> return TRACE_TYPE_PARTIAL_LINE;
>
> - ret = trace_seq_printf(s, "CPU[%03d] ", cpu);
> + /* Function */
> + for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
> + ret = trace_seq_printf(s, " ");
> + if (!ret)
> + return TRACE_TYPE_PARTIAL_LINE;
> + }
> +
> + ret = seq_print_ip_sym(s, call->func, 0);
> + if (!ret)
> + return TRACE_TYPE_PARTIAL_LINE;
> +
> + ret = trace_seq_printf(s, "();");
> if (!ret)
> return TRACE_TYPE_PARTIAL_LINE;
>
> + /* Duration */
> + ret = trace_seq_printf(s, TRACE_GRAPH_TIMESPACE_ENTRY);
> + if (!ret)
> + return TRACE_TYPE_PARTIAL_LINE;
> +
> + ret = print_graph_duration(duration, s);
> + if (!ret)
> + return TRACE_TYPE_PARTIAL_LINE;
> +
> + return TRACE_TYPE_HANDLED;
> +}
> +
> +static enum print_line_t
> +print_graph_entry_nested(struct ftrace_graph_ent_entry *entry,
> + struct trace_seq *s)
> +{
> + int i;
> + int ret;
> + struct ftrace_graph_ent *call = &entry->graph_ent;
> +
> + /* No overhead */
> + ret = trace_seq_printf(s, " ");
> + if (!ret)
> + return TRACE_TYPE_PARTIAL_LINE;
> +
> + /* Function */
> for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
> ret = trace_seq_printf(s, " ");
> if (!ret)
> @@ -93,26 +201,62 @@ print_graph_entry(struct ftrace_graph_ent *call, struct trace_seq *s,
> if (!ret)
> return TRACE_TYPE_PARTIAL_LINE;
>
> - ret = trace_seq_printf(s, "() {\n");
> + ret = trace_seq_printf(s, "() {");
> if (!ret)
> return TRACE_TYPE_PARTIAL_LINE;
> +
> + /* No duration to print at this state */
> + ret = trace_seq_printf(s, TRACE_GRAPH_TIMESPACE_ENTRY "-\n");
> + if (!ret)
> + return TRACE_TYPE_PARTIAL_LINE;
> +
> return TRACE_TYPE_HANDLED;
> }
>
> static enum print_line_t
> +print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
> + struct trace_iterator *iter, int cpu)
> +{
> + int ret;
> + struct trace_entry *ent = iter->ent;
> +
> + if (!verif_pid(s, ent->pid, cpu))
> + return TRACE_TYPE_PARTIAL_LINE;
> +
> + ret = trace_seq_printf(s, "CPU[%03d] ", cpu);
> + if (!ret)
> + return TRACE_TYPE_PARTIAL_LINE;
> +
> + if (trace_branch_is_leaf(iter, field))
> + return print_graph_entry_leaf(iter, field, s);
> + else
> + return print_graph_entry_nested(field, s);
> +
> +}
> +
> +static enum print_line_t
> print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
> struct trace_entry *ent, int cpu)
> {
> int i;
> int ret;
> + unsigned long long duration = trace->rettime - trace->calltime;
>
> + /* Pid */
> if (!verif_pid(s, ent->pid, cpu))
> return TRACE_TYPE_PARTIAL_LINE;
>
> + /* Cpu */
> ret = trace_seq_printf(s, "CPU[%03d] ", cpu);
> if (!ret)
> return TRACE_TYPE_PARTIAL_LINE;
>
> + /* Overhead */
> + ret = print_graph_overhead(duration, s);
> + if (!ret)
> + return TRACE_TYPE_PARTIAL_LINE;
> +
> + /* Closing brace */
> for (i = 0; i < trace->depth * TRACE_GRAPH_INDENT; i++) {
> ret = trace_seq_printf(s, " ");
> if (!ret)
> @@ -123,10 +267,16 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
> if (!ret)
> return TRACE_TYPE_PARTIAL_LINE;
>
> - ret = trace_seq_printf(s, "%llu\n", trace->rettime - trace->calltime);
> + /* Duration */
> + ret = trace_seq_printf(s, TRACE_GRAPH_TIMESPACE_RET);
> + if (!ret)
> + return TRACE_TYPE_PARTIAL_LINE;
> +
> + ret = print_graph_duration(duration, s);
> if (!ret)
> return TRACE_TYPE_PARTIAL_LINE;
>
> + /* Overrun */
> if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERRUN) {
> ret = trace_seq_printf(s, " (Overruns: %lu)\n",
> trace->overrun);
> @@ -146,7 +296,7 @@ print_graph_function(struct trace_iterator *iter)
> case TRACE_GRAPH_ENT: {
> struct ftrace_graph_ent_entry *field;
> trace_assign_type(field, entry);
> - return print_graph_entry(&field->graph_ent, s, entry,
> + return print_graph_entry(field, s, iter,
> iter->cpu);
> }
> case TRACE_GRAPH_RET: {
> @@ -160,7 +310,7 @@ print_graph_function(struct trace_iterator *iter)
> }
>
> static struct tracer graph_trace __read_mostly = {
> - .name = "function-graph",
> + .name = "function_graph",
> .init = graph_trace_init,
> .reset = graph_trace_reset,
> .print_line = print_graph_function,
> --
> 1.5.2.5
>
One detail. If you get a trace through the "trace" file, you will have
no problem.
But if you cat trace_pipe, leaf functions are considered as nested.
This is because iter->buffer_iter[iter->cpu]; is very often (always?)
false by using this file.
I don't know why yet....
But it makes the tracer unable to check the next entry to verify if it
matches its own return.
^ permalink raw reply [flat|nested] 25+ messages in thread* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 0:57 ` Frédéric Weisbecker
@ 2008-11-27 1:08 ` Steven Rostedt
2008-11-27 12:53 ` Frédéric Weisbecker
0 siblings, 1 reply; 25+ messages in thread
From: Steven Rostedt @ 2008-11-27 1:08 UTC (permalink / raw)
To: Frédéric Weisbecker; +Cc: Ingo Molnar, Tim Bird, Linux Kernel
>
>
> One detail. If you get a trace through the "trace" file, you will have
> no problem.
> But if you cat trace_pipe, leaf functions are considered as nested.
>
> This is because iter->buffer_iter[iter->cpu]; is very often (always?)
> false by using this file.
> I don't know why yet....
> But it makes the tracer unable to check the next entry to verify if it
> matches its own return.
That's because trace_pipe does not use an iterator ;-) It is live stream.
There's two cases: static read and consume. On static read we can take
our time and we iterate over the data in the file. The data does not get
consumed so we use an iterator to traverse the data.
The consume read will consume each entry as it reads it. We do not need an
iterator for this because we are always reading the head of the file.
After we read the data, that data is consumed and we read the next item.
Hmm, I may need to make this apparent to the plugins like yours. This way
you can do different things whether it is a static read or a consuming
read.
Perhaps the info now is what you already found out.
"iter->buffer_iter[iter->cpu] will always be NULL when it is a consuming
read. Intead you need to use:
ring_buffer_peek instead of ring_buffer_iter_peek
and
ring_buffer_consume instead of ring_buffer_read
This is the way you can use it:
entry = ring_buffer_peek(iter->tr->buffer, iter->cpu, NULL);
entry = ring_buffer_consume(iter->tr->buffer, iter->cpu, NULL);
-- Steve
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 1:08 ` Steven Rostedt
@ 2008-11-27 12:53 ` Frédéric Weisbecker
0 siblings, 0 replies; 25+ messages in thread
From: Frédéric Weisbecker @ 2008-11-27 12:53 UTC (permalink / raw)
To: Steven Rostedt; +Cc: Ingo Molnar, Tim Bird, Linux Kernel
2008/11/27 Steven Rostedt <rostedt@goodmis.org>:
>
>>
>>
>> One detail. If you get a trace through the "trace" file, you will have
>> no problem.
>> But if you cat trace_pipe, leaf functions are considered as nested.
>>
>> This is because iter->buffer_iter[iter->cpu]; is very often (always?)
>> false by using this file.
>> I don't know why yet....
>> But it makes the tracer unable to check the next entry to verify if it
>> matches its own return.
>
> That's because trace_pipe does not use an iterator ;-) It is live stream.
>
> There's two cases: static read and consume. On static read we can take
> our time and we iterate over the data in the file. The data does not get
> consumed so we use an iterator to traverse the data.
>
> The consume read will consume each entry as it reads it. We do not need an
> iterator for this because we are always reading the head of the file.
> After we read the data, that data is consumed and we read the next item.
>
> Hmm, I may need to make this apparent to the plugins like yours. This way
> you can do different things whether it is a static read or a consuming
> read.
>
> Perhaps the info now is what you already found out.
> "iter->buffer_iter[iter->cpu] will always be NULL when it is a consuming
> read. Intead you need to use:
>
> ring_buffer_peek instead of ring_buffer_iter_peek
>
> and
>
> ring_buffer_consume instead of ring_buffer_read
>
> This is the way you can use it:
>
> entry = ring_buffer_peek(iter->tr->buffer, iter->cpu, NULL);
> entry = ring_buffer_consume(iter->tr->buffer, iter->cpu, NULL);
Ok. Thanks, I will correct it by covering the two cases, like in
trace.c : peek_next_entry()
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 0:46 [PATCH] tracing/function-branch-tracer: enhancements for the trace output Frederic Weisbecker
2008-11-27 0:57 ` Frédéric Weisbecker
@ 2008-11-27 10:19 ` Peter Zijlstra
2008-11-27 14:53 ` Frédéric Weisbecker
2008-11-27 10:34 ` Ingo Molnar
2 siblings, 1 reply; 25+ messages in thread
From: Peter Zijlstra @ 2008-11-27 10:19 UTC (permalink / raw)
To: Frederic Weisbecker; +Cc: Ingo Molnar, Steven Rostedt, Tim Bird, Linux Kernel
On Thu, 2008-11-27 at 01:46 +0100, Frederic Weisbecker wrote:
> Impact: enhancement
>
> This patch applies some ideas of Ingo Molnar and Steven Rostedt.
>
> * Output leaf functions in one line with parenthesis, semicolon and duration
> output.
>
> * Add a second column (after cpu) for an overhead sign.
> if duration > 100 us, "!"
> if duration > 10 us, "+"
> else " "
>
> * Print output in us with remaining nanosec: u.n
>
> * Print duration on the right end, following the indentation of the functions.
> Use also visual clues: "-" on entry call (no duration to output) and "+" on
> return (duration output).
>
> The name of the tracer has been fixed as well: function-branch becomes
> function_branch.
>
> Here is an example of the new output:
>
> CPU[000] dequeue_entity() { -
> CPU[000] update_curr() { -
> CPU[000] update_min_vruntime(); + 0.512 us
> CPU[000] } + 1.504 us
> CPU[000] clear_buddies(); + 0.481 us
> CPU[000] update_min_vruntime(); + 0.504 us
> CPU[000] } + 4.557 us
> CPU[000] hrtick_update() { -
> CPU[000] hrtick_start_fair(); + 0.489 us
> CPU[000] } + 1.443 us
> CPU[000] + } + 14.655 us
> CPU[000] + } + 15.678 us
> CPU[000] + } + 16.686 us
> CPU[000] msecs_to_jiffies(); + 0.481 us
> CPU[000] put_prev_task_fair(); + 0.504 us
> CPU[000] pick_next_task_fair(); + 0.482 us
> CPU[000] pick_next_task_rt(); + 0.504 us
> CPU[000] pick_next_task_fair(); + 0.481 us
> CPU[000] pick_next_task_idle(); + 0.489 us
> CPU[000] _spin_trylock(); + 0.655 us
> CPU[000] _spin_unlock(); + 0.609 us
>
> CPU[000] ------------8<---------- thread bash-2794 ------------8<----------
>
> CPU[000] finish_task_switch() { -
> CPU[000] _spin_unlock_irq(); + 0.722 us
> CPU[000] } + 2.369 us
> CPU[000] ! } + 501972.605 us
> CPU[000] ! } + 501973.763 us
> CPU[000] copy_from_read_buf() { -
> CPU[000] _spin_lock_irqsave(); + 0.670 us
> CPU[000] _spin_unlock_irqrestore(); + 0.699 us
> CPU[000] copy_to_user() { -
> CPU[000] might_fault() { -
> CPU[000] __might_sleep(); + 0.503 us
> CPU[000] } + 1.632 us
> CPU[000] __copy_to_user_ll(); + 0.542 us
> CPU[000] } + 3.858 us
> CPU[000] tty_audit_add_data() { -
> CPU[000] _spin_lock_irq(); + 0.609 us
> CPU[000] _spin_unlock_irq(); + 0.624 us
> CPU[000] } + 3.196 us
> CPU[000] _spin_lock_irqsave(); + 0.624 us
> CPU[000] _spin_unlock_irqrestore(); + 0.625 us
> CPU[000] + } + 13.611 us
> CPU[000] copy_from_read_buf() { -
> CPU[000] _spin_lock_irqsave(); + 0.624 us
> CPU[000] _spin_unlock_irqrestore(); + 0.616 us
> CPU[000] } + 2.820 us
> CPU[000]
May I suggest putting the times in front of the functions, the times can
be rendered in fixed with, avoiding all this unaligned foobar.
Furthermore, it would be really sweet if ftrace_printk() output would be
at the right indentation level wrt the function it was called from. eg.
CPU[000] - do_sync_read() {
CPU[000] # sock: 0x12345 flag: 1
CPU[000] - sock_aio_read() {
...
CPU[000] + 0.123 }
Where the # line is the ftrace_printk() output.
^ permalink raw reply [flat|nested] 25+ messages in thread* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 10:19 ` Peter Zijlstra
@ 2008-11-27 14:53 ` Frédéric Weisbecker
2008-11-27 15:05 ` Ingo Molnar
0 siblings, 1 reply; 25+ messages in thread
From: Frédéric Weisbecker @ 2008-11-27 14:53 UTC (permalink / raw)
To: Peter Zijlstra; +Cc: Ingo Molnar, Steven Rostedt, Tim Bird, Linux Kernel
2008/11/27 Peter Zijlstra <peterz@infradead.org>:
> Furthermore, it would be really sweet if ftrace_printk() output would be
> at the right indentation level wrt the function it was called from. eg.
>
> CPU[000] - do_sync_read() {
> CPU[000] # sock: 0x12345 flag: 1
> CPU[000] - sock_aio_read() {
> ...
> CPU[000] + 0.123 }
>
>
> Where the # line is the ftrace_printk() output.
I didn't think of ftrace_printk yet.
That's a good idea, this way we will see where the ftrace_printk was
called, in which
function at which depth....
Don't you think that would be better to have it as C comments.
We are in a C-style output and ftrace_printk are especially designed for
comments in a trace.
That would make sense to read:
do_sync_read() {
/* sock: 0x12345 flag: 1 */
sock_aio_read() {
0.123 }
^ permalink raw reply [flat|nested] 25+ messages in thread* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 14:53 ` Frédéric Weisbecker
@ 2008-11-27 15:05 ` Ingo Molnar
0 siblings, 0 replies; 25+ messages in thread
From: Ingo Molnar @ 2008-11-27 15:05 UTC (permalink / raw)
To: Frédéric Weisbecker
Cc: Peter Zijlstra, Steven Rostedt, Tim Bird, Linux Kernel
* Frédéric Weisbecker <fweisbec@gmail.com> wrote:
> I didn't think of ftrace_printk yet. That's a good idea, this way we
> will see where the ftrace_printk was called, in which function at
> which depth....
>
> Don't you think that would be better to have it as C comments. We
> are in a C-style output and ftrace_printk are especially designed
> for comments in a trace. That would make sense to read:
>
> do_sync_read() {
> /* sock: 0x12345 flag: 1 */
> sock_aio_read() {
Nice idea :-)
Ingo
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 0:46 [PATCH] tracing/function-branch-tracer: enhancements for the trace output Frederic Weisbecker
2008-11-27 0:57 ` Frédéric Weisbecker
2008-11-27 10:19 ` Peter Zijlstra
@ 2008-11-27 10:34 ` Ingo Molnar
2008-11-27 10:55 ` Peter Zijlstra
2008-11-27 13:06 ` Frédéric Weisbecker
2 siblings, 2 replies; 25+ messages in thread
From: Ingo Molnar @ 2008-11-27 10:34 UTC (permalink / raw)
To: Frederic Weisbecker
Cc: Steven Rostedt, Tim Bird, Linux Kernel, Peter Zijlstra
* Frederic Weisbecker <fweisbec@gmail.com> wrote:
> Here is an example of the new output:
>
> CPU[000] dequeue_entity() { -
> CPU[000] update_curr() { -
> CPU[000] update_min_vruntime(); + 0.512 us
> CPU[000] } + 1.504 us
> CPU[000] clear_buddies(); + 0.481 us
> CPU[000] update_min_vruntime(); + 0.504 us
> CPU[000] } + 4.557 us
> CPU[000] hrtick_update() { -
> CPU[000] hrtick_start_fair(); + 0.489 us
> CPU[000] } + 1.443 us
> CPU[000] + } + 14.655 us
> CPU[000] + } + 15.678 us
> CPU[000] + } + 16.686 us
> CPU[000] msecs_to_jiffies(); + 0.481 us
> CPU[000] put_prev_task_fair(); + 0.504 us
> CPU[000] pick_next_task_fair(); + 0.482 us
> CPU[000] pick_next_task_rt(); + 0.504 us
> CPU[000] pick_next_task_fair(); + 0.481 us
> CPU[000] pick_next_task_idle(); + 0.489 us
> CPU[000] _spin_trylock(); + 0.655 us
> CPU[000] _spin_unlock(); + 0.609 us
>
> CPU[000] ------------8<---------- thread bash-2794 ------------8<----------
>
> CPU[000] finish_task_switch() { -
> CPU[000] _spin_unlock_irq(); + 0.722 us
> CPU[000] } + 2.369 us
> CPU[000] ! } + 501972.605 us
> CPU[000] ! } + 501973.763 us
> CPU[000] copy_from_read_buf() { -
> CPU[000] _spin_lock_irqsave(); + 0.670 us
> CPU[000] _spin_unlock_irqrestore(); + 0.699 us
> CPU[000] copy_to_user() { -
> CPU[000] might_fault() { -
> CPU[000] __might_sleep(); + 0.503 us
> CPU[000] } + 1.632 us
> CPU[000] __copy_to_user_ll(); + 0.542 us
> CPU[000] } + 3.858 us
> CPU[000] tty_audit_add_data() { -
> CPU[000] _spin_lock_irq(); + 0.609 us
> CPU[000] _spin_unlock_irq(); + 0.624 us
> CPU[000] } + 3.196 us
> CPU[000] _spin_lock_irqsave(); + 0.624 us
> CPU[000] _spin_unlock_irqrestore(); + 0.625 us
> CPU[000] + } + 13.611 us
> CPU[000] copy_from_read_buf() { -
> CPU[000] _spin_lock_irqsave(); + 0.624 us
> CPU[000] _spin_unlock_irqrestore(); + 0.616 us
> CPU[000] } + 2.820 us
> CPU[000]
cool :-)
One small detail. Could you please make the cost numbers on the right
side be aligned to the _left_ boundary of the function name, not the
right side of it?
I.e. instead of:
CPU[000] sys_read() { -
CPU[000] fget_light(); + 0.331 us
CPU[000] vfs_read() { -
CPU[000] rw_verify_area() { -
CPU[000] security_file_permission() { -
CPU[000] cap_file_permission(); + 0.306 us
CPU[000] } + 0.993 us
CPU[000] } + 1.649 us
CPU[000] do_sync_read() { -
CPU[000] sock_aio_read() { -
CPU[000] __sock_recvmsg() { -
CPU[000] security_socket_recvmsg() { -
CPU[000] cap_socket_recvmsg(); + 0.319 us
My original suggestion was to have:
CPU[000] sys_read() { -
CPU[000] fget_light(); + 0.331 us
CPU[000] vfs_read() { -
CPU[000] rw_verify_area() { -
CPU[000] security_file_permission() { -
CPU[000] cap_file_permission(); + 0.306 us
CPU[000] } + 0.993 us
CPU[000] } + 1.649 us
CPU[000] do_sync_read() { -
CPU[000] sock_aio_read() { -
CPU[000] __sock_recvmsg() { -
CPU[000] security_socket_recvmsg() { -
CPU[000] cap_socket_recvmsg(); + 0.319 us
Note how much easier it is to line up numbers and nesting with each
other.
But in fact, it might be even better to display the costs like this,
on the left side [mockup]:
---------------------------------------------------------
CPU) cost | function
---------------------------------------------------------
0) | sys_read() {
0) 0.331 us | fget_light();
0) | vfs_read() {
0) | rw_verify_area() {
0) | security_file_permission() {
0) 0.306 us | cap_file_permission();
0) 0.300 us | cap_file_permission();
0) 8.909 us | }
0) 0.993 us | }
0) 11.649 us | }
0) | do_sync_read() {
0) | sock_aio_read() {
0) | __sock_recvmsg() {
0) | security_socket_recvmsg() {
0) 100.319 us | cap_socket_recvmsg();
---------------------------------------------------------
note the 8 small tweaks i did to optimize the visual real estate of
the tracer output:
1) we done need reminders on the left side that this is about CPU
numbers. It will be obvious anyway if it's "all mixed up".
(microseconds is different - that is a unit that will be quoted and
it's also a number that actually matters more in the daily use of
such traces )
2) no need for [] on the left side - a single separator is enough. I
picked ')' as it looks pretty natural and unintrusive.
3) we should use the CPU number width on the left side that
log10(cpus_weight_nr(cpu_online_map)) tells us. So if a system has
just two cores, we should print single-width. If it has 16 CPUs, we
should print 00..01....15.
4) I left 4 decimal points for the cost. That's up to 9999.999
microseconds, after that point we should lose precision and print:
99999.99, then should print up to 999999.9, and then print up to
99999999 microseconds. Always keep the length of the number at 8
characters. Above that, just let the rest shift to the right a bit.
(but that will be about delays of more than 100 seconds - that does
not really matter in practice)
5) Note, by printing the cost at fixed width, we can leave out the '+'
and '!' visual alerts (sorry! :-). The visible width of the numbers
will be enough of an attention grabber - as you can see it in the
mockup above already.
6) Note the vertical '|' separator. I tried it with and without, and i
think the code on the right side looks more structured that way. It
looks like a sheet of paper, and it looks tidier - so please add
it.
7) Note how unobscured the right side code portion looks like this
way. Since this is the only piece of information that is heavily
variable-width, we keep it at the end and dont worry about length
problems.
8) Please print this in the trace header:
---------------------------------------------------------
CPU) cost | function
---------------------------------------------------------
The tabulation format and the field names makes it all more familar
and more friendly to people.
What do you think?
Ingo
^ permalink raw reply [flat|nested] 25+ messages in thread* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 10:34 ` Ingo Molnar
@ 2008-11-27 10:55 ` Peter Zijlstra
2008-11-27 11:29 ` Ingo Molnar
2008-11-27 13:11 ` Frédéric Weisbecker
2008-11-27 13:06 ` Frédéric Weisbecker
1 sibling, 2 replies; 25+ messages in thread
From: Peter Zijlstra @ 2008-11-27 10:55 UTC (permalink / raw)
To: Ingo Molnar; +Cc: Frederic Weisbecker, Steven Rostedt, Tim Bird, Linux Kernel
On Thu, 2008-11-27 at 11:34 +0100, Ingo Molnar wrote:
> * Frederic Weisbecker <fweisbec@gmail.com> wrote:
>
> > Here is an example of the new output:
> >
> > CPU[000] ------------8<---------- thread bash-2794 ------------8<----------
This is the most horrid thing I've ever seen.
Please just put the comm/pid in another left column and leave a plain
"---" string for context switches.
comm/pid only in the separator is useless, you cannot grep stuff like
that, also, what's up with those '8's ?
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 10:55 ` Peter Zijlstra
@ 2008-11-27 11:29 ` Ingo Molnar
2008-11-27 13:18 ` Frédéric Weisbecker
2008-11-27 14:07 ` Steven Rostedt
2008-11-27 13:11 ` Frédéric Weisbecker
1 sibling, 2 replies; 25+ messages in thread
From: Ingo Molnar @ 2008-11-27 11:29 UTC (permalink / raw)
To: Peter Zijlstra
Cc: Frederic Weisbecker, Steven Rostedt, Tim Bird, Linux Kernel
* Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:
> On Thu, 2008-11-27 at 11:34 +0100, Ingo Molnar wrote:
> > * Frederic Weisbecker <fweisbec@gmail.com> wrote:
> >
> > > Here is an example of the new output:
> > >
>
> > > CPU[000] ------------8<---------- thread bash-2794 ------------8<----------
>
> This is the most horrid thing I've ever seen.
Yeah, wanted to point that out too - but i started with the more
commonly used (and most critical) printout portion: the function call
graph itself.
> Please just put the comm/pid in another left column and leave a
> plain "---" string for context switches.
That extra column should be a trace_option though - default-off. (it
uses up quite some screen real estate) It would have to have a width
of 14 characters to be practical:
ssssssss-12345
mockup:
----------------------------------------------------------------
CPU) task-PID | cost | function
----------------------------------------------------------------
0) bash-54320 | | sys_read() {
0) bash-54320 | 0.331 us | fget_light();
0) bash-54320 | | vfs_read() {
0) mycomman-1234 | | rw_verify_area() {
0) mycomman-1234 | 121.444 us | func();
Note some details:
1) longer comm names can be stripped off at 7 chars - 7 chars is
enough to recognize most of the things and the PID is good enough
for extra separation)
2) the ssssssss-12345 task identifier is _center_ aligned. It's a rare
alignment case but useful here: most people look at the command
portion and the whole string must be greppable and useful in traces
as an identifier - so right-aligning the PID is not a good
solution.
3) there's vertical separation after the task portion as well. This
helps us ignore the task portion when we want to look at only the
code and the cost of it. (the common case)
> comm/pid only in the separator is useless, you cannot grep stuff
> like that, also, what's up with those '8's ?
yeah, that context-switch separator is horrible.
We can keep the separator, but as something saner, like:
---------------------------------------------------------
CPU) cost | function
---------------------------------------------------------
0) | sys_read() {
0) 0.331 us | fget_light();
0) | vfs_read() {
0) | rw_verify_area() {
0) | security_file_permission() {
0) 0.306 us | cap_file_permission();
0) 0.300 us | cap_file_permission();
0) 8.909 us | }
0) 0.993 us | }
0) 11.649 us | }
0) | do_sync_read() {
. -------------------------
0) ==> [ bash-2794 => cat-1234 ]
-------------------------
0) | __sock_recvmsg() {
0) | security_socket_recvmsg() {
0) 100.319 us | cap_socket_recvmsg();
---------------------------------------------------------
Note the six small details:
1) '==>' sign put to the vertical separator. This shows that something
flow-intrusive (context-switch) happened.
2) The context-switch printout is in a little box that separates it
from the flow of the outgoing task.
3) there's an extra newline for the incoming flow. Context-switches
are usually attached to the outgoing flow - the incoming flow is
picked semi-randomly, so the newline is a visual separator for that
fact.
4) it uses the ssssssss-12345 taskname convention for both the
outgoing and the incoming task. That makes it greppable
generally.
5) the '----------' lines of the 'box' have no CPU nor task or cost
field. That makes it easy to grep them out - but they are still
helpful visual cues. They are variable length but that's solvable
by using an 'open box' simplification:
0) 0.300 us | cap_file_permission();
0) 8.909 us | }
0) 0.993 us | }
0) 11.649 us | }
0) | do_sync_read() {
. -----------------------------------
0) ==> [ bash-2794 => cat-1234
-----------------------------------
Note how the box top and bottom is 35 characters, fixed. That looks
good with most task identifiers. Even in the worst-case length
length situation it looks good:
. -----------------------------------
0) ==> [ mycomman-12345 => mycomman-12345
-----------------------------------
Or it could be printed out variable length as well - it's a
solvable task :-)
6) note the small dot in the leadin to a context-switch: it's
intentional.
Ingo
^ permalink raw reply [flat|nested] 25+ messages in thread* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 11:29 ` Ingo Molnar
@ 2008-11-27 13:18 ` Frédéric Weisbecker
2008-11-27 14:07 ` Steven Rostedt
1 sibling, 0 replies; 25+ messages in thread
From: Frédéric Weisbecker @ 2008-11-27 13:18 UTC (permalink / raw)
To: Ingo Molnar; +Cc: Peter Zijlstra, Steven Rostedt, Tim Bird, Linux Kernel
2008/11/27 Ingo Molnar <mingo@elte.hu>:
> That extra column should be a trace_option though - default-off. (it
> uses up quite some screen real estate) It would have to have a width
> of 14 characters to be practical:
>
> ssssssss-12345
>
> mockup:
>
> ----------------------------------------------------------------
> CPU) task-PID | cost | function
> ----------------------------------------------------------------
>
> 0) bash-54320 | | sys_read() {
> 0) bash-54320 | 0.331 us | fget_light();
> 0) bash-54320 | | vfs_read() {
> 0) mycomman-1234 | | rw_verify_area() {
> 0) mycomman-1234 | 121.444 us | func();
>
> Note some details:
>
> 1) longer comm names can be stripped off at 7 chars - 7 chars is
> enough to recognize most of the things and the PID is good enough
> for extra separation)
>
> 2) the ssssssss-12345 task identifier is _center_ aligned. It's a rare
> alignment case but useful here: most people look at the command
> portion and the whole string must be greppable and useful in traces
> as an identifier - so right-aligning the PID is not a good
> solution.
>
> 3) there's vertical separation after the task portion as well. This
> helps us ignore the task portion when we want to look at only the
> code and the cost of it. (the common case)
Yeah! I agree with all of that.
And as you said, that should be an option deactivated by default.
>> comm/pid only in the separator is useless, you cannot grep stuff
>> like that, also, what's up with those '8's ?
>
> yeah, that context-switch separator is horrible.
>
> We can keep the separator, but as something saner, like:
>
> ---------------------------------------------------------
> CPU) cost | function
> ---------------------------------------------------------
>
> 0) | sys_read() {
> 0) 0.331 us | fget_light();
> 0) | vfs_read() {
> 0) | rw_verify_area() {
> 0) | security_file_permission() {
> 0) 0.306 us | cap_file_permission();
> 0) 0.300 us | cap_file_permission();
> 0) 8.909 us | }
> 0) 0.993 us | }
> 0) 11.649 us | }
> 0) | do_sync_read() {
> . -------------------------
> 0) ==> [ bash-2794 => cat-1234 ]
> -------------------------
>
> 0) | __sock_recvmsg() {
> 0) | security_socket_recvmsg() {
> 0) 100.319 us | cap_socket_recvmsg();
> ---------------------------------------------------------
>
> Note the six small details:
>
> 1) '==>' sign put to the vertical separator. This shows that something
> flow-intrusive (context-switch) happened.
>
> 2) The context-switch printout is in a little box that separates it
> from the flow of the outgoing task.
>
> 3) there's an extra newline for the incoming flow. Context-switches
> are usually attached to the outgoing flow - the incoming flow is
> picked semi-randomly, so the newline is a visual separator for that
> fact.
>
> 4) it uses the ssssssss-12345 taskname convention for both the
> outgoing and the incoming task. That makes it greppable
> generally.
>
> 5) the '----------' lines of the 'box' have no CPU nor task or cost
> field. That makes it easy to grep them out - but they are still
> helpful visual cues. They are variable length but that's solvable
> by using an 'open box' simplification:
>
> 0) 0.300 us | cap_file_permission();
> 0) 8.909 us | }
> 0) 0.993 us | }
> 0) 11.649 us | }
> 0) | do_sync_read() {
> . -----------------------------------
> 0) ==> [ bash-2794 => cat-1234
> -----------------------------------
>
> Note how the box top and bottom is 35 characters, fixed. That looks
> good with most task identifiers. Even in the worst-case length
> length situation it looks good:
>
> . -----------------------------------
> 0) ==> [ mycomman-12345 => mycomman-12345
> -----------------------------------
>
> Or it could be printed out variable length as well - it's a
> solvable task :-)
>
> 6) note the small dot in the leadin to a context-switch: it's
> intentional.
>
> Ingo
>
That's fair.
I will apply these advices, probably divided in multiple patches....
^ permalink raw reply [flat|nested] 25+ messages in thread* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 11:29 ` Ingo Molnar
2008-11-27 13:18 ` Frédéric Weisbecker
@ 2008-11-27 14:07 ` Steven Rostedt
2008-11-27 14:13 ` Ingo Molnar
1 sibling, 1 reply; 25+ messages in thread
From: Steven Rostedt @ 2008-11-27 14:07 UTC (permalink / raw)
To: Ingo Molnar; +Cc: Peter Zijlstra, Frederic Weisbecker, Tim Bird, Linux Kernel
On Thu, 27 Nov 2008, Ingo Molnar wrote:
>
> mockup:
>
> ----------------------------------------------------------------
> CPU) task-PID | cost | function
> ----------------------------------------------------------------
>
> 0) bash-54320 | | sys_read() {
> 0) bash-54320 | 0.331 us | fget_light();
> 0) bash-54320 | | vfs_read() {
> 0) mycomman-1234 | | rw_verify_area() {
> 0) mycomman-1234 | 121.444 us | func();
>
> Note some details:
>
> 1) longer comm names can be stripped off at 7 chars - 7 chars is
> enough to recognize most of the things and the PID is good enough
> for extra separation)
>
> 2) the ssssssss-12345 task identifier is _center_ aligned. It's a rare
> alignment case but useful here: most people look at the command
> portion and the whole string must be greppable and useful in traces
> as an identifier - so right-aligning the PID is not a good
> solution.
>
> 3) there's vertical separation after the task portion as well. This
> helps us ignore the task portion when we want to look at only the
> code and the cost of it. (the common case)
>
> > comm/pid only in the separator is useless, you cannot grep stuff
> > like that, also, what's up with those '8's ?
>
> yeah, that context-switch separator is horrible.
>
> We can keep the separator, but as something saner, like:
>
> ---------------------------------------------------------
> CPU) cost | function
> ---------------------------------------------------------
>
> 0) | sys_read() {
> 0) 0.331 us | fget_light();
> 0) | vfs_read() {
> 0) | rw_verify_area() {
> 0) | security_file_permission() {
> 0) 0.306 us | cap_file_permission();
> 0) 0.300 us | cap_file_permission();
> 0) 8.909 us | }
> 0) 0.993 us | }
> 0) 11.649 us | }
> 0) | do_sync_read() {
> . -------------------------
> 0) ==> [ bash-2794 => cat-1234 ]
> -------------------------
>
> 0) | __sock_recvmsg() {
> 0) | security_socket_recvmsg() {
> 0) 100.319 us | cap_socket_recvmsg();
> ---------------------------------------------------------
Yes please. I like the separator better. Sure, we could add a trace_option
that will let us print the name on all lines, which will make it grepable
better. But this is better to see when the switch happens.
Also, Frederic could use my ftrace_trace_pid to filter only on a single
thread. But that will need to wait till we figure out this namespace
issue.
-- Steve
^ permalink raw reply [flat|nested] 25+ messages in thread* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 14:07 ` Steven Rostedt
@ 2008-11-27 14:13 ` Ingo Molnar
0 siblings, 0 replies; 25+ messages in thread
From: Ingo Molnar @ 2008-11-27 14:13 UTC (permalink / raw)
To: Steven Rostedt
Cc: Peter Zijlstra, Frederic Weisbecker, Tim Bird, Linux Kernel
* Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Thu, 27 Nov 2008, Ingo Molnar wrote:
>
> >
> > mockup:
> >
> > ----------------------------------------------------------------
> > CPU) task-PID | cost | function
> > ----------------------------------------------------------------
> >
> > 0) bash-54320 | | sys_read() {
> > 0) bash-54320 | 0.331 us | fget_light();
> > 0) bash-54320 | | vfs_read() {
> > 0) mycomman-1234 | | rw_verify_area() {
> > 0) mycomman-1234 | 121.444 us | func();
> >
> > Note some details:
> >
> > 1) longer comm names can be stripped off at 7 chars - 7 chars is
> > enough to recognize most of the things and the PID is good enough
> > for extra separation)
> >
> > 2) the ssssssss-12345 task identifier is _center_ aligned. It's a rare
> > alignment case but useful here: most people look at the command
> > portion and the whole string must be greppable and useful in traces
> > as an identifier - so right-aligning the PID is not a good
> > solution.
> >
> > 3) there's vertical separation after the task portion as well. This
> > helps us ignore the task portion when we want to look at only the
> > code and the cost of it. (the common case)
> >
> > > comm/pid only in the separator is useless, you cannot grep stuff
> > > like that, also, what's up with those '8's ?
> >
> > yeah, that context-switch separator is horrible.
> >
> > We can keep the separator, but as something saner, like:
> >
> > ---------------------------------------------------------
> > CPU) cost | function
> > ---------------------------------------------------------
> >
> > 0) | sys_read() {
> > 0) 0.331 us | fget_light();
> > 0) | vfs_read() {
> > 0) | rw_verify_area() {
> > 0) | security_file_permission() {
> > 0) 0.306 us | cap_file_permission();
> > 0) 0.300 us | cap_file_permission();
> > 0) 8.909 us | }
> > 0) 0.993 us | }
> > 0) 11.649 us | }
> > 0) | do_sync_read() {
> > . -------------------------
> > 0) ==> [ bash-2794 => cat-1234 ]
> > -------------------------
> >
> > 0) | __sock_recvmsg() {
> > 0) | security_socket_recvmsg() {
> > 0) 100.319 us | cap_socket_recvmsg();
> > ---------------------------------------------------------
>
> Yes please. I like the separator better. Sure, we could add a trace_option
> that will let us print the name on all lines, which will make it grepable
> better. But this is better to see when the switch happens.
>
> Also, Frederic could use my ftrace_trace_pid to filter only on a
> single thread. But that will need to wait till we figure out this
> namespace issue.
Note that your PID filter is in tip/tracing/core already, so Frederic
can make use of it if he wishes to. Changing it to struct pid
(whenever that happens) will not change its functionality.
Ingo
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 10:55 ` Peter Zijlstra
2008-11-27 11:29 ` Ingo Molnar
@ 2008-11-27 13:11 ` Frédéric Weisbecker
2008-11-27 14:03 ` Steven Rostedt
1 sibling, 1 reply; 25+ messages in thread
From: Frédéric Weisbecker @ 2008-11-27 13:11 UTC (permalink / raw)
To: Peter Zijlstra; +Cc: Ingo Molnar, Steven Rostedt, Tim Bird, Linux Kernel
2008/11/27 Peter Zijlstra <a.p.zijlstra@chello.nl>:
> On Thu, 2008-11-27 at 11:34 +0100, Ingo Molnar wrote:
>> * Frederic Weisbecker <fweisbec@gmail.com> wrote:
>>
>> > Here is an example of the new output:
>> >
>
>> > CPU[000] ------------8<---------- thread bash-2794 ------------8<----------
>
> This is the most horrid thing I've ever seen.
>
> Please just put the comm/pid in another left column and leave a plain
> "---" string for context switches.
>
> comm/pid only in the separator is useless, you cannot grep stuff like
> that, also, what's up with those '8's ?
You don't like my ungreppable but cute scissors? :-)
Yes, I will fix it.
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 13:11 ` Frédéric Weisbecker
@ 2008-11-27 14:03 ` Steven Rostedt
0 siblings, 0 replies; 25+ messages in thread
From: Steven Rostedt @ 2008-11-27 14:03 UTC (permalink / raw)
To: Frédéric Weisbecker
Cc: Peter Zijlstra, Ingo Molnar, Tim Bird, Linux Kernel
On Thu, 27 Nov 2008, Fr?d?ric Weisbecker wrote:
> 2008/11/27 Peter Zijlstra <a.p.zijlstra@chello.nl>:
> > On Thu, 2008-11-27 at 11:34 +0100, Ingo Molnar wrote:
> >> * Frederic Weisbecker <fweisbec@gmail.com> wrote:
> >>
> >> > Here is an example of the new output:
> >> >
> >
> >> > CPU[000] ------------8<---------- thread bash-2794 ------------8<----------
> >
> > This is the most horrid thing I've ever seen.
> >
> > Please just put the comm/pid in another left column and leave a plain
> > "---" string for context switches.
> >
> > comm/pid only in the separator is useless, you cannot grep stuff like
> > that, also, what's up with those '8's ?
>
>
> You don't like my ungreppable but cute scissors? :-)
> Yes, I will fix it.
scissors! Oh that's what they were!
;-)
-- Steve
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 10:34 ` Ingo Molnar
2008-11-27 10:55 ` Peter Zijlstra
@ 2008-11-27 13:06 ` Frédéric Weisbecker
2008-11-27 13:51 ` Ingo Molnar
1 sibling, 1 reply; 25+ messages in thread
From: Frédéric Weisbecker @ 2008-11-27 13:06 UTC (permalink / raw)
To: Ingo Molnar; +Cc: Steven Rostedt, Tim Bird, Linux Kernel, Peter Zijlstra
2008/11/27 Ingo Molnar <mingo@elte.hu>:
> But in fact, it might be even better to display the costs like this,
> on the left side [mockup]:
>
> ---------------------------------------------------------
> CPU) cost | function
> ---------------------------------------------------------
>
> 0) | sys_read() {
> 0) 0.331 us | fget_light();
> 0) | vfs_read() {
> 0) | rw_verify_area() {
> 0) | security_file_permission() {
> 0) 0.306 us | cap_file_permission();
> 0) 0.300 us | cap_file_permission();
> 0) 8.909 us | }
> 0) 0.993 us | }
> 0) 11.649 us | }
> 0) | do_sync_read() {
> 0) | sock_aio_read() {
> 0) | __sock_recvmsg() {
> 0) | security_socket_recvmsg() {
> 0) 100.319 us | cap_socket_recvmsg();
> ---------------------------------------------------------
>
> note the 8 small tweaks i did to optimize the visual real estate of
> the tracer output:
>
> 1) we done need reminders on the left side that this is about CPU
> numbers. It will be obvious anyway if it's "all mixed up".
> (microseconds is different - that is a unit that will be quoted and
> it's also a number that actually matters more in the daily use of
> such traces )
>
> 2) no need for [] on the left side - a single separator is enough. I
> picked ')' as it looks pretty natural and unintrusive.
>
> 3) we should use the CPU number width on the left side that
> log10(cpus_weight_nr(cpu_online_map)) tells us. So if a system has
> just two cores, we should print single-width. If it has 16 CPUs, we
> should print 00..01....15.
>
> 4) I left 4 decimal points for the cost. That's up to 9999.999
> microseconds, after that point we should lose precision and print:
> 99999.99, then should print up to 999999.9, and then print up to
> 99999999 microseconds. Always keep the length of the number at 8
> characters. Above that, just let the rest shift to the right a bit.
> (but that will be about delays of more than 100 seconds - that does
> not really matter in practice)
>
> 5) Note, by printing the cost at fixed width, we can leave out the '+'
> and '!' visual alerts (sorry! :-). The visible width of the numbers
> will be enough of an attention grabber - as you can see it in the
> mockup above already.
>
> 6) Note the vertical '|' separator. I tried it with and without, and i
> think the code on the right side looks more structured that way. It
> looks like a sheet of paper, and it looks tidier - so please add
> it.
>
> 7) Note how unobscured the right side code portion looks like this
> way. Since this is the only piece of information that is heavily
> variable-width, we keep it at the end and dont worry about length
> problems.
Yeah, I will miss a bit the overhead signs, they were really useful to
find in one
quick sight a costly function call.
I know that the decimal. The visible width of the duration replaces it but not
as much efficiently.
Moreover, put these times on the full left will be perhaps harder for
the eyes to retrieve the concerned
function return (thinking of a deep calls).
I don't know, perhaps that will actually be better in practice...
> 8) Please print this in the trace header:
>
> ---------------------------------------------------------
> CPU) cost | function
> ---------------------------------------------------------
>
> The tabulation format and the field names makes it all more familar
> and more friendly to people.
>
> What do you think?
>
> Ingo
>
Ok.
^ permalink raw reply [flat|nested] 25+ messages in thread* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 13:06 ` Frédéric Weisbecker
@ 2008-11-27 13:51 ` Ingo Molnar
2008-11-27 14:44 ` Frédéric Weisbecker
0 siblings, 1 reply; 25+ messages in thread
From: Ingo Molnar @ 2008-11-27 13:51 UTC (permalink / raw)
To: Frédéric Weisbecker
Cc: Steven Rostedt, Tim Bird, Linux Kernel, Peter Zijlstra
* Frédéric Weisbecker <fweisbec@gmail.com> wrote:
> 2008/11/27 Ingo Molnar <mingo@elte.hu>:
> > But in fact, it might be even better to display the costs like this,
> > on the left side [mockup]:
> >
> > ---------------------------------------------------------
> > CPU) cost | function
> > ---------------------------------------------------------
> >
> > 0) | sys_read() {
> > 0) 0.331 us | fget_light();
> > 0) | vfs_read() {
> > 0) | rw_verify_area() {
> > 0) | security_file_permission() {
> > 0) 0.306 us | cap_file_permission();
> > 0) 0.300 us | cap_file_permission();
> > 0) 8.909 us | }
> > 0) 0.993 us | }
> > 0) 11.649 us | }
> > 0) | do_sync_read() {
> > 0) | sock_aio_read() {
> > 0) | __sock_recvmsg() {
> > 0) | security_socket_recvmsg() {
> > 0) 100.319 us | cap_socket_recvmsg();
> > ---------------------------------------------------------
> >
> > note the 8 small tweaks i did to optimize the visual real estate of
> > the tracer output:
> >
> > 1) we done need reminders on the left side that this is about CPU
> > numbers. It will be obvious anyway if it's "all mixed up".
> > (microseconds is different - that is a unit that will be quoted and
> > it's also a number that actually matters more in the daily use of
> > such traces )
> >
> > 2) no need for [] on the left side - a single separator is enough. I
> > picked ')' as it looks pretty natural and unintrusive.
> >
> > 3) we should use the CPU number width on the left side that
> > log10(cpus_weight_nr(cpu_online_map)) tells us. So if a system has
> > just two cores, we should print single-width. If it has 16 CPUs, we
> > should print 00..01....15.
> >
> > 4) I left 4 decimal points for the cost. That's up to 9999.999
> > microseconds, after that point we should lose precision and print:
> > 99999.99, then should print up to 999999.9, and then print up to
> > 99999999 microseconds. Always keep the length of the number at 8
> > characters. Above that, just let the rest shift to the right a bit.
> > (but that will be about delays of more than 100 seconds - that does
> > not really matter in practice)
> >
> > 5) Note, by printing the cost at fixed width, we can leave out the '+'
> > and '!' visual alerts (sorry! :-). The visible width of the numbers
> > will be enough of an attention grabber - as you can see it in the
> > mockup above already.
> >
> > 6) Note the vertical '|' separator. I tried it with and without, and i
> > think the code on the right side looks more structured that way. It
> > looks like a sheet of paper, and it looks tidier - so please add
> > it.
> >
> > 7) Note how unobscured the right side code portion looks like this
> > way. Since this is the only piece of information that is heavily
> > variable-width, we keep it at the end and dont worry about length
> > problems.
>
>
> Yeah, I will miss a bit the overhead signs, they were really useful
> to find in one quick sight a costly function call. I know that the
> decimal. The visible width of the duration replaces it but not as
> much efficiently. Moreover, put these times on the full left will be
> perhaps harder for the eyes to retrieve the concerned function
> return (thinking of a deep calls).
We can still add the overhead signs.
We still have a single space in the first column before the CPU number
(that looks better when these traces are pasted into email, which is
one of the most common uses of them), and we can add the sign there.
I.e. something like this:
> > ---------------------------------------------------------
> > CPU) cost | function
> > ---------------------------------------------------------
> >
> > 0) | sys_read() {
> > 0) 0.331 us | fget_light();
> > 0) | vfs_read() {
> > 0) | rw_verify_area() {
> > 0) | security_file_permission() {
> > 0) 0.306 us | cap_file_permission();
> > 0) 0.300 us | cap_file_permission();
> > 0) 8.909 us | }
> > 0) 0.993 us | }
> > +0) 11.649 us | }
> > 0) | do_sync_read() {
> > 0) | sock_aio_read() {
> > 0) | __sock_recvmsg() {
> > 0) | security_socket_recvmsg() {
> > !0) 100.319 us | cap_socket_recvmsg();
> > ---------------------------------------------------------
Or we could add them to the function name bit - there we have two free
space characters anyway:
Something like this:
> > ---------------------------------------------------------
> > CPU) cost | function
> > ---------------------------------------------------------
> >
> > 0) | sys_read() {
> > 0) 0.331 us | fget_light();
> > 0) | vfs_read() {
> > 0) | rw_verify_area() {
> > 0) | security_file_permission() {
> > 0) 0.306 us | cap_file_permission();
> > 0) 0.300 us | cap_file_permission();
> > 0) 8.909 us | }
> > 0) 0.993 us | }
> > 0) 11.649 us |+ }
> > 0) | do_sync_read() {
> > 0) | sock_aio_read() {
> > 0) | __sock_recvmsg() {
> > 0) | security_socket_recvmsg() {
> > 0) 100.319 us |! cap_socket_recvmsg();
> > ---------------------------------------------------------
Hm?
> I don't know, perhaps that will actually be better in practice...
i think it will be better. I'm biased, so i gave the output to two
people with good visual taste (one of them female), [note, i gave them
the mockup from the previous mail] and the first question of both of
them was: "why arent the times on the left?".
I think we could make the time column a trace_option as well -
default-enabled.
Ingo
^ permalink raw reply [flat|nested] 25+ messages in thread* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 13:51 ` Ingo Molnar
@ 2008-11-27 14:44 ` Frédéric Weisbecker
2008-11-27 14:46 ` Ingo Molnar
2008-11-27 15:31 ` Steven Rostedt
0 siblings, 2 replies; 25+ messages in thread
From: Frédéric Weisbecker @ 2008-11-27 14:44 UTC (permalink / raw)
To: Ingo Molnar; +Cc: Steven Rostedt, Tim Bird, Linux Kernel, Peter Zijlstra
2008/11/27 Ingo Molnar <mingo@elte.hu>:
> We can still add the overhead signs.
>
> We still have a single space in the first column before the CPU number
> (that looks better when these traces are pasted into email, which is
> one of the most common uses of them), and we can add the sign there.
>
> I.e. something like this:
>
>> > ---------------------------------------------------------
>> > CPU) cost | function
>> > ---------------------------------------------------------
>> >
>> > 0) | sys_read() {
>> > 0) 0.331 us | fget_light();
>> > 0) | vfs_read() {
>> > 0) | rw_verify_area() {
>> > 0) | security_file_permission() {
>> > 0) 0.306 us | cap_file_permission();
>> > 0) 0.300 us | cap_file_permission();
>> > 0) 8.909 us | }
>> > 0) 0.993 us | }
>> > +0) 11.649 us | }
>> > 0) | do_sync_read() {
>> > 0) | sock_aio_read() {
>> > 0) | __sock_recvmsg() {
>> > 0) | security_socket_recvmsg() {
>> > !0) 100.319 us | cap_socket_recvmsg();
>> > ---------------------------------------------------------
>
> Or we could add them to the function name bit - there we have two free
> space characters anyway:
>
> Something like this:
>
>> > ---------------------------------------------------------
>> > CPU) cost | function
>> > ---------------------------------------------------------
>> >
>> > 0) | sys_read() {
>> > 0) 0.331 us | fget_light();
>> > 0) | vfs_read() {
>> > 0) | rw_verify_area() {
>> > 0) | security_file_permission() {
>> > 0) 0.306 us | cap_file_permission();
>> > 0) 0.300 us | cap_file_permission();
>> > 0) 8.909 us | }
>> > 0) 0.993 us | }
>> > 0) 11.649 us |+ }
>> > 0) | do_sync_read() {
>> > 0) | sock_aio_read() {
>> > 0) | __sock_recvmsg() {
>> > 0) | security_socket_recvmsg() {
>> > 0) 100.319 us |! cap_socket_recvmsg();
>> > ---------------------------------------------------------
>
> Hm?
I like it before the CPU number. The main purpose would be to scroll
quickly the file and find the overheads. That would be easy if set as
a first character.
I will set it as a default disabled option.
>
>> I don't know, perhaps that will actually be better in practice...
>
> i think it will be better. I'm biased, so i gave the output to two
> people with good visual taste (one of them female), [note, i gave them
> the mockup from the previous mail] and the first question of both of
> them was: "why arent the times on the left?".
Really?
Actually yes, I'm certainly biased too.
> I think we could make the time column a trace_option as well -
> default-enabled.
Ok, I will apply it.
^ permalink raw reply [flat|nested] 25+ messages in thread* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 14:44 ` Frédéric Weisbecker
@ 2008-11-27 14:46 ` Ingo Molnar
2008-11-27 14:58 ` Frédéric Weisbecker
2008-11-27 15:31 ` Steven Rostedt
1 sibling, 1 reply; 25+ messages in thread
From: Ingo Molnar @ 2008-11-27 14:46 UTC (permalink / raw)
To: Frédéric Weisbecker
Cc: Steven Rostedt, Tim Bird, Linux Kernel, Peter Zijlstra
* Frédéric Weisbecker <fweisbec@gmail.com> wrote:
> >> > 0) 0.993 us | }
> >> > +0) 11.649 us | }
> >> > 0) | do_sync_read() {
> >> > 0) | sock_aio_read() {
> >> > 0) | __sock_recvmsg() {
> >> > 0) | security_socket_recvmsg() {
> >> > !0) 100.319 us | cap_socket_recvmsg();
> >> > ---------------------------------------------------------
>
> I like it before the CPU number. The main purpose would be to scroll
> quickly the file and find the overheads. That would be easy if set
> as a first character.
>
> I will set it as a default disabled option.
lets keep it default-enabled, ok? It makes sense.
Ingo
^ permalink raw reply [flat|nested] 25+ messages in thread* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 14:46 ` Ingo Molnar
@ 2008-11-27 14:58 ` Frédéric Weisbecker
2008-11-27 15:03 ` Ingo Molnar
0 siblings, 1 reply; 25+ messages in thread
From: Frédéric Weisbecker @ 2008-11-27 14:58 UTC (permalink / raw)
To: Ingo Molnar; +Cc: Steven Rostedt, Tim Bird, Linux Kernel, Peter Zijlstra
2008/11/27 Ingo Molnar <mingo@elte.hu>:
>
> * Frédéric Weisbecker <fweisbec@gmail.com> wrote:
>
>> >> > 0) 0.993 us | }
>> >> > +0) 11.649 us | }
>> >> > 0) | do_sync_read() {
>> >> > 0) | sock_aio_read() {
>> >> > 0) | __sock_recvmsg() {
>> >> > 0) | security_socket_recvmsg() {
>> >> > !0) 100.319 us | cap_socket_recvmsg();
>> >> > ---------------------------------------------------------
>>
>> I like it before the CPU number. The main purpose would be to scroll
>> quickly the file and find the overheads. That would be easy if set
>> as a first character.
>>
>> I will set it as a default disabled option.
>
> lets keep it default-enabled, ok? It makes sense.
Ok.
BTW I understand why it is better to have a "pipe" if there is no time:
0) | do_sync_read() {
0) | sock_aio_read() {
0) | __sock_recvmsg() {
0) | security_socket_recvmsg() {
But I don't see why it is necessary to have one just after the time:
!0) 100.319 us | cap_socket_recvmsg();
It appears to me as noise....
^ permalink raw reply [flat|nested] 25+ messages in thread* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 14:58 ` Frédéric Weisbecker
@ 2008-11-27 15:03 ` Ingo Molnar
2008-11-27 15:09 ` Frédéric Weisbecker
0 siblings, 1 reply; 25+ messages in thread
From: Ingo Molnar @ 2008-11-27 15:03 UTC (permalink / raw)
To: Frédéric Weisbecker
Cc: Steven Rostedt, Tim Bird, Linux Kernel, Peter Zijlstra
* Frédéric Weisbecker <fweisbec@gmail.com> wrote:
> 2008/11/27 Ingo Molnar <mingo@elte.hu>:
> >
> > * Frédéric Weisbecker <fweisbec@gmail.com> wrote:
> >
> >> >> > 0) 0.993 us | }
> >> >> > +0) 11.649 us | }
> >> >> > 0) | do_sync_read() {
> >> >> > 0) | sock_aio_read() {
> >> >> > 0) | __sock_recvmsg() {
> >> >> > 0) | security_socket_recvmsg() {
> >> >> > !0) 100.319 us | cap_socket_recvmsg();
> >> >> > ---------------------------------------------------------
> >>
> >> I like it before the CPU number. The main purpose would be to scroll
> >> quickly the file and find the overheads. That would be easy if set
> >> as a first character.
> >>
> >> I will set it as a default disabled option.
> >
> > lets keep it default-enabled, ok? It makes sense.
>
> Ok.
> BTW I understand why it is better to have a "pipe" if there is no time:
>
> 0) | do_sync_read() {
> 0) | sock_aio_read() {
> 0) | __sock_recvmsg() {
> 0) | security_socket_recvmsg() {
>
> But I don't see why it is necessary to have one just after the time:
>
> !0) 100.319 us | cap_socket_recvmsg();
>
> It appears to me as noise....
if you look at it on a console where you look at code, it all looks
like a straight line:
0) | sys_read() {
0) 0.331 us | fget_light();
0) | vfs_read() {
0) | rw_verify_area() {
0) | security_file_permission() {
0) 0.306 us | cap_file_permission();
0) 0.300 us | cap_file_permission();
0) 8.909 us | }
0) 0.993 us | }
0) 11.649 us | }
0) | do_sync_read() {
. -------------------------
0) ==> [ bash-2794 => cat-1234 ]
-------------------------
as if the code to the right was on a sheet of paper.
If i understand you correct, are you suggesting this format:
0) | sys_read() {
0) 0.331 us fget_light();
0) | vfs_read() {
0) | rw_verify_area() {
0) | security_file_permission() {
0) 0.306 us cap_file_permission();
0) 0.300 us cap_file_permission();
0) 8.909 us }
0) 0.993 us }
0) 11.649 us }
0) | do_sync_read() {
. -------------------------
0) ==> [ bash-2794 => cat-1234 ]
-------------------------
i dont think that looks very good.
Ingo
^ permalink raw reply [flat|nested] 25+ messages in thread* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 15:03 ` Ingo Molnar
@ 2008-11-27 15:09 ` Frédéric Weisbecker
0 siblings, 0 replies; 25+ messages in thread
From: Frédéric Weisbecker @ 2008-11-27 15:09 UTC (permalink / raw)
To: Ingo Molnar; +Cc: Steven Rostedt, Tim Bird, Linux Kernel, Peter Zijlstra
2008/11/27 Ingo Molnar <mingo@elte.hu>:
> if you look at it on a console where you look at code, it all looks
> like a straight line:
>
>
> 0) | sys_read() {
> 0) 0.331 us | fget_light();
> 0) | vfs_read() {
> 0) | rw_verify_area() {
> 0) | security_file_permission() {
> 0) 0.306 us | cap_file_permission();
> 0) 0.300 us | cap_file_permission();
> 0) 8.909 us | }
> 0) 0.993 us | }
> 0) 11.649 us | }
> 0) | do_sync_read() {
> . -------------------------
> 0) ==> [ bash-2794 => cat-1234 ]
> -------------------------
>
>
> as if the code to the right was on a sheet of paper.
>
> If i understand you correct, are you suggesting this format:
>
> 0) | sys_read() {
> 0) 0.331 us fget_light();
> 0) | vfs_read() {
> 0) | rw_verify_area() {
> 0) | security_file_permission() {
> 0) 0.306 us cap_file_permission();
> 0) 0.300 us cap_file_permission();
> 0) 8.909 us }
> 0) 0.993 us }
> 0) 11.649 us }
> 0) | do_sync_read() {
> . -------------------------
> 0) ==> [ bash-2794 => cat-1234 ]
> -------------------------
>
> i dont think that looks very good.
Hmm. I must confess that it draws a useful boundary for the eyes.
Ok.
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 14:44 ` Frédéric Weisbecker
2008-11-27 14:46 ` Ingo Molnar
@ 2008-11-27 15:31 ` Steven Rostedt
2008-11-27 15:51 ` Frédéric Weisbecker
2008-11-28 13:05 ` Ingo Molnar
1 sibling, 2 replies; 25+ messages in thread
From: Steven Rostedt @ 2008-11-27 15:31 UTC (permalink / raw)
To: Frédéric Weisbecker
Cc: Ingo Molnar, Tim Bird, Linux Kernel, Peter Zijlstra
On Thu, 27 Nov 2008, Fr?d?ric Weisbecker wrote:
> >
> >> > ---------------------------------------------------------
> >> > CPU) cost | function
> >> > ---------------------------------------------------------
> >> >
> >> > 0) | sys_read() {
> >> > 0) 0.331 us | fget_light();
> >> > 0) | vfs_read() {
> >> > 0) | rw_verify_area() {
> >> > 0) | security_file_permission() {
> >> > 0) 0.306 us | cap_file_permission();
> >> > 0) 0.300 us | cap_file_permission();
> >> > 0) 8.909 us | }
> >> > 0) 0.993 us | }
> >> > 0) 11.649 us |+ }
> >> > 0) | do_sync_read() {
> >> > 0) | sock_aio_read() {
> >> > 0) | __sock_recvmsg() {
> >> > 0) | security_socket_recvmsg() {
> >> > 0) 100.319 us |! cap_socket_recvmsg();
> >> > ---------------------------------------------------------
> >
> > Hm?
>
> I like it before the CPU number. The main purpose would be to scroll
> quickly the file and find the overheads. That would be easy if set as
> a first character.
No, please keep the CPU # first. If anything, you will want to separate
out the CPUs first. Otherwise you will see things all mixed up.
Hmm, I could also add a per cpu files.
debugfs/tracing/buffers/cpu0
debugfs/tracing/buffers/cpu1
debugfs/tracing/buffers/cpu2
debugfs/tracing/buffers/cpu3
That would print out the trace for a single CPU.
BTW, I'm really not here. I'm on holiday eating turkeys.
-- Steve
^ permalink raw reply [flat|nested] 25+ messages in thread* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 15:31 ` Steven Rostedt
@ 2008-11-27 15:51 ` Frédéric Weisbecker
2008-11-28 13:05 ` Ingo Molnar
1 sibling, 0 replies; 25+ messages in thread
From: Frédéric Weisbecker @ 2008-11-27 15:51 UTC (permalink / raw)
To: Steven Rostedt; +Cc: Ingo Molnar, Tim Bird, Linux Kernel, Peter Zijlstra
2008/11/27 Steven Rostedt <rostedt@goodmis.org>:
> No, please keep the CPU # first. If anything, you will want to separate
> out the CPUs first. Otherwise you will see things all mixed up.
So perhaps between CPU and time?
I don't really like it after the time, not so easy to find....
> Hmm, I could also add a per cpu files.
>
> debugfs/tracing/buffers/cpu0
> debugfs/tracing/buffers/cpu1
> debugfs/tracing/buffers/cpu2
> debugfs/tracing/buffers/cpu3
That would be useful indeed, as the ftrace_trace_pid on this tracer.
But I wonder about the cost of double function tracing in this case.
Your idea of a tgid;pid would be nice (with tgid || pid).
> That would print out the trace for a single CPU.
>
> BTW, I'm really not here. I'm on holiday eating turkeys.
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH] tracing/function-branch-tracer: enhancements for the trace output
2008-11-27 15:31 ` Steven Rostedt
2008-11-27 15:51 ` Frédéric Weisbecker
@ 2008-11-28 13:05 ` Ingo Molnar
1 sibling, 0 replies; 25+ messages in thread
From: Ingo Molnar @ 2008-11-28 13:05 UTC (permalink / raw)
To: Steven Rostedt
Cc: Frédéric Weisbecker, Tim Bird, Linux Kernel,
Peter Zijlstra
* Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Thu, 27 Nov 2008, Fr?d?ric Weisbecker wrote:
> > >
> > >> > ---------------------------------------------------------
> > >> > CPU) cost | function
> > >> > ---------------------------------------------------------
> > >> >
> > >> > 0) | sys_read() {
> > >> > 0) 0.331 us | fget_light();
> > >> > 0) | vfs_read() {
> > >> > 0) | rw_verify_area() {
> > >> > 0) | security_file_permission() {
> > >> > 0) 0.306 us | cap_file_permission();
> > >> > 0) 0.300 us | cap_file_permission();
> > >> > 0) 8.909 us | }
> > >> > 0) 0.993 us | }
> > >> > 0) 11.649 us |+ }
> > >> > 0) | do_sync_read() {
> > >> > 0) | sock_aio_read() {
> > >> > 0) | __sock_recvmsg() {
> > >> > 0) | security_socket_recvmsg() {
> > >> > 0) 100.319 us |! cap_socket_recvmsg();
> > >> > ---------------------------------------------------------
> > >
> > > Hm?
> >
> > I like it before the CPU number. The main purpose would be to scroll
> > quickly the file and find the overheads. That would be easy if set as
> > a first character.
>
> No, please keep the CPU # first. If anything, you will want to separate
> out the CPUs first. Otherwise you will see things all mixed up.
>
> Hmm, I could also add a per cpu files.
>
> debugfs/tracing/buffers/cpu0
> debugfs/tracing/buffers/cpu1
> debugfs/tracing/buffers/cpu2
> debugfs/tracing/buffers/cpu3
>
> That would print out the trace for a single CPU.
yes, doing that makes sense anyway: if someone wants to make the mistake
of capturing a _LOT_ of tracing events without pre-filtering them in the
kernel intelligently (just to be able to waste days sorting them apart
and analyzing them, and then billing the client for the cost), then it
would make sense to start 4 threads on all 4 CPUs, switch the ftrace
output mode into raw binary format and read the per cpu buffers into
userspace buffer.
We could perhaps even zero-copy it all straight to the pagecache: the
ring-buffer is 4K pages based already and the data is position
independent.
->splice_read() / ->splice_write() support for the ring-buffer would
nicely enable all of that, to all splice-able IO transports. (i.e. the
majority of IO transports that matter)
> BTW, I'm really not here. I'm on holiday eating turkeys.
okay.
Ingo
^ permalink raw reply [flat|nested] 25+ messages in thread
end of thread, other threads:[~2008-11-28 13:05 UTC | newest]
Thread overview: 25+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2008-11-27 0:46 [PATCH] tracing/function-branch-tracer: enhancements for the trace output Frederic Weisbecker
2008-11-27 0:57 ` Frédéric Weisbecker
2008-11-27 1:08 ` Steven Rostedt
2008-11-27 12:53 ` Frédéric Weisbecker
2008-11-27 10:19 ` Peter Zijlstra
2008-11-27 14:53 ` Frédéric Weisbecker
2008-11-27 15:05 ` Ingo Molnar
2008-11-27 10:34 ` Ingo Molnar
2008-11-27 10:55 ` Peter Zijlstra
2008-11-27 11:29 ` Ingo Molnar
2008-11-27 13:18 ` Frédéric Weisbecker
2008-11-27 14:07 ` Steven Rostedt
2008-11-27 14:13 ` Ingo Molnar
2008-11-27 13:11 ` Frédéric Weisbecker
2008-11-27 14:03 ` Steven Rostedt
2008-11-27 13:06 ` Frédéric Weisbecker
2008-11-27 13:51 ` Ingo Molnar
2008-11-27 14:44 ` Frédéric Weisbecker
2008-11-27 14:46 ` Ingo Molnar
2008-11-27 14:58 ` Frédéric Weisbecker
2008-11-27 15:03 ` Ingo Molnar
2008-11-27 15:09 ` Frédéric Weisbecker
2008-11-27 15:31 ` Steven Rostedt
2008-11-27 15:51 ` Frédéric Weisbecker
2008-11-28 13:05 ` Ingo Molnar
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.