[sheepdog] [PATCH v2 4/5] collie/trace: add graph stat function

[MORITA Kazutaka]

At Mon, 12 Aug 2013 13:40:28 +0800,
Liu Yuan wrote:
> 
> On Mon, Aug 12, 2013 at 12:41:11PM +0900, MORITA Kazutaka wrote:
> > At Mon, 12 Aug 2013 11:17:04 +0800,
> > Liu Yuan wrote:
> > > 
> > > On Mon, Aug 12, 2013 at 05:04:12AM +0900, MORITA Kazutaka wrote:
> > > > > +
> > > > > +static void stat_list_print(void)
> > > > > +{
> > > > > +	struct graph_stat_entry *entry;
> > > > > +
> > > > > +	list_for_each_entry(entry, &stat_list, list) {
> > > > > +		float f = (float)entry->duration / 1000000000;
> > > > > +		float pf = (float)entry->duration / entry->nr_calls / 1000;
> > > > > +
> > > > > +		printf("%-*s| %-10"PRIu32" | %-16f| %-16f\n", TRACE_FNAME_LEN,
> > > > > +		       entry->fname, entry->nr_calls, f, pf);
> > > > 
> > > > I prefer a right-aligned number.  In addition, the default number of
> > > > digits after the decimal point looks long to me.  Then the format
> > > > string is like "%-*s| %10"PRIu32" |%16.3f |%16.3f \n".
> > > > 
> > > > I wonder if we can use the same format as the existing tool's one?
> > > > E.g. gprof output is
> > > > 
> > > > http://sourceware.org/binutils/docs/gprof/Flat-Profile.html#Flat-Profile
> > > > 
> > > > I think it'd be great if we can have the "self seconds" column to
> > > > investigate a bottleneck.
> > > 
> > > 'Total Time' is 'self seconds'. The gprof format looks obscure and redundant.
> > > I think total time, time per call, call nr, name is good enough.
> > 
> > I think 'Total TIme' is 'cumulative seconds'.  It includes the time
> > spent by internally called functions, too.
> 
> I tried to get "cululative time", but no success because our trace buffer is not
> always reliable to use self_time = item->return_time - last_item->return_time,
> 
> e.g, 
> ...
> io 18340            |            |eventfd_xwrite() {
> main                |            |worker_routine() {
> main                |            |   gettid() {
> main                |       1.444|   }
> ...
> 
> Because of eventfd_xwrite() trace is interrupted, we'll get a wrong self time
> for eventfd_xwrite() later in the trace.
> 
> Probably we can later modify trace.c or graph.c to get self_time correctly. Now

Yes, I think we need to modify at least sheep/trace/graph.c.

> let's start with total(accumulative) time only and rely on 'graph cat' to get
> more accurate trace time.

Okay.

Thanks,

Kazutaka