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
let's start with total(accumulative) time only and rely on 'graph cat' to get
more accurate trace time.
Thanks
Yuan
|
|