Re: [PATCH 1/2] tracing/function-graph-tracer: various fixes and features

[Frederic Weisbecker <fweisbec@gmail.com>]

On Wed, Jan 21, 2009 at 08:43:24PM -0500, Steven Rostedt wrote:
> 
> On Wed, 21 Jan 2009, Frederic Weisbecker wrote:
> 
> > I thought I would have the time to implement the callbacks in trace_event too but I
> > really have to sleep :-(
> > That will be for later.
> 
> No need to rush. Get to sleep.
> 
> > --
> > 
> > This patch brings various bugfixes:
> > 
> > _ Drop the first irrelevant task switch on the very beginning of a trace.
> >   But actually that only solves the first time one does print the trace file.
> >   I have to fix the others cases too.
> 
> I'm not sure what you mean by the first time here. Can you explain it
> a bit better.


On the very first time one cat the trace file, the per cpu pid array is init to -1.
So the comparison between the current pid and the previous one (-1) is always false
and then a task switch is printed.
This one is fixed.

The other cases are when one cat the trace file after closing it.
The pid array is not anymore filled with -1 values but with old traced pid, and then
a task switch is printed here too.
I will have to hook on open and reset the pid table to -1 to fix that.

 
> > _ Drop the OVERHEAD word from the headers, the DURATION word is sufficient and will not
> >   overlap other columns.
> > _ Make the headers fit well their respective columns whatever the selected options.
> > 
> > Ie, default options:
> > 
> > # tracer: function_graph
> > #
> > # CPU  DURATION                  FUNCTION CALLS
> > # |     |   |                     |   |   |   |
> > 
> >  1)   0.646 us    |                    }
> >  1)               |                    mem_cgroup_del_lru_list() {
> >  1)   0.624 us    |                      lookup_page_cgroup();
> >  1)   1.970 us    |                    }
> > 
> > echo funcgraph-proc > trace_options
> > 
> > # tracer: function_graph
> > #
> > # CPU  TASK/PID        DURATION                  FUNCTION CALLS
> > # |    |    |           |   |                     |   |   |   |
> > 
> >  0)   bash-2937    |   0.895 us    |                }
> >  0)   bash-2937    |   0.888 us    |                __rcu_read_unlock();
> >  0)   bash-2937    |   0.864 us    |                conv_uni_to_pc();
> >  0)   bash-2937    |   1.015 us    |                __rcu_read_lock();
> > 
> > echo nofuncgraph-cpu > trace_options
> > echo nofuncgraph-proc > trace_options
> > 
> > # tracer: function_graph
> > #
> > #   DURATION                  FUNCTION CALLS
> > #    |   |                     |   |   |   |
> > 
> >   3.752 us    |                  native_pud_val();
> >   0.616 us    |                  native_pud_val();
> >   0.624 us    |                  native_pmd_val();
> > 
> > 
> > About features, one can now disable the duration (this will hide the overhead too
> > for convenient reasons and because on  doesn't need overhead if it hasn't the duration
> > 
> > echo nofuncgraph-duration > trace_options
> > 
> > # tracer: function_graph
> > #
> > #                FUNCTION CALLS
> > #                |   |   |   |
> > 
> >           cap_vm_enough_memory() {
> >             __vm_enough_memory() {
> >               vm_acct_memory();
> >             }
> >           }
> >         }
> > 
> > And at last, an option to print the absolute time:
> > 
> > //Restart from default options
> > echo funcgraph-abstime > trace_options
> > 
> > # tracer: function_graph
> > #
> > #      TIME       CPU  DURATION                  FUNCTION CALLS
> > #       |         |     |   |                     |   |   |   |
> > 
> >   261.339774 |   1) + 42.823 us   |    }
> >   261.339775 |   1)   1.045 us    |    _spin_lock_irq();
> >   261.339777 |   1)   0.940 us    |    _spin_lock_irqsave();
> >   261.339778 |   1)   0.752 us    |    _spin_unlock_irqrestore();
> >   261.339780 |   1)   0.857 us    |    _spin_unlock_irq();
> >   261.339782 |   1)               |    flush_to_ldisc() {
> >   261.339783 |   1)               |      tty_ldisc_ref() {
> >   261.339783 |   1)               |        tty_ldisc_try() {
> >   261.339784 |   1)   1.075 us    |          _spin_lock_irqsave();
> >   261.339786 |   1)   0.842 us    |          _spin_unlock_irqrestore();
> >   261.339788 |   1)   4.211 us    |        }
> >   261.339788 |   1)   5.662 us    |      }
> > 
> > The format is seconds.usecs
> > I guess no one needs the nanosec precision here, the main goal is to find when happened
> > the events on a cpu when the trace switches from one cpu to another.
> > 
> > ie:
> > 
> >   274.874760 |   1)   0.676 us    |      _spin_unlock();
> >   274.874762 |   1)   0.609 us    |      native_load_sp0();
> >   274.874763 |   1)   0.602 us    |      native_load_tls();
> >   274.878739 |   0)   0.722 us    |                  }
> >   274.878740 |   0)   0.714 us    |                  native_pmd_val();
> >   274.878741 |   0)   0.730 us    |                  native_pmd_val();
> > 
> > Here there is a 4000 usecs difference when we switch the cpu.
> 
> These examples will most likely be cut from the change log. Updating
> ftrace.txt would be nice ;-)


Yes, definetly. I didn't drop my hands into this yet because of my
messy english :-)
But I know some people who could review it :-)


> > 
> > Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> > ---
> >  kernel/trace/trace_functions_graph.c |  245 +++++++++++++++++++++-------------
> >  1 files changed, 151 insertions(+), 94 deletions(-)
> > 
> 
> -- Steve
> 

Thanks.