Re: [PATCH] ftrace: Access ret_stack->subtime only in the function profiler

[Namhyung Kim <namhyung@kernel.org>]

On Tue, Aug 30, 2016 at 10:34:41AM +0900, Namhyung Kim wrote:
> Hi Steve,
> 
> On Mon, Aug 29, 2016 at 04:07:00PM -0400, Steven Rostedt wrote:
> > On Mon, 29 Aug 2016 12:05:18 +0900
> > Namhyung Kim <namhyung@kernel.org> wrote:
> > 
> > > The subtime is used only for function profiler with function graph
> > > tracer enabled.  Move the definition of subtime under
> > > CONFIG_FUNCTION_PROFILER to reduce the memory usage.  Also move the
> > > initialization of subtime into the graph entry callback.
> > 
> > Hmm, I think documentation needs to be updated. Although it was never
> > implemented, I believe I added the subtime to not only work with the
> > profiler, but also with the normal tracing (to have the time of the
> > internal functions subtracted from the upper level functions). But it
> > appears that part was never implemented.
> > 
> > I'm fine with the patch, or actually implementing what graph-time
> > states in Documentation/ftrace.txt. If we take this patch, that comment
> > needs to be made to only mention the profiler (and the option should
> > only be shown when the profiler is enabled).
> 
> Ah, missed the documentation part.  To implement it in the normal
> tracing, I think we need to add 'subtime' field to struct
> ftrace_graph_ret which will increase disk size.  Are you ok with this?

On second thought, I think I can do it by just adding value of subtime
to ftrace_graph_ret.calltime when graph-time is off.  Then the
calltime would not be the timestamp at function entry, but it seems
not guaranteed due to the sleep-time anyway.  Now I wonder why it
doesn't have 'duration' in the ftrace_graph_ret instead of having
calltime and rettime.

Thanks,
Namhyung


> 
> > 
> > > 
> > > Cc: Josh Poimboeuf <jpoimboe@redhat.com>
> > > Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> > > ---
> > >  include/linux/ftrace.h               | 2 ++
> > >  kernel/trace/ftrace.c                | 6 ++++++
> > >  kernel/trace/trace_functions_graph.c | 1 -
> > >  3 files changed, 8 insertions(+), 1 deletion(-)
> > > 
> > > diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
> > > index 6f93ac46e7f0..b3d34d3e0e7e 100644
> > > --- a/include/linux/ftrace.h
> > > +++ b/include/linux/ftrace.h
> > > @@ -794,7 +794,9 @@ struct ftrace_ret_stack {
> > >  	unsigned long ret;
> > >  	unsigned long func;
> > >  	unsigned long long calltime;
> > > +#ifdef CONFIG_FUNCTION_PROFILER
> > >  	unsigned long long subtime;
> > > +#endif
> > >  #ifdef HAVE_FUNCTION_GRAPH_FP_TEST
> > >  	unsigned long fp;
> > >  #endif
> > > diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
> > > index 84752c8e28b5..2050a7652a86 100644
> > > --- a/kernel/trace/ftrace.c
> > > +++ b/kernel/trace/ftrace.c
> > > @@ -872,7 +872,13 @@ function_profile_call(unsigned long ip, unsigned long parent_ip,
> > >  #ifdef CONFIG_FUNCTION_GRAPH_TRACER
> > >  static int profile_graph_entry(struct ftrace_graph_ent *trace)
> > >  {
> > > +	int index = trace->depth;
> > > +
> > >  	function_profile_call(trace->func, 0, NULL, NULL);
> > > +
> > > +	if (index >= 0 && index < FTRACE_RETFUNC_DEPTH)
> > > +		current->ret_stack[index].subtime = 0;
> > > +
> > >  	return 1;
> > >  }
> > >  
> > > diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
> > > index 0cbe38a844fa..9c7ffa4df5a8 100644
> > > --- a/kernel/trace/trace_functions_graph.c
> > > +++ b/kernel/trace/trace_functions_graph.c
> > > @@ -170,7 +170,6 @@ ftrace_push_return_trace(unsigned long ret, unsigned long func, int *depth,
> > >  	current->ret_stack[index].ret = ret;
> > >  	current->ret_stack[index].func = func;
> > >  	current->ret_stack[index].calltime = calltime;
> > > -	current->ret_stack[index].subtime = 0;
> > >  #ifdef HAVE_FUNCTION_GRAPH_FP_TEST
> > >  	current->ret_stack[index].fp = frame_pointer;
> > >  #endif
> >