* [RFC PATCH] ftrace function-graph: print the function name on all } lines
@ 2014-05-02 19:11 Elliott, Robert (Server Storage)
2014-05-02 19:32 ` Steven Rostedt
0 siblings, 1 reply; 4+ messages in thread
From: Elliott, Robert (Server Storage) @ 2014-05-02 19:11 UTC (permalink / raw)
To: rostedt, fweisbec, mingo; +Cc: linux-kernel (linux-kernel@vger.kernel.org)
Using ftrace function-graph to examine the times consumed by
functions, the time shows up on the line where the call is made
if no other traceable functions were called by that function:
11) 0.672 us | cmd_alloc [hpsa]();
but the time shows up down by the } if the were other traceable
functions called by that function:
11) | cmd_alloc [hpsa]() {
11) 0.129 us | cmd_free [hpsa]();
11) 0.106 us | cmd_free [hpsa]();
11) 2.014 us | }
On its own, the } line doesn't indicate which function it is
closing, so grep cannot be used to search for all the times
for this function. You have to write a parser.
The function name does get printed on those lines when the
start of the function is off the trace, so I modified
trace_functions_graph.c to do that in all cases.
11) | hpsa_scsi_ioaccel_raid_map [hpsa]() {
11) | hpsa_scsi_ioaccel_queue_command [hpsa]() {
11) | hpsa_scsi_ioaccel2_queue_command [hpsa]() {
11) 0.067 us | fixup_ioaccel_cdb [hpsa]();
11) 0.053 us | set_encrypt_ioaccel2 [hpsa]();
11) 0.199 us | enqueue_cmd_and_start_io [hpsa]();
11) 1.952 us | } /* hpsa_scsi_ioaccel2_queue_command [hpsa] */
11) 2.501 us | } /* hpsa_scsi_ioaccel_queue_command [hpsa] */
11) 3.093 us | } /* hpsa_scsi_ioaccel_raid_map [hpsa] */
11) 4.667 us | } /* hpsa_scsi_queue_command [hpsa] */
rather than:
11) | hpsa_scsi_ioaccel_raid_map [hpsa]() {
11) | hpsa_scsi_ioaccel_queue_command [hpsa]() {
11) | hpsa_scsi_ioaccel2_queue_command [hpsa]() {
11) 0.067 us | fixup_ioaccel_cdb [hpsa]();
11) 0.053 us | set_encrypt_ioaccel2 [hpsa]();
11) 0.199 us | enqueue_cmd_and_start_io [hpsa]();
11) 1.952 us | }
11) 2.501 us | }
11) 3.093 us | }
11) 4.667 us | }
Is this a change you would be interested in taking, or
do you think that makes the output too cluttered?
A potential patch (based on kernel-3.14) is:
From: Robert Elliott <elliott@hp.com>
In the function-graph tracer, print the function name on
all } lines, not just functions whose first line is no
longer in the trace buffer.
If a function calls other traced functions, its total
time appears on its } line. This change allows grep
to be used to determine the function for which the
line corresponds.
Signed-off-by: Robert Elliott <elliott@hp.com>
---
kernel/trace/trace_functions_graph.c | 24 ++++++------------------
1 files changed, 6 insertions(+), 18 deletions(-)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 0b99120..d530a61 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -1130,7 +1130,6 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
struct fgraph_data *data = iter->private;
pid_t pid = ent->pid;
int cpu = iter->cpu;
- int func_match = 1;
int ret;
int i;
@@ -1150,11 +1149,8 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
*/
cpu_data->depth = trace->depth - 1;
- if (trace->depth < FTRACE_RETFUNC_DEPTH) {
- if (cpu_data->enter_funcs[trace->depth] != trace->func)
- func_match = 0;
+ if (trace->depth < FTRACE_RETFUNC_DEPTH)
cpu_data->enter_funcs[trace->depth] = 0;
- }
}
if (print_graph_prologue(iter, s, 0, 0, flags))
@@ -1173,20 +1169,12 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
}
/*
- * If the return function does not have a matching entry,
- * then the entry was lost. Instead of just printing
- * the '}' and letting the user guess what function this
- * belongs to, write out the function name.
+ * Write out the function name if the return
+ * function has or does not have a matching entry.
*/
- if (func_match) {
- ret = trace_seq_puts(s, "}\n");
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
- } else {
- ret = trace_seq_printf(s, "} /* %ps */\n", (void *)trace->func);
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
- }
+ ret = trace_seq_printf(s, "} /* %ps */\n", (void *)trace->func);
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
/* Overrun */
if (flags & TRACE_GRAPH_PRINT_OVERRUN) {
---
Rob Elliott HP Server Storage
^ permalink raw reply related [flat|nested] 4+ messages in thread
* Re: [RFC PATCH] ftrace function-graph: print the function name on all } lines
2014-05-02 19:11 [RFC PATCH] ftrace function-graph: print the function name on all } lines Elliott, Robert (Server Storage)
@ 2014-05-02 19:32 ` Steven Rostedt
2014-05-05 19:21 ` Elliott, Robert (Server Storage)
0 siblings, 1 reply; 4+ messages in thread
From: Steven Rostedt @ 2014-05-02 19:32 UTC (permalink / raw)
To: Elliott, Robert (Server Storage)
Cc: fweisbec, mingo, linux-kernel (linux-kernel@vger.kernel.org)
On Fri, 2 May 2014 19:11:11 +0000
"Elliott, Robert (Server Storage)" <Elliott@hp.com> wrote:
> Using ftrace function-graph to examine the times consumed by
> functions, the time shows up on the line where the call is made
> if no other traceable functions were called by that function:
> 11) 0.672 us | cmd_alloc [hpsa]();
>
> but the time shows up down by the } if the were other traceable
> functions called by that function:
> 11) | cmd_alloc [hpsa]() {
> 11) 0.129 us | cmd_free [hpsa]();
> 11) 0.106 us | cmd_free [hpsa]();
> 11) 2.014 us | }
>
> On its own, the } line doesn't indicate which function it is
> closing, so grep cannot be used to search for all the times
> for this function. You have to write a parser.
>
> The function name does get printed on those lines when the
> start of the function is off the trace, so I modified
> trace_functions_graph.c to do that in all cases.
>
> 11) | hpsa_scsi_ioaccel_raid_map [hpsa]() {
> 11) | hpsa_scsi_ioaccel_queue_command [hpsa]() {
> 11) | hpsa_scsi_ioaccel2_queue_command [hpsa]() {
> 11) 0.067 us | fixup_ioaccel_cdb [hpsa]();
> 11) 0.053 us | set_encrypt_ioaccel2 [hpsa]();
> 11) 0.199 us | enqueue_cmd_and_start_io [hpsa]();
> 11) 1.952 us | } /* hpsa_scsi_ioaccel2_queue_command [hpsa] */
> 11) 2.501 us | } /* hpsa_scsi_ioaccel_queue_command [hpsa] */
> 11) 3.093 us | } /* hpsa_scsi_ioaccel_raid_map [hpsa] */
> 11) 4.667 us | } /* hpsa_scsi_queue_command [hpsa] */
>
> rather than:
> 11) | hpsa_scsi_ioaccel_raid_map [hpsa]() {
> 11) | hpsa_scsi_ioaccel_queue_command [hpsa]() {
> 11) | hpsa_scsi_ioaccel2_queue_command [hpsa]() {
> 11) 0.067 us | fixup_ioaccel_cdb [hpsa]();
> 11) 0.053 us | set_encrypt_ioaccel2 [hpsa]();
> 11) 0.199 us | enqueue_cmd_and_start_io [hpsa]();
> 11) 1.952 us | }
> 11) 2.501 us | }
> 11) 3.093 us | }
> 11) 4.667 us | }
>
> Is this a change you would be interested in taking, or
> do you think that makes the output too cluttered?
Yes it is too cluttered. Please make this a tracing option that is
default off.
Thanks,
-- Steve
>
> A potential patch (based on kernel-3.14) is:
>
^ permalink raw reply [flat|nested] 4+ messages in thread
* RE: [RFC PATCH] ftrace function-graph: print the function name on all } lines
2014-05-02 19:32 ` Steven Rostedt
@ 2014-05-05 19:21 ` Elliott, Robert (Server Storage)
2014-05-05 19:38 ` Steven Rostedt
0 siblings, 1 reply; 4+ messages in thread
From: Elliott, Robert (Server Storage) @ 2014-05-05 19:21 UTC (permalink / raw)
To: Steven Rostedt
Cc: fweisbec, mingo, linux-kernel (linux-kernel@vger.kernel.org)
> From: Steven Rostedt [mailto:rostedt@goodmis.org]
> ...
> Yes it is too cluttered. Please make this a tracing option that is
> default off.
The TRACE_GRAPH_PRINT_xx macros exist in two places:
* trace.h has one set
* trace_functions_graph.c has redefinitions of them and adds
TRACE_GRAPH_PRINT_IRQS.
The new macro will only be used inside trace_functions_graph.c.
That is true of some of the others like TRACE_GRAPH_PRINT_OVERRUN,
so doesn't seem to be the guiding principle for separate sets.
Should the new one be added to both places, or should the
duplicate definitions in trace_functions_graph.c be removed?
trace_functions_graph.c:
#include "trace.h"
...
/* Flag options */
#define TRACE_GRAPH_PRINT_OVERRUN 0x1
#define TRACE_GRAPH_PRINT_CPU 0x2
#define TRACE_GRAPH_PRINT_OVERHEAD 0x4
#define TRACE_GRAPH_PRINT_PROC 0x8
#define TRACE_GRAPH_PRINT_DURATION 0x10
#define TRACE_GRAPH_PRINT_ABS_TIME 0x20
#define TRACE_GRAPH_PRINT_IRQS 0x40
#define TRACE_GRAPH_PRINT_TAIL 0x80 /* <-- new */
trace.h:
/* Flag options */
#define TRACE_GRAPH_PRINT_OVERRUN 0x1
#define TRACE_GRAPH_PRINT_CPU 0x2
#define TRACE_GRAPH_PRINT_OVERHEAD 0x4
#define TRACE_GRAPH_PRINT_PROC 0x8
#define TRACE_GRAPH_PRINT_DURATION 0x10
#define TRACE_GRAPH_PRINT_ABS_TIME 0x20
#define TRACE_GRAPH_PRINT_FILL_SHIFT 28
#define TRACE_GRAPH_PRINT_FILL_MASK (0x3 << TRACE_GRAPH_PRINT_FILL_SHIFT)
---
Rob Elliott HP Server Storage
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [RFC PATCH] ftrace function-graph: print the function name on all } lines
2014-05-05 19:21 ` Elliott, Robert (Server Storage)
@ 2014-05-05 19:38 ` Steven Rostedt
0 siblings, 0 replies; 4+ messages in thread
From: Steven Rostedt @ 2014-05-05 19:38 UTC (permalink / raw)
To: Elliott, Robert (Server Storage)
Cc: fweisbec, mingo, linux-kernel (linux-kernel@vger.kernel.org)
On Mon, 5 May 2014 19:21:03 +0000
"Elliott, Robert (Server Storage)" <Elliott@hp.com> wrote:
> > From: Steven Rostedt [mailto:rostedt@goodmis.org]
> > ...
> > Yes it is too cluttered. Please make this a tracing option that is
> > default off.
>
> The TRACE_GRAPH_PRINT_xx macros exist in two places:
> * trace.h has one set
> * trace_functions_graph.c has redefinitions of them and adds
> TRACE_GRAPH_PRINT_IRQS.
>
> The new macro will only be used inside trace_functions_graph.c.
> That is true of some of the others like TRACE_GRAPH_PRINT_OVERRUN,
> so doesn't seem to be the guiding principle for separate sets.
>
> Should the new one be added to both places, or should the
> duplicate definitions in trace_functions_graph.c be removed?
>
> trace_functions_graph.c:
> #include "trace.h"
> ...
> /* Flag options */
> #define TRACE_GRAPH_PRINT_OVERRUN 0x1
> #define TRACE_GRAPH_PRINT_CPU 0x2
> #define TRACE_GRAPH_PRINT_OVERHEAD 0x4
> #define TRACE_GRAPH_PRINT_PROC 0x8
> #define TRACE_GRAPH_PRINT_DURATION 0x10
> #define TRACE_GRAPH_PRINT_ABS_TIME 0x20
> #define TRACE_GRAPH_PRINT_IRQS 0x40
> #define TRACE_GRAPH_PRINT_TAIL 0x80 /* <-- new */
>
> trace.h:
> /* Flag options */
> #define TRACE_GRAPH_PRINT_OVERRUN 0x1
> #define TRACE_GRAPH_PRINT_CPU 0x2
> #define TRACE_GRAPH_PRINT_OVERHEAD 0x4
> #define TRACE_GRAPH_PRINT_PROC 0x8
> #define TRACE_GRAPH_PRINT_DURATION 0x10
> #define TRACE_GRAPH_PRINT_ABS_TIME 0x20
> #define TRACE_GRAPH_PRINT_FILL_SHIFT 28
> #define TRACE_GRAPH_PRINT_FILL_MASK (0x3 << TRACE_GRAPH_PRINT_FILL_SHIFT)
This is a bit sloppy. Looks like some of them were copied over to
trace.h to be used in other files, but never deleted from their
original location :-/
Probably should just move them all to trace.h. I want to change this
code in the near future anyway.
-- Steve
>
> ---
> Rob Elliott HP Server Storage
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2014-05-05 19:38 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2014-05-02 19:11 [RFC PATCH] ftrace function-graph: print the function name on all } lines Elliott, Robert (Server Storage)
2014-05-02 19:32 ` Steven Rostedt
2014-05-05 19:21 ` Elliott, Robert (Server Storage)
2014-05-05 19:38 ` Steven Rostedt
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).