Commit graph

370 commits

Author SHA1 Message Date
Arnaldo Carvalho de Melo
ec218fc4a7 perf tools: Remove show_mask bitmask
As it was not being exposed via any command line and with --dsos/--comms
we can do this and even more, like asking for just kernel + some module:

[root@doppio linux-2.6-tip]# perf report --dsos \[kernel\],\[drm\]
--vmlinux /home/acme/git/build/tip-recvmmsg/vmlinux --modules | head -15
 # Samples: 619669
 #
 # Overhead          Command  Shared Object  Symbol
 # ........  ...............  .............  ......
 #
      7.12%          swapper  [kernel]       [k] read_hpet
      6.86%             init  [kernel]       [k] read_hpet
      6.22%             init  [kernel]       [k] mwait_idle_with_hints
      5.34%          swapper  [kernel]       [k] mwait_idle_with_hints
      3.01%          firefox  [kernel]       [.] vread_hpet
      2.14%             Xorg  [drm]          [k] drm_clflush_pages
      2.09%           pidgin  [kernel]       [.] vread_hpet
      1.58%     npviewer.bin  [kernel]       [.] vread_hpet
      1.37%          swapper  [kernel]       [k] hpet_next_event
      1.23%             Xorg  [kernel]       [k] read_hpet
[root@doppio linux-2.6-tip]#

Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frédéric Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Mike Galbraith <efault@gmx.de>
LKML-Reference: <20091003233048.GA30535@ghostprotocols.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-10-04 19:37:11 +02:00
Arnaldo Carvalho de Melo
9735abf11b perf tools: Move hist_entry__add common code to hist.c
Now perf report and annotate do the callgraph/hit processing in
their specialized hist_entry__add functions.

Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Acked-by: Frédéric Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Mike Galbraith <efault@gmx.de>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-10-03 16:01:59 +02:00
Arnaldo Carvalho de Melo
439d473b47 perf tools: Rewrite and improve support for kernel modules
Representing modules as struct map entries, backed by a DSO, etc,
using /proc/modules to find where the module is loaded.

DSOs now can have a short and long name, so that in verbose mode we
can show exactly which .ko or vmlinux image was used.

As kernel modules now are a DSO separate from the kernel, we can
ask for just the hits for a particular set of kernel modules, just
like we can do with shared libraries:

[root@doppio linux-2.6-tip]# perf report -n --vmlinux
/home/acme/git/build/tip-recvmmsg/vmlinux --modules --dsos \[drm\] | head -15
    84.58%      13266             Xorg  [k] drm_clflush_pages
     4.02%        630             Xorg  [k] trace_kmalloc.clone.0
     3.95%        619             Xorg  [k] drm_ioctl
     2.07%        324             Xorg  [k] drm_addbufs
     1.68%        263             Xorg  [k] drm_gem_close_ioctl
     0.77%        120             Xorg  [k] drm_setmaster_ioctl
     0.70%        110             Xorg  [k] drm_lastclose
     0.68%        106             Xorg  [k] drm_open
     0.54%         85             Xorg  [k] drm_mm_search_free
[root@doppio linux-2.6-tip]#

Specifying --dsos /lib/modules/2.6.31-tip/kernel/drivers/gpu/drm/drm.ko
would have the same effect. Allowing specifying just 'drm.ko' is left
for another patch.

Processing kallsyms so that per kernel module struct map are
instantiated was also left for another patch. That will allow
removing the module name from each of its symbols.

struct symbol was reduced by removing the ->module backpointer and
moving it (well now the map) to struct symbol_entry in perf top,
that is its only user right now.

The total linecount went down by ~500 lines.

Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frédéric Weisbecker <fweisbec@gmail.com>
Cc: "H. Peter Anvin" <hpa@zytor.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Avi Kivity <avi@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-10-02 10:48:42 +02:00
Mulyadi Santosa
1ad0560e8c perf tools: Run generate-cmdlist.sh properly
Right now generate-cmdlist.sh is not executable, so we
should call it as an argument ".".

This fixes cases where due to different umask defaults
the generate-cmdlist.sh script is not executable in
a kernel tree checkout.

Signed-off-by: Mulyadi Santosa <mulyadi.santosa@gmail.com>
Acked-by: Sam Ravnborg <sam@ravnborg.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <f284c33d0909251201w422e9687x8cd3a784e85adf7d@mail.gmail.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-10-01 10:12:03 +02:00
Arjan van de Ven
39a90a8ef1 perf timechart: Add a power-only mode
For doing work on the Linux power management components, I need to
make long (30+ seconds) traces. Currently, this then results in a
HUGE svg file, with mostly process data that isn't interesting.

This patch adds a --power-only mode to perf timechart that only
outputs the CPU power section of the SVG; this significantly
reduces the size of the SVG file, making even 30+ second traces
viewable with inkscape.

As a minor tweak for the same effect, the minimum text size is
decreased; current inkscape cannot zoom in deep enough to show text
this small, but it reduces inkscape compute time.

Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
Cc: peterz@infradead.org
LKML-Reference: <20090924154013.0675ab71@infradead.org>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-10-01 09:26:40 +02:00
Arnaldo Carvalho de Melo
2ccdc450e6 perf top: Remove dead {min,max}_ip unused variables
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frédéric Weisbecker <fweisbec@gmail.com>
Cc: "H. Peter Anvin" <hpa@zytor.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Mike Galbraith <efault@gmx.de>
LKML-Reference: <20090924212400.GA15321@ghostprotocols.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-10-01 08:46:15 +02:00
Arnaldo Carvalho de Melo
cad3071424 perf trace: Remove dead code
Several variables are not used at all, cut'n'paste leftovers.

Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frédéric Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Mike Galbraith <efault@gmx.de>
Cc: "H. Peter Anvin" <hpa@zytor.com>
LKML-Reference: <20090928200818.GF3361@ghostprotocols.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-30 13:57:57 +02:00
Arnaldo Carvalho de Melo
a80deb622d perf sched: Remove dead code
Several variables are not used at all, cut'n'paste leftovers.

Also check if the sample_type is RAW earlier, to avoid needless
searches.

Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frédéric Weisbecker <fweisbec@gmail.com>
Cc: "H. Peter Anvin" <hpa@zytor.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Mike Galbraith <efault@gmx.de>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-30 13:57:57 +02:00
Arnaldo Carvalho de Melo
1b46cddfcc perf tools: Use rb_tree for maps
Threads can have many and kernel modules will be represented as a
tree of maps as well.

Ah, and for a perf.data with 146607 samples:

Before:

[root@doppio ~]# perf stat -r 5 perf report > /dev/null

 Performance counter stats for 'perf report' (5 runs):

     699.823680  task-clock-msecs         #      0.991 CPUs    ( +-   0.454% )
             74  context-switches         #      0.000 M/sec   ( +-   1.709% )
              2  CPU-migrations           #      0.000 M/sec   ( +-  17.008% )
          23114  page-faults              #      0.033 M/sec   ( +-   0.000% )
     1381257019  cycles                   #   1973.721 M/sec   ( +-   0.290% )
     1456894438  instructions             #      1.055 IPC     ( +-   0.007% )
       18779818  cache-references         #     26.835 M/sec   ( +-   0.380% )
         641799  cache-misses             #      0.917 M/sec   ( +-   1.200% )

    0.705972729  seconds time elapsed   ( +-   0.501% )

[root@doppio ~]#

After

 Performance counter stats for 'perf report' (5 runs):

     691.261451  task-clock-msecs         #      0.993 CPUs    ( +-   0.307% )
             72  context-switches         #      0.000 M/sec   ( +-   0.829% )
              6  CPU-migrations           #      0.000 M/sec   ( +-  18.409% )
          23127  page-faults              #      0.033 M/sec   ( +-   0.000% )
     1366395876  cycles                   #   1976.670 M/sec   ( +-   0.153% )
     1443136016  instructions             #      1.056 IPC     ( +-   0.012% )
       17956402  cache-references         #     25.976 M/sec   ( +-   0.325% )
         661924  cache-misses             #      0.958 M/sec   ( +-   1.335% )

    0.696127275  seconds time elapsed   ( +-   0.377% )

I.e. we see some speedup too.

Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frédéric Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Mike Galbraith <efault@gmx.de>
Cc: "H. Peter Anvin" <hpa@zytor.com>
LKML-Reference: <20090928174846.GA3361@ghostprotocols.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-30 13:57:56 +02:00
John Kacur
3d1d07ecd2 perf tools: Put common histogram functions in their own file
Move histogram related functions into their own files (hist.c and
hist.h) and make use of them in builtin-annotate.c and
builtin-report.c.

Signed-off-by: John Kacur <jkacur@redhat.com>
Acked-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
LKML-Reference: <alpine.LFD.2.00.0909281531180.8316@localhost.localdomain>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-30 13:57:56 +02:00
Arnaldo Carvalho de Melo
8357275bb9 perf top: Add poll_idle to the skip list
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Acked-by: Eric Dumazet <eric.dumazet@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Mike Galbraith <efault@gmx.de>
LKML-Reference: <20090925220239.GA5488@ghostprotocols.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-30 13:56:54 +02:00
John Kacur
dd68ada2d4 perf tools: Create util/sort.and use it
Create util/sort.[ch] and move common functionality for
builtin-report.c and builtin-annotate.c there, and make use of it.

Signed-off-by: John Kacur <jkacur@redhat.com>
LKML-Reference: <alpine.LFD.2.00.0909241758390.11383@localhost.localdomain>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-24 21:27:52 +02:00
John Kacur
8b40f521cf perf tools: Protect header files with a consistent style
There was a colorful mix of header guards - standardize them.

Signed-off-by: John Kacur <jkacur@redhat.com>
LKML-Reference: <alpine.LFD.2.00.0909241756530.11383@localhost.localdomain>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-24 21:27:51 +02:00
John Kacur
cbfeb267cb perf annotate: Add the cmp_null function and make use of it
This function exists in builtin-report.c but not in
builtin-annotate.c Functions that use cmp_null are shorter and
clearer.

Synchronizing functions between these two files will also make it
easier to potential share code in the future.

Signed-off-by: John Kacur <jkacur@redhat.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
LKML-Reference: <alpine.LFD.2.00.0909241754031.11383@localhost.localdomain>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-24 21:27:50 +02:00
Eric Dumazet
725b13685c perf tools: Dont use openat()
openat() is still a young glibc facility, better to not use it in a
non performance critical program (perf list)

Many machines have older glibc (RHEL 4 Update 5 -> glibc-2.3.4-2.36
on my dev machine for example).

Signed-off-by: Eric Dumazet <eric.dumazet@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Ulrich Drepper <drepper@redhat.com>
LKML-Reference: <4ABB767D.6080004@gmail.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-24 21:20:08 +02:00
Eric Dumazet
a255a9981a perf tools: Fix buffer allocation
"perf top" cores dump on my dev machine, if run from a directory
where vmlinux is present:

  *** glibc detected *** malloc(): memory corruption: 0x085670d0 ***

Signed-off-by: Eric Dumazet <eric.dumazet@gmail.com>
Cc: <stable@kernel.org>
LKML-Reference: <4ABB6EB7.7000002@gmail.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-24 15:11:23 +02:00
Kirill Smelkov
67030036eb perf tools: .gitignore += perf*.html
I've tried building the docs in tools/perf/Documentation/ , and after
that `git status` showed dozen of untracked htmls. Let's ignore them.

Signed-off-by: Kirill Smelkov <kirr@mns.spb.ru>
LKML-Reference: <1253790022-10300-1-git-send-email-kirr@mns.spb.ru>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-24 14:01:22 +02:00
Mike Galbraith
dd906a0fe8 perf tools: Handle relative paths while loading module symbols
Inform util/module.c::mod_dso__load_module_paths() that relative
paths do exist in some modules.dep, and make it fail noisily should
it encounter a path that it doesn't understand, or a module it
cannot open.

Reported-by: Avi Kivity <avi@redhat.com>
Signed-off-by: Mike Galbraith <efault@gmx.de>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: rostedt@goodmis.org
Cc: Mathieu Desnoyers <mathieu.desnoyers@polymtl.ca>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Masami Hiramatsu <mhiramat@redhat.com>
LKML-Reference: <1253779628.10513.8.camel@marge.simson.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-24 11:40:35 +02:00
Mike Galbraith
508c4d0874 perf tools: Fix module symbol loading bug
Avi Kivity reported 'perf annotate' failures with modules, the
requested function was not annotated.

If there are no modules currently loaded, or the last module
scanned is not loaded, dso__load_modules() steps on the value from
dso__load_vmlinux(), so we happily load the kallsyms symbols on top
of what we've already loaded.

Fix that such that the total count of symbols loaded is returned.
Should module symbol load fail after parsing of vmlinux, is's a
hard failure, so do not silently fall-back to kallsyms.

Reported-by: Avi Kivity <avi@redhat.com>
Signed-off-by: Mike Galbraith <efault@gmx.de>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: rostedt@goodmis.org
Cc: Mathieu Desnoyers <mathieu.desnoyers@polymtl.ca>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Masami Hiramatsu <mhiramat@redhat.com>
LKML-Reference: <1253697658.11461.36.camel@marge.simson.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-23 13:45:48 +02:00
Ingo Molnar
c7f7fea30b perf stat: Fix zero total printouts
Before:

           0  sched:sched_switch #        nan M/sec

After:

           0  sched:sched_switch #      0.000 M/sec

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-22 15:01:47 +02:00
Ingo Molnar
cdd6c482c9 perf: Do the big rename: Performance Counters -> Performance Events
Bye-bye Performance Counters, welcome Performance Events!

In the past few months the perfcounters subsystem has grown out its
initial role of counting hardware events, and has become (and is
becoming) a much broader generic event enumeration, reporting, logging,
monitoring, analysis facility.

Naming its core object 'perf_counter' and naming the subsystem
'perfcounters' has become more and more of a misnomer. With pending
code like hw-breakpoints support the 'counter' name is less and
less appropriate.

All in one, we've decided to rename the subsystem to 'performance
events' and to propagate this rename through all fields, variables
and API names. (in an ABI compatible fashion)

The word 'event' is also a bit shorter than 'counter' - which makes
it slightly more convenient to write/handle as well.

Thanks goes to Stephane Eranian who first observed this misnomer and
suggested a rename.

User-space tooling and ABI compatibility is not affected - this patch
should be function-invariant. (Also, defconfigs were not touched to
keep the size down.)

This patch has been generated via the following script:

  FILES=$(find * -type f | grep -vE 'oprofile|[^K]config')

  sed -i \
    -e 's/PERF_EVENT_/PERF_RECORD_/g' \
    -e 's/PERF_COUNTER/PERF_EVENT/g' \
    -e 's/perf_counter/perf_event/g' \
    -e 's/nb_counters/nb_events/g' \
    -e 's/swcounter/swevent/g' \
    -e 's/tpcounter_event/tp_event/g' \
    $FILES

  for N in $(find . -name perf_counter.[ch]); do
    M=$(echo $N | sed 's/perf_counter/perf_event/g')
    mv $N $M
  done

  FILES=$(find . -name perf_event.*)

  sed -i \
    -e 's/COUNTER_MASK/REG_MASK/g' \
    -e 's/COUNTER/EVENT/g' \
    -e 's/\<event\>/event_id/g' \
    -e 's/counter/event/g' \
    -e 's/Counter/Event/g' \
    $FILES

... to keep it as correct as possible. This script can also be
used by anyone who has pending perfcounters patches - it converts
a Linux kernel tree over to the new naming. We tried to time this
change to the point in time where the amount of pending patches
is the smallest: the end of the merge window.

Namespace clashes were fixed up in a preparatory patch - and some
stylistic fallout will be fixed up in a subsequent patch.

( NOTE: 'counters' are still the proper terminology when we deal
  with hardware registers - and these sed scripts are a bit
  over-eager in renaming them. I've undone some of that, but
  in case there's something left where 'counter' would be
  better than 'event' we can undo that on an individual basis
  instead of touching an otherwise nicely automated patch. )

Suggested-by: Stephane Eranian <eranian@google.com>
Acked-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
Acked-by: Paul Mackerras <paulus@samba.org>
Reviewed-by: Arjan van de Ven <arjan@linux.intel.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Benjamin Herrenschmidt <benh@kernel.crashing.org>
Cc: David Howells <dhowells@redhat.com>
Cc: Kyle McMartin <kyle@mcmartin.ca>
Cc: Martin Schwidefsky <schwidefsky@de.ibm.com>
Cc: "David S. Miller" <davem@davemloft.net>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: "H. Peter Anvin" <hpa@zytor.com>
Cc: <linux-arch@vger.kernel.org>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-21 14:28:04 +02:00
Arjan van de Ven
611a546bec perf util: SVG performance improvements
Tweak the output SVG to increase performance in SVG viewers by
limiting the different types of font sizes and by smarter
transformations on the text.

At least with Inkscape this gives a notable performance improvement
during zoom and scrolling.

Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <20090920181438.3a49cb93@linux.intel.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-20 19:37:36 +02:00
Arjan van de Ven
5094b65545 perf util: Make the timechart SVG width dynamic
This patch adds a command line option for timechart that allows the
user to specify the width of the SVG file.

This patch also makes sure that each second of recording has at
least 200 units (pixels at 96 DPI) of width.  This impacts
recordings longer than 5 seconds; recordings shorter than 5 second
will scale up to have a width of 1000 units for the whole recording
(as before).

Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <20090920181416.69570c5d@linux.intel.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-20 19:37:35 +02:00
Arjan van de Ven
a92fe7b306 perf timechart: Show the duration of scheduler delays in the SVG
Given that scheduler latencies are the hot thing nowadays, show the
duration of said latencies in the SVG in text form.

In addition, if the latency is more than 10 msec, pick a brighter
yellow color as a way to point these long delays out.

Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <20090920181353.796f4509@linux.intel.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-20 19:37:35 +02:00
Arjan van de Ven
4f1202c8e6 perf timechart: Show the name of the waker/wakee in timechart
Timechart currently shows thin green lines for sending or receiving
wakeups. This patch also prints (in a very small font) the name of
the process that is being woken/wakes up this process.

Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <20090920181328.68baa978@linux.intel.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-20 19:37:34 +02:00
Arjan van de Ven
ec60a3fe47 perf utils: Use a define for the maximum length of a trace event
As per Ingo's review: use a #define rather than an open coded constant
for the maximum length of a trace event for storing in the perf.data file.

Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
Cc: fweisbec@gmail.com
Cc: peterz@infradead.org
Cc: Paul Mackerras <paulus@samba.org>
LKML-Reference: <20090919133630.10533d3e@infradead.org>
[ add a few comments to nearby functions ]
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-19 18:57:53 +02:00
Arjan van de Ven
151750cec5 perf: Add timechart help text and add timechart to "perf help"
As suggested by Ingo, add a timechart man page help text, as well
as add it to the "perf help" overview.

Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
Cc: fweisbec@gmail.com
Cc: peterz@infradead.org
Cc: Paul Mackerras <paulus@samba.org>
LKML-Reference: <20090919133604.3767fa35@infradead.org>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-19 18:57:53 +02:00
Arjan van de Ven
964a0b3d2b perf utils: Be consistent about minimum text size in the svghelper
Be more consistent in the svghelper about the minimum text size
by having a global #define for this.

There needs to be a minimum text size in order to keep the size
of the SVG file within the reach of what current SVG viewers can
cope with.

Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
Cc: fweisbec@gmail.com
Cc: peterz@infradead.org
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arjan van de Ven <arjan@infradead.org>
LKML-Reference: <20090919133507.7374ef8b@infradead.org>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-19 18:57:52 +02:00
Arjan van de Ven
3c09eebd61 perf timechart: Add "perf timechart record"
Add a command line option to record a trace, similar to "perf sched record".

Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
Cc: fweisbec@gmail.com
Cc: peterz@infradead.org
Cc: Paul Mackerras <paulus@samba.org>
LKML-Reference: <20090919133442.0dc2c7f5@infradead.org>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-19 18:57:51 +02:00
Arjan van de Ven
10274989fd perf: Add the timechart tool
timechart is a tool to visualize what is going on in the system.

The user makes a trace of what is going on with

 > perf record --timechart /usr/bin/some_command

and then can turn the output of this into an svg file

 > perf timechart

which then can be viewed with any SVG view; inkscape works well
enough for me.

The idea behind timechart is to create a "infinitely zoomable"
picture; something that has high level information on a 1:1 zoom
level, but which exposes more details every time you zoom into a
specific area.

Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
Acked-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <20090912130713.6a77bbc0@infradead.org>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-19 11:42:13 +02:00
Arjan van de Ven
f48d55ce78 perf: Add a SVG helper library file
The timechart tool writes out SVG format output; this patch adds a
set of helper functions to abstract dealing with SVG from the core
timechart code.

Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
Acked-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <20090912130613.677f0516@infradead.org>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-19 11:42:13 +02:00
Arjan van de Ven
fd39e055c4 perf: Add a sample_event type to the event_union
Add a sample_event type to the event_union so that raw samples can
be processed easily.

Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
Acked-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <20090912130511.411434b5@infradead.org>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-19 11:42:12 +02:00
Arjan van de Ven
a79d7db9fd perf: Allow perf utilities to have "callback" options without arguments
timechart needs to add a "callback" type command line argument that
does not take arguments.

This patch adds the parse-options.h infrastructure to make this
possible.

Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
Acked-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <20090912130440.548666c1@infradead.org>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-19 11:42:11 +02:00
Arjan van de Ven
8755a8f27a perf: Store trace event name/id pairs in perf.data
The trace event name<->id mapping is dynamic for each kernel
compile. In order for perf.data to be useable outside the actual
system, we thus need to store a table of this mapping for later
use.

This patch adds this table to perf.data, and provides helper
functions for lookup up fields from this table.

To avoid mistakes, lookup-from-table is kept completely seprate
from lookup-from-local-debugfs.

Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
Acked-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <20090912130405.6960d099@infradead.org>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-19 11:42:11 +02:00
Arjan van de Ven
393b2ad8c7 perf: Add a timestamp to fork events
perf timechart needs to know when a process forked, in order to be
able to visualize properly when tasks start.

This patch adds a time field to the event structure, and fills it
in appropriately.

Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
Acked-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <20090912130341.51ad2de2@infradead.org>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-19 11:42:10 +02:00
Ingo Molnar
929bf0d015 Merge branch 'linus' into perfcounters/core
Merge reason: Bring in tracing changes we depend on.

Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-19 11:28:41 +02:00
Mike Galbraith
4b77a72977 perf sched: Add --input=file option to builtin-sched.c
perf sched record passes unparsed args on to perf record, so
specifying an output file via perf sched record -o FILE (cmd) just
works.  Ergo, provide an option to specify input file as well.

Also add the missing 'map' command to help.

Signed-off-by: Mike Galbraith <efault@gmx.de>
Acked-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
LKML-Reference: <1253254944.20589.11.camel@marge.simson.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-18 08:36:06 +02:00
Li Zefan
1281a49b7a perf trace: Sample timestamp and cpu when using record flag
Sample timestamp and cpu just like the -R option.

Before:
            init-0     [-01] 1266874889.17179869184709551615: irq_handler_entry: irq=18 handler=eth0
            init-0     [-01] 1266874889.17179869184709551615: irq_handler_entry: irq=18 handler=eth0
            init-0     [-01] 1266874889.17179869184709551615: irq_handler_entry: irq=1 handler=i8042
            init-0     [-01] 1266874889.17179869184709551615: irq_handler_entry: irq=18 handler=eth0
            init-0     [-01] 1266874889.17179869184709551615: irq_handler_entry: irq=1 handler=i8042

After:
            init-0     [001]  7364.568965353: irq_handler_entry: irq=18 handler=eth0
            init-0     [001]  7365.530226877: irq_handler_entry: irq=1 handler=i8042
            init-0     [001]  7365.542831563: irq_handler_entry: irq=18 handler=eth0
            init-0     [001]  7365.644156299: irq_handler_entry: irq=18 handler=eth0
            init-0     [001]  7365.694556201: irq_handler_entry: irq=18 handler=eth0

Signed-off-by: Li Zefan <lizf@cn.fujitsu.com>
Acked-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
LKML-Reference: <4AB1F827.8040905@cn.fujitsu.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-18 00:30:25 +02:00
Li Zefan
270bbbe80d perf tools: Increase MAX_EVENT_LENGTH
The name length of some trace events is longer than 30, like
sys_enter_sched_get_priority_max and
ext4_mb_discard_preallocations.

Passing those events to perf-record will fail, try:

  # ./perf record -f -e syscalls:sys_enter_sched_get_priority_max -F 1 -a

Signed-off-by: Li Zefan <lizf@cn.fujitsu.com>
Acked-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
LKML-Reference: <4AB1F4AB.7050205@cn.fujitsu.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-18 00:30:25 +02:00
Li Zefan
6706ccf8e7 perf tools: Fix memory leak in read_ftrace_printk()
get_tracing_file() should be paired with put_tracing_file().

Signed-off-by: Li Zefan <lizf@cn.fujitsu.com>
Acked-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
LKML-Reference: <4AB1F48F.4070807@cn.fujitsu.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-18 00:30:24 +02:00
Ingo Molnar
40749d0ff4 perf sched: Determine the number of CPUs automatically
For 'perf sched map' output, determine max_cpu automatically,
instead of the static default of 15.

[ v2: use sysconf() pointed out by Arjan van de Ven <arjan@infradead.org> ]

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-17 22:09:19 +02:00
Peter Zijlstra
8b412664d0 perf record: Disable profiling before draining the buffer
I noticed that perf-record continues profiling itself after the
child terminated and we're draining the buffer.

This can cause a _lot_ of overhead with --all recording - we keep
and keep recording, which produces new and new events.

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-17 22:08:27 +02:00
Ingo Molnar
0ec04e16d0 perf sched: Add 'perf sched map' scheduling event map printout
This prints a textual context-switching outline of workload
captured via perf sched record.

For example, on a 16 CPU box it outputs:

   N1  O1  .   .   .   S1  .   .   .   B0  .  *I0  C1  .   M1  .    23002.773423 secs
   N1  O1  .  *Q0  .   S1  .   .   .   B0  .   I0  C1  .   M1  .    23002.773423 secs
   N1  O1  .   Q0  .   S1  .   .   .   B0  .  *R1  C1  .   M1  .    23002.773485 secs
   N1  O1  .   Q0  .   S1  .  *S0  .   B0  .   R1  C1  .   M1  .    23002.773478 secs
  *L0  O1  .   Q0  .   S1  .   S0  .   B0  .   R1  C1  .   M1  .    23002.773523 secs
   L0  O1  .  *.   .   S1  .   S0  .   B0  .   R1  C1  .   M1  .    23002.773531 secs
   L0  O1  .   .   .   S1  .   S0  .   B0  .   R1  C1 *T1  M1  .    23002.773547 secs T1 => irqbalance:2089
   L0  O1  .   .   .   S1  .   S0  .  *P0  .   R1  C1  T1  M1  .    23002.773549 secs
  *N1  O1  .   .   .   S1  .   S0  .   P0  .   R1  C1  T1  M1  .    23002.773566 secs
   N1  O1  .   .   .  *J0  .   S0  .   P0  .   R1  C1  T1  M1  .    23002.773571 secs
   N1  O1  .   .   .   J0  .   S0 *B0  P0  .   R1  C1  T1  M1  .    23002.773592 secs
   N1  O1  .   .   .   J0  .  *U0  B0  P0  .   R1  C1  T1  M1  .    23002.773582 secs
   N1  O1  .   .   .  *S1  .   U0  B0  P0  .   R1  C1  T1  M1  .    23002.773604 secs
   N1  O1  .   .   .   S1  .   U0  B0 *.   .   R1  C1  T1  M1  .    23002.773615 secs
   N1  O1  .   .   .   S1  .   U0  B0  .   .  *K0  C1  T1  M1  .    23002.773631 secs
   N1  O1  .  *M0  .   S1  .   U0  B0  .   .   K0  C1  T1  M1  .    23002.773624 secs
   N1  O1  .   M0  .   S1  .   U0 *.   .   .   K0  C1  T1  M1  .    23002.773644 secs
   N1  O1  .   M0  .   S1  .   U0  .   .   .  *R1  C1  T1  M1  .    23002.773662 secs
   N1  O1  .   M0  .   S1  .  *.   .   .   .   R1  C1  T1  M1  .    23002.773648 secs
   N1  O1  .  *.   .   S1  .   .   .   .   .   R1  C1  T1  M1  .    23002.773680 secs
   N1  O1  .   .   .  *L0  .   .   .   .   .   R1  C1  T1  M1  .    23002.773717 secs
  *N0  O1  .   .   .   L0  .   .   .   .   .   R1  C1  T1  M1  .    23002.773709 secs
  *N1  O1  .   .   .   L0  .   .   .   .   .   R1  C1  T1  M1  .    23002.773747 secs

Columns stand for individual CPUs, from CPU0 to CPU15, and the
two-letter shortcuts stand for tasks that are running on a CPU.

'*' denotes the CPU that had the event.

A dot signals an idle CPU.

New tasks are assigned new two-letter shortcuts - when they occur
first they are printed. In the above example 'T1' stood for irqbalance:

      T1 => irqbalance:2089

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-16 16:41:30 +02:00
Ingo Molnar
80ed0987f3 perf sched: Make idle thread and comm/pid names more consistent
Peter noticed that we have 3 ways of referring to the idle thread:

 [idle]:0
 swapper:0
 swapper-0

Standardize on 'swapper:0'.

Reported-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-16 12:15:47 +02:00
Ingo Molnar
c8a3775104 perf sched: Sanity check context switch events
Use 'perf sched latency' to track the current task based on
context-switch events, and flag the cases where there's some
impossible transition: such as a PID being switched out that
was not switched in.

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-16 12:08:28 +02:00
Ingo Molnar
dc02bf7178 perf sched: Account for lost events, increase default buffering
Output such lost event and state machine weirdness stats:

   TOTAL:                |  14974.910 ms |    46384 |
  ---------------------------------------------------
   INFO: 8.865% lost events (19132 out of 215819, in 8 chunks)
   INFO: 0.198% state machine bugs (49 out of 24708) (due to lost events?)

And increase buffering to -m 1024 (4 MB) by default. Since we
use output multiplexing that kind of space is needed.

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-16 11:48:05 +02:00
mingo
39aeb52f99 perf sched: Add support for sched:sched_stat_runtime events
This allows more precise 'perf sched latency' output:

 ---------------------------------------------------------------------------------------
  Task                  |  Runtime ms | Switches | Average delay ms | Maximum delay ms |
 ---------------------------------------------------------------------------------------
  ksoftirqd/0-4         |    0.010 ms |        2 | avg:    2.476 ms | max:    2.977 ms |
  perf-12328            |   15.844 ms |       66 | avg:    1.118 ms | max:    9.979 ms |
  bdi-default-235       |    0.009 ms |        1 | avg:    0.998 ms | max:    0.998 ms |
  events/1-8            |    0.020 ms |        2 | avg:    0.998 ms | max:    0.998 ms |
  events/0-7            |    0.018 ms |        2 | avg:    0.992 ms | max:    0.996 ms |
  sleep-12329           |    0.742 ms |        3 | avg:    0.906 ms | max:    2.289 ms |
  sshd-12122            |    0.163 ms |        2 | avg:    0.283 ms | max:    0.562 ms |
  loop-getpid-lon-12322 | 1023.636 ms |       69 | avg:    0.208 ms | max:    5.996 ms |
  loop-getpid-lon-12321 | 1038.638 ms |        5 | avg:    0.073 ms | max:    0.171 ms |
  migration/1-5         |    0.000 ms |        1 | avg:    0.006 ms | max:    0.006 ms |
 ---------------------------------------------------------------------------------------
  TOTAL:                | 2079.078 ms |      153 |
 -------------------------------------------------

Also, streamline the code a bit more, add asserts for various state
machine failures (they should be debugged if they occur) and fix
a few odd ends.

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-14 20:08:23 +02:00
mingo
08f69e6c2e perf sched: Print PIDs too
Often it's useful to know the PID of the task as well - print it
out too.

( While at it, reformat the output to be a bit more
  paste-into-commit-logs friendly. )

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-14 18:34:57 +02:00
Ingo Molnar
d11533893b perf sched: Fix 'perf sched latency' output on 32-bit systems
Before:

  -----------------------------------------------------------------------------------
   Task              |  Runtime ms | Switches | Average delay ms | Maximum delay ms |
  -----------------------------------------------------------------------------------
   perf              |4853313.251 ms |       10 | avg:    0.046 ms | max:    0.337 ms |
   flush-8:0         |2426659.202 ms |        5 | avg:    0.015 ms | max:    0.016 ms |
   sleep             |485331.966 ms |        1 | avg:    0.012 ms | max:    0.012 ms |
   ksoftirqd/1       |485331.320 ms |        1 | avg:    0.005 ms | max:    0.005 ms |
  -----------------------------------------------------------------------------------
   TOTAL:            |8250635.739 ms |       17 |
  ---------------------------------------------

After:

  -----------------------------------------------------------------------------------
   Task              |  Runtime ms | Switches | Average delay ms | Maximum delay ms |
  -----------------------------------------------------------------------------------
   perf              |    0.206 ms |       10 | avg:    0.046 ms | max:    0.337 ms |
   flush-8:0         |    2.680 ms |        5 | avg:    0.015 ms | max:    0.016 ms |
   sleep             |    0.662 ms |        1 | avg:    0.012 ms | max:    0.012 ms |
   ksoftirqd/1       |    0.015 ms |        1 | avg:    0.005 ms | max:    0.005 ms |
  -----------------------------------------------------------------------------------
   TOTAL:            |    3.563 ms |       17 |
  ---------------------------------------------

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-14 18:22:53 +02:00
Ingo Molnar
ea57c4f520 perf tools: Implement counter output multiplexing
Finish the -M/--multiplex option implementation:

 - separate it out from group_fd

 - correctly set it via the ioctl and dont mmap counters that
   are multiplexed

 - modify the perf record event loop to deal with buffer-less
   counters.

 - remove the -g option from perf sched record

 - account for unordered events in perf sched latency

 - (add -f to perf sched record to ease measurements)

 - skip idle threads (pid==0) in latency output

The result is better latency output by 'perf sched latency':

 -----------------------------------------------------------------------------------
  Task              |  Runtime ms | Switches | Average delay ms | Maximum delay ms |
 -----------------------------------------------------------------------------------
  ksoftirqd/8       |    0.071 ms |        2 | avg:    0.458 ms | max:    0.913 ms |
  at-spi-registry   |    0.609 ms |       19 | avg:    0.013 ms | max:    0.023 ms |
  perf              |    3.316 ms |       16 | avg:    0.013 ms | max:    0.054 ms |
  Xorg              |    0.392 ms |       19 | avg:    0.011 ms | max:    0.018 ms |
  sleep             |    0.537 ms |        2 | avg:    0.009 ms | max:    0.009 ms |
 -----------------------------------------------------------------------------------
  TOTAL:            |    4.925 ms |       58 |
 ---------------------------------------------

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-14 15:45:11 +02:00
Frederic Weisbecker
aa1ab9d26a perf tools: Fix processing of randomly serialized sched traces
Currently it's possible to meet such too high latency results
with 'perf sched latency'.

 -----------------------------------------------------------------------------------
 Task              |  Runtime ms | Switches | Average delay ms | Maximum delay ms |
 -----------------------------------------------------------------------------------
 xfce4-panel       |    0.222 ms |        2 | avg: 4718.345 ms | max: 9436.493 ms |
 scsi_eh_3         |    3.962 ms |       36 | avg:   55.957 ms | max: 1977.829 ms |

The origin is on traces that are sometimes badly serialized across cpus.
For example the raw traces that raised such results for xfce4-panel:

(1)          [init]-0     [000]  1494.663899990: sched_switch: task swapper:0 [140] (R) ==> xfce4-panel:4569 [120]
(2)     xfce4-panel-4569  [000]  1494.663928373: sched_switch: task xfce4-panel:4569 [120] (S) ==> swapper:0 [140]
(3)            Xorg-4276  [001]  1494.663860125: sched_wakeup: task xfce4-panel:4569 [120] success=1 [000]
(4)            Xorg-4276  [001]  1504.098252756: sched_wakeup: task xfce4-panel:4569 [120] success=1 [000]
(5)            perf-5219  [000]  1504.100353302: sched_switch: task perf:5219 [120] (S) ==> xfce4-panel:4569 [120]

The traces are processed in the order they arrive. Then in (2),
xfce4-panel sleeps, it is first waken up in (3) and eventually
scheduled in (5).

The latency reported is then 1504 - 1495 = 9 secs, as reported by perf
sched. But this is wrong, we are confident in the fact the traces are
nicely serialized while we should actually more trust the timestamps.

If we reorder by timestamps we get:

(1)            Xorg-4276  [001]  1494.663860125: sched_wakeup: task xfce4-panel:4569 [120] success=1 [000]
(2)          [init]-0     [000]  1494.663899990: sched_switch: task swapper:0 [140] (R) ==> xfce4-panel:4569 [120]
(3)     xfce4-panel-4569  [000]  1494.663928373: sched_switch: task xfce4-panel:4569 [120] (S) ==> swapper:0 [140]
(4)            Xorg-4276  [001]  1504.098252756: sched_wakeup: task xfce4-panel:4569 [120] success=1 [000]
(5)            perf-5219  [000]  1504.100353302: sched_switch: task perf:5219 [120] (S) ==> xfce4-panel:4569 [120]

Now the trace make more sense, xfce4-panel is sleeping. Then it is
woken up in (1), scheduled in (2)
It goes to sleep in (3), woken up in (4) and scheduled in (5).

Now, latency captured between (1) and (2) is of 39 us.
And between (4) and (5) it is 2.1 ms.

Such pattern of bad serializing is the origin of the high latencies
reported by perf sched.

Basically, we need to check whether wake up time is higher than
schedule out time. If it's not the case, we need to tag the current
work atom as invalid.

Beside that, we may need to work later on a better ordering of the
traces given by the kernel.

After this patch:

xfce4-session     |    0.221 ms |        1 | avg:    0.538 ms | max:    0.538 ms |

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-14 15:45:10 +02:00
Frederic Weisbecker
d13025222c perf tools: Add an option to multiplex counters in a single channel
Add an option to multiplex counters output in the channel of
the group leader, ie: the first counter opened:

	-M --multiplex

The effect is better serialized samples. This is especially
useful for tracepoint samples that need to be well serialized
for their post-processing.

Also make use of this option in 'perf sched'.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-14 09:52:23 +02:00
Ingo Molnar
c13f0d3c81 perf sched: Add 'perf sched trace', improve documentation
Alias 'perf sched trace' to 'perf trace', for workflow completeness.

Add a bit of documentation for perf sched.

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 17:55:23 +02:00
Ingo Molnar
1fc35b29b4 perf sched: Implement the 'perf sched record' subcommand
Implement the 'perf sched record' subcommand that adds a
default list of events, turns on raw sampling and system-wide
tracing and passes off the rest of the command to perf record.

This is more convenient than having to specify the events all
the time.

Before:

 $ perf record -a -R -e sched:sched_switch:r -e sched:sched_stat_wait:r -e sched:sched_stat_sleep:r -e sched:sched_stat_iowait:r -e sched:sched_process_exit:r -e sched:sched_process_fork:r -e sched:sched_wakeup:r -e sched:sched_migrate_task:r -c 1 sleep 1

After:

 $ perf sched record -f sleep 1

Also fix an assumption in the event string parser that assumed
that strings passed in can be modified. (In this case they wont
be as they come from a readonly constant section.)

Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 10:22:51 +02:00
Ingo Molnar
b5fae128e4 perf sched: Clean up PID sorting logic
Use a sort list for thread atoms insertion as well - instead of
hardcoded for PID.

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 10:22:50 +02:00
Ingo Molnar
b1ffe8f3e0 perf sched: Finish latency => atom rename and misc cleanups
- Rename 'latency' field/variable names to the better 'atom' ones

 - Reduce the number of #include lines and consolidate them

 - Gather file scope variables at the top of the file

 - Remove unused bits

No change in functionality.

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 10:22:49 +02:00
Ingo Molnar
f2858d8ad9 perf sched: Add 'perf sched latency' and 'perf sched replay'
Separate the option parsing cleanly and add two variants:

 - 'perf sched latency' (can be abbreviated via 'perf sched lat')
 - 'perf sched replay'  (can be abbreviated via 'perf sched rep')

Also add a repeat count option to replay and add a separation
set of options for replay.

Do the sorting setup only in the latency sub-command.

Display separate help screens for 'perf sched' and
'perf sched replay -h' - i.e. further separation of the
sub-commands.

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 10:22:49 +02:00
Frederic Weisbecker
daa1d7a5ea perf sched: Implement multidimensional sorting
Implement multidimensional sorting on perf sched so that
you can sort either by number of switches, latency average,
latency maximum, runtime.

perf sched -l -s avg,max  (this is the default)

-----------------------------------------------------------------------------------
 Task              |  Runtime ms | Switches | Average delay ms | Maximum delay ms |
-----------------------------------------------------------------------------------
 gnome-power-man   |    0.113 ms |        1 | avg: 4998.531 ms | max: 4998.531 ms |
 xfdesktop         |    1.190 ms |        7 | avg:  136.475 ms | max:  940.933 ms |
 xfce-mcs-manage   |    2.194 ms |       22 | avg:   38.534 ms | max:  735.174 ms |
 notification-da   |    2.749 ms |       31 | avg:   27.436 ms | max:  731.791 ms |
 xfce4-session     |    3.343 ms |       28 | avg:   26.796 ms | max:  734.891 ms |
 xfwm4             |    3.159 ms |       22 | avg:   12.406 ms | max:  241.333 ms |
 xchat             |   42.789 ms |      214 | avg:   11.886 ms | max:  100.349 ms |
 xfce4-terminal    |    5.386 ms |       22 | avg:   11.414 ms | max:  241.611 ms |
 firefox           |  151.992 ms |      123 | avg:    9.543 ms | max:  153.717 ms |
 xfce4-panel       |   24.324 ms |       47 | avg:    8.189 ms | max:  242.352 ms |
 :5090             |    6.932 ms |      111 | avg:    8.131 ms | max:  102.665 ms |
 events/0          |    0.758 ms |       12 | avg:    1.964 ms | max:   21.879 ms |
 Xorg              |  280.558 ms |      340 | avg:    1.864 ms | max:   99.526 ms |
 geany             |   63.391 ms |      295 | avg:    1.099 ms | max:    9.334 ms |
 reiserfs/0        |    0.039 ms |        2 | avg:    0.854 ms | max:    1.487 ms |
 kondemand/0       |    8.251 ms |      245 | avg:    0.691 ms | max:   34.372 ms |

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 10:22:48 +02:00
Frederic Weisbecker
7362262687 perf sched: Fix nsec to msec conversion
We are dividing a time in ns by 1e9. This is a nsec to sec
conversion. What we want is msecs. Fix it by dividing by 1e6.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 10:22:48 +02:00
Frederic Weisbecker
66685678a0 perf sched: Export the total, max latency and total runtime to thread atoms list
Add a field in the thread atom list that keeps track of the
total and max latencies and also the total runtime. This makes
a faster output and also prepares for sorting.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 10:22:47 +02:00
Frederic Weisbecker
c6ced61112 perf sched: Add involuntarily sleeping task in work atoms
Currently in perf sched, we are measuring the scheduler wakeup
latencies.

Now we also want measure the time a task wait to be scheduled
after it gets preempted.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 10:22:47 +02:00
Frederic Weisbecker
1756220530 perf sched: Rename struct lat_snapshot to struct work atoms
To measures the latencies, we capture the sched atoms data into
a specific structure named struct lat_snapshot.

As this structure can be used for other purposes of scheduler
profiling and mirrors what happens in a thread work atom, lets
rename it to struct work_atom and propagate this renaming in
other functions and structures names to keep it coherent.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 10:22:46 +02:00
Ingo Molnar
3e304147cd perf sched: Output runtime and context switch totals
After:

-----------------------------------------------------------------------------------
 Task              |  Runtime ms | Switches | Average delay ms | Maximum delay ms |
-----------------------------------------------------------------------------------
 make              |    0.678 ms |       13 | avg:    0.018 ms | max:    0.050 ms |
 gcc               |    0.014 ms |        2 | avg:    0.320 ms | max:    0.627 ms |
 gcc               |    0.000 ms |        2 | avg:    0.185 ms | max:    0.369 ms |
...
-----------------------------------------------------------------------------------
 TOTAL:            |   21.316 ms |       63 |
---------------------------------------------

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 10:22:45 +02:00
Ingo Molnar
ea92ed5a8f perf sched: Add runtime stats
Extend the latency tracking structure with scheduling atom
runtime info - and sum it up during per task display.

(Also clean up a few details.)

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 10:22:45 +02:00
Ingo Molnar
d9340c1db3 perf sched: Display time in milliseconds, reorganize output
After:

-----------------------------------------------------------------------------------
 Task              |  runtime ms | switches | average delay ms | maximum delay ms |
-----------------------------------------------------------------------------------
 migration/0       |    0.000 ms |        1 | avg:    0.047 ms | max:    0.047 ms |
 ksoftirqd/0       |    0.000 ms |        1 | avg:    0.039 ms | max:    0.039 ms |
 migration/1       |    0.000 ms |        3 | avg:    0.013 ms | max:    0.016 ms |
 migration/3       |    0.000 ms |        2 | avg:    0.003 ms | max:    0.004 ms |
 migration/4       |    0.000 ms |        1 | avg:    0.022 ms | max:    0.022 ms |
 distccd           |    0.000 ms |        1 | avg:    0.004 ms | max:    0.004 ms |
 distccd           |    0.000 ms |        1 | avg:    0.014 ms | max:    0.014 ms |
 distccd           |    0.000 ms |        2 | avg:    0.000 ms | max:    0.000 ms |
 distccd           |    0.000 ms |        2 | avg:    0.012 ms | max:    0.019 ms |
 distccd           |    0.000 ms |        1 | avg:    0.002 ms | max:    0.002 ms |
 as                |    0.000 ms |        2 | avg:    0.019 ms | max:    0.019 ms |
 as                |    0.000 ms |        3 | avg:    0.015 ms | max:    0.017 ms |
 as                |    0.000 ms |        1 | avg:    0.009 ms | max:    0.009 ms |
 perf              |    0.000 ms |        1 | avg:    0.001 ms | max:    0.001 ms |
 gcc               |    0.000 ms |        1 | avg:    0.021 ms | max:    0.021 ms |
 run-mozilla.sh    |    0.000 ms |        2 | avg:    0.010 ms | max:    0.017 ms |
 mozilla-plugin-   |    0.000 ms |        1 | avg:    0.006 ms | max:    0.006 ms |
 gcc               |    0.000 ms |        2 | avg:    0.013 ms | max:    0.013 ms |
-----------------------------------------------------------------------------------

(The runtime ms column is not filled in yet.)

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 10:22:44 +02:00
Ingo Molnar
46f392c97f perf sched: Clean up latency and replay sub-commands
- Separate the latency and the replay commands more cleanly

 - Use consistent naming

 - Display help page on 'perf sched' outlining comments,
   instead of aborting

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 10:22:44 +02:00
Frederic Weisbecker
cdce9d738b perf sched: Add sched latency profiling
Add the -l --latency option that reports statistics about the
scheduler latencies.

For now, the latencies are measured in the following sequence
scope:

- task A is sleeping (D or S state)
- task B wakes up A
         ^
         |
         |

   latency timeframe

         |
         |
         v
- task A is scheduled in

Start by recording every scheduler events:

	perf record -e sched:*

and then fetch the results:

	perf sched -l

 Tasks                     count          total              avg            max

migration/0                  2             39849            19924           28826
ksoftirqd/0                  7            756383           108054          373014
migration/1                  5             45391             9078           10452
ksoftirqd/1                  2            399055           199527          359130
events/0                     8           4780110           597513         4500250
events/1                     9           6353057           705895         2986012
kblockd/0                   42          37805097           900121         5077684

The snapshot are in nanoseconds.

- Count: number of snapshots taken for the given task
- Total: total latencies in nanosec
- Avg  : average of latency between wake up and sched in
- Max  : max snapshot latency

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 10:22:43 +02:00
Frederic Weisbecker
419ab0d6a9 perf sched: Make it easier to plug in new sub profilers
Create a sched event structure of handlers in which various
sched events reader can plug their own callbacks.

This makes easier the addition of new perf sched sub commands.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 10:22:42 +02:00
Frederic Weisbecker
4653881802 perf sched: Fix bad event alignment
perf sched raises the following error when it meets a sched
switch event:

perf: builtin-sched.c:286: register_pid: Assertion `!(pid >= 65536)' failed.
Abandon

Currently in x86-64, the sched switch events have a hole in the
middle of the structure:

	u16 common_type;
	u8 common_flags;
	u8 common_preempt_count;
	u32 common_pid;
	u32 common_tgid;

	char prev_comm[16];
	u32 prev_pid;
	u32 prev_prio;
			<--- there
	u64 prev_state;
	char next_comm[16];
	u32 next_pid;
	u32 next_prio;

Gcc inserts a 4 bytes hole there for prev_state to be u64
aligned. And the events are exported to userspace with this
hole.

But in userspace, from perf sched, we fetch it using a
structure that has a new field in the beginning: u32 size. This
is because our trace is exported with its size as a field. But
now that we have this new field, the hole in the middle
disappears because it makes prev_state becoming well aligned.

And since we are using a pointer to the raw trace using this
struct, instead of reading prev_state, we are reading the hole.

We could fix it by keeping the size seperate from the struct
but actually there a lot of other potential problems: some
fields may be saved as long in a 64 bits system and later read
as long in a 32 bits system. Also this direct cast doesn't care
about the endianness differences between the host traced
machine and the machine in which we do the post processing.

So instead of using such dangerous direct casts, fetch the
values using the trace parsing API that already takes care of
all these problems.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 10:22:41 +02:00
Frederic Weisbecker
bcd3279f46 perf tools: Allow the specification of all tracepoints at once
Currently, when one wants to activate every tracepoint
counters of a subsystem from perf record, the current sequence
is needed:

  perf record -e subsys:ev1 -e subsys:ev2 -e subsys:ev3

This may annoy the most patient of us.

Now we can just do:

  perf record -e subsys:*

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 10:22:40 +02:00
Ingo Molnar
ad236fd23b perf sched: Tighten up the code
Various small cleanups - removal of debug printks and dead
functions, etc.

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 10:22:39 +02:00
Ingo Molnar
fbf9482911 perf sched: Implement the scheduling workload replay engine
Integrate the schedbench.c bits with the raw trace events
that we get from the perf machinery, and activate the
workload replayer/simulator.

Example of a captured 'make -j' workload:

$ perf sched

  run measurement overhead: 90 nsecs
  sleep measurement overhead: 2724743 nsecs
  the run test took 1000081 nsecs
  the sleep test took 2981111 nsecs
  version = 0.5
  ...
  nr_run_events:        70
  nr_sleep_events:      66
  nr_wakeup_events:     9
  target-less wakeups:  71
  multi-target wakeups: 47
  run events optimized: 139
  task      0 (                perf:      6607), nr_events: 2
  task      1 (                perf:      6608), nr_events: 6
  task      2 (                    :         0), nr_events: 1
  task      3 (                make:      6609), nr_events: 5
  task      4 (                  sh:      6610), nr_events: 4
  task      5 (                make:      6611), nr_events: 6
  task      6 (                  sh:      6612), nr_events: 4
  task      7 (                make:      6613), nr_events: 5
  task      8 (        migration/11:        25), nr_events: 1
  task      9 (        migration/13:        29), nr_events: 1
  task     10 (        migration/15:        33), nr_events: 1
  task     11 (         migration/9:        21), nr_events: 1
  task     12 (                  sh:      6614), nr_events: 4
  task     13 (                make:      6615), nr_events: 5
  task     14 (                  sh:      6616), nr_events: 4
  task     15 (                make:      6617), nr_events: 7
  task     16 (         migration/3:         9), nr_events: 1
  task     17 (         migration/5:        13), nr_events: 1
  task     18 (         migration/7:        17), nr_events: 1
  task     19 (         migration/1:         5), nr_events: 1
  task     20 (                  sh:      6618), nr_events: 4
  task     21 (                make:      6619), nr_events: 5
  task     22 (                  sh:      6620), nr_events: 4
  task     23 (                make:      6621), nr_events: 10
  task     24 (                  sh:      6623), nr_events: 3
  task     25 (                 gcc:      6624), nr_events: 4
  task     26 (                 gcc:      6625), nr_events: 4
  task     27 (                 gcc:      6626), nr_events: 5
  task     28 (            collect2:      6627), nr_events: 5
  task     29 (                  sh:      6622), nr_events: 1
  task     30 (                make:      6628), nr_events: 7
  task     31 (                  sh:      6630), nr_events: 4
  task     32 (                 gcc:      6631), nr_events: 4
  task     33 (                  sh:      6629), nr_events: 1
  task     34 (                 gcc:      6632), nr_events: 4
  task     35 (                 gcc:      6633), nr_events: 4
  task     36 (            collect2:      6634), nr_events: 4
  task     37 (                make:      6635), nr_events: 8
  task     38 (                  sh:      6637), nr_events: 4
  task     39 (                  sh:      6636), nr_events: 1
  task     40 (                 gcc:      6638), nr_events: 4
  task     41 (                 gcc:      6639), nr_events: 4
  task     42 (                 gcc:      6640), nr_events: 4
  task     43 (            collect2:      6641), nr_events: 4
  task     44 (                make:      6642), nr_events: 6
  task     45 (                  sh:      6643), nr_events: 5
  task     46 (                  sh:      6644), nr_events: 3
  task     47 (                  sh:      6645), nr_events: 4
  task     48 (                make:      6646), nr_events: 6
  task     49 (                  sh:      6647), nr_events: 3
  task     50 (                make:      6648), nr_events: 5
  task     51 (                  sh:      6649), nr_events: 5
  task     52 (                  sh:      6650), nr_events: 6
  task     53 (                make:      6651), nr_events: 4
  task     54 (                make:      6652), nr_events: 5
  task     55 (                make:      6653), nr_events: 4
  task     56 (                make:      6654), nr_events: 4
  task     57 (                make:      6655), nr_events: 5
  task     58 (                  sh:      6656), nr_events: 4
  task     59 (                 gcc:      6657), nr_events: 9
  task     60 (         ksoftirqd/3:        10), nr_events: 1
  task     61 (                 gcc:      6658), nr_events: 4
  task     62 (                make:      6659), nr_events: 5
  task     63 (                  sh:      6660), nr_events: 3
  task     64 (                 gcc:      6661), nr_events: 5
  task     65 (            collect2:      6662), nr_events: 4
  ------------------------------------------------------------
  #1  : 256.745, ravg: 256.74, cpu: 0.00 / 0.00
  #2  : 439.372, ravg: 275.01, cpu: 0.00 / 0.00
  #3  : 411.971, ravg: 288.70, cpu: 0.00 / 0.00
  #4  : 385.500, ravg: 298.38, cpu: 0.00 / 0.00
  #5  : 366.526, ravg: 305.20, cpu: 0.00 / 0.00
  #6  : 381.281, ravg: 312.81, cpu: 0.00 / 0.00
  #7  : 410.756, ravg: 322.60, cpu: 0.00 / 0.00
  #8  : 368.009, ravg: 327.14, cpu: 0.00 / 0.00
  #9  : 408.098, ravg: 335.24, cpu: 0.00 / 0.00
  #10 : 368.582, ravg: 338.57, cpu: 0.00 / 0.00

I.e. we successfully analyzed the trace, replayed it
via real threads and measured the replayed workload's
scheduling properties.

This is how it looked like in 'top' output:

   PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
  7164 mingo     20   0 1434m 8080  888 R 57.0  0.1   0:02.04 :perf
  7165 mingo     20   0 1434m 8080  888 R 41.8  0.1   0:01.52 :perf
  7228 mingo     20   0 1434m 8080  888 R 39.8  0.1   0:01.44 :gcc
  7225 mingo     20   0 1434m 8080  888 R 33.8  0.1   0:01.26 :gcc
  7202 mingo     20   0 1434m 8080  888 R 31.2  0.1   0:01.16 :sh
  7222 mingo     20   0 1434m 8080  888 R 25.2  0.1   0:00.96 :sh
  7211 mingo     20   0 1434m 8080  888 R 21.9  0.1   0:00.82 :sh
  7213 mingo     20   0 1434m 8080  888 D 19.2  0.1   0:00.74 :sh
  7194 mingo     20   0 1434m 8080  888 D 18.6  0.1   0:00.72 :make

There's still various kinks in it - more patches to come.

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 10:22:38 +02:00
Ingo Molnar
ec156764d4 perf sched: Import schedbench.c
Import the schedbench.c tool that i wrote some time ago to
simulate scheduler behavior but never finished. It's a good
basis for perf sched nevertheless.

Most of its guts are not hooked up to the perf event loop
yet - that will be done in the patches to come.

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 10:22:37 +02:00
Ingo Molnar
0a02ad9331 perf: Add 'perf sched' tool
This turn-key tool allows scheduler measurements to be
conducted and the results be displayed numerically.

First baby step towards that goal: clone the new command off of
perf trace.

Fix a few other details along the way:

 - add (minimal) perf trace documentation

 - reorder a few places

 - list perf trace in the mainporcelain list as well
   as it's a very useful utility.

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 10:22:36 +02:00
David S. Miller
cabc5c0f7f Merge branch 'master' of /home/davem/src/GIT/linux-2.6/
Conflicts:
	arch/sparc/Kconfig
2009-09-11 20:35:13 -07:00
Linus Torvalds
483e3cd6a3 Merge branch 'tracing-core-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/linux-2.6-tip
* 'tracing-core-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/linux-2.6-tip: (105 commits)
  ring-buffer: only enable ring_buffer_swap_cpu when needed
  ring-buffer: check for swapped buffers in start of committing
  tracing: report error in trace if we fail to swap latency buffer
  tracing: add trace_array_printk for internal tracers to use
  tracing: pass around ring buffer instead of tracer
  tracing: make tracing_reset safe for external use
  tracing: use timestamp to determine start of latency traces
  tracing: Remove mentioning of legacy latency_trace file from documentation
  tracing/filters: Defer pred allocation, fix memory leak
  tracing: remove users of tracing_reset
  tracing: disable buffers and synchronize_sched before resetting
  tracing: disable update max tracer while reading trace
  tracing: print out start and stop in latency traces
  ring-buffer: disable all cpu buffers when one finds a problem
  ring-buffer: do not count discarded events
  ring-buffer: remove ring_buffer_event_discard
  ring-buffer: fix ring_buffer_read crossing pages
  ring-buffer: remove unnecessary cpu_relax
  ring-buffer: do not swap buffers during a commit
  ring-buffer: do not reset while in a commit
  ...
2009-09-11 13:24:03 -07:00
Ingo Molnar
ed011b22ce Merge commit 'v2.6.31-rc9' into tracing/core
Merge reason: move from -rc5 to -rc9.

Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-06 06:11:42 +02:00
Ulrich Drepper
6b58e7f146 perf tools: Avoid unnecessary work in directory lookups
This patch improves some (common) inefficiencies in the
handling of directory lookups:

- not using the d_type information returned by the kernel

- constructing (absolute) paths for file operation even though
  directory-relative operations using the *at functions is
  possible

There are more places to fix but this is a start.

Signed-off-by: Ulrich Drepper <drepper@redhat.com>
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Mike Galbraith <efault@gmx.de>
LKML-Reference: <20090904193951.GB6186@ghostprotocols.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-04 21:50:17 +02:00
Peter Zijlstra
849abde92b perf stat: Clean up statistics calculations a bit more
Remove some, now useless, global storage.
Don't calculate the stddev when not needed.

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-04 20:27:26 +02:00
Peter Zijlstra
8a02631a47 perf stat: More advanced variance computation
Use the more advanced single pass variance algorithm outlined
on the wikipedia page. This is numerically more stable for
larger sample sets.

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-04 17:38:15 +02:00
Peter Zijlstra
63d40deb2e perf stat: Use stddev_mean in stead of stddev
When we're computing the mean by sampling the distribution,
then the std dev of the mean is related to the std dev of the
sample set by:

  stddev_mean = std_dev / sqrt(N)

Which is exactly what we want.

This results in the error on the mean decreasing with
increasing number of samples.

Also fix the scaled == -1, aka not counted case.

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-04 17:38:14 +02:00
Peter Zijlstra
9e9772c458 perf stat: Remove the limit on repeat
Since we don't need all the individual samples to calculate the
error remove both the limit and the storage overhead associated
with that.

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-04 16:33:08 +02:00
Peter Zijlstra
506d4bc8d5 perf stat: Change noise calculation to use stddev
The current noise computation does:

 \Sum abs(n_i - avg(n)) * N^-1.5

Which is (afaik) not a regular noise function, and needs the
complete sample set available to post-process.

Change this to use a regular stddev computation which can be
done by keeping a two sums:

 stddev = sqrt( 1/N (\Sum n_i^2) - avg(n)^2 )

For which we only need to keep \Sum n_i and \Sum n_i^2.

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: <stable@kernel.org>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-04 16:33:07 +02:00
Jens Axboe
825c9fb47a sparc: add basic support for 'perf'
This wires up the perf_counter_open() syscall so that basic
software support for perf is working.

Signed-off-by: Jens Axboe <jens.axboe@oracle.com>
Signed-off-by: David S. Miller <davem@davemloft.net>
2009-09-04 02:56:22 -07:00
Ingo Molnar
6f4596d931 perf trace: Fix read_string()
We did not account for the enclosing \0. Depending on what malloc()
gave us this resulted in corrupted version string printouts.

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-03 16:22:45 +02:00
Ingo Molnar
00fc97863c perf trace: Print out in nanoseconds
Print out more accurate timestamps - usecs does not cut it
anymore on fast enough boxes ;-)

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-03 16:22:02 +02:00
Ingo Molnar
2e01d17911 perf tools: Seek to the end of the header area
Leave the input fd at the data area.

It does not matter right now - but seeking at the end of it
certainly did not make sense.

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-03 16:21:11 +02:00
Ingo Molnar
8886f42d6d perf trace: Fix parsing of perf.data
We started parsing perf.data at head 0. This caused -D to
segfault and it could possibly also case incorrect trace
entries to be displayed.

Parse it at data_offset instead.

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-03 16:19:57 +02:00
Ingo Molnar
6ddf259da7 perf trace: Sample timestamps as well
Before:

            perf-21082 [013]     0.000000: sched_wakeup_new: task perf:21083 [120] success=1 [015]
            perf-21082 [013]     0.000000: sched_migrate_task: task perf:21082 [120] from: 13  to: 15
            perf-21082 [013]     0.000000: sched_process_fork: parent perf:21082  child perf:21083
            true-21083 [015]     0.000000: sched_wakeup: task migration/15:33 [0] success=1 [015]
            perf-21082 [013]     0.000000: sched_switch: task perf:21082 [120] (S) ==> swapper:0 [140]
            true-21083 [015]     0.000000: sched_switch: task perf:21083 [120] (R) ==> migration/15:33 [0]
            true-21083 [011]     0.000000: sched_process_exit: task true:21083 [120]

After:

            perf-21082 [013] 14674.797613: sched_wakeup_new: task perf:21083 [120] success=1 [015]
            perf-21082 [013] 14674.797506: sched_migrate_task: task perf:21082 [120] from: 13  to: 15
            perf-21082 [013] 14674.797610: sched_process_fork: parent perf:21082  child perf:21083
            true-21083 [015] 14674.797725: sched_wakeup: task migration/15:33 [0] success=1 [015]
            perf-21082 [013] 14674.797722: sched_switch: task perf:21082 [120] (S) ==> swapper:0 [140]
            true-21083 [015] 14674.797729: sched_switch: task perf:21083 [120] (R) ==> migration/15:33 [0]
            true-21083 [011] 14674.798159: sched_process_exit: task true:21083 [120]

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-03 15:45:49 +02:00
Ingo Molnar
cd6feeeafd perf trace: Sample the CPU too
Sample, record, parse and print the CPU field - it had all zeroes before.

Before (watch the second column, the CPU values):

            perf-32685 [000]     0.000000: sched_wakeup_new: task perf:32686 [120] success=1 [011]
            perf-32685 [000]     0.000000: sched_migrate_task: task perf:32685 [120] from: 1  to: 11
            perf-32685 [000]     0.000000: sched_process_fork: parent perf:32685  child perf:32686
            true-32686 [000]     0.000000: sched_wakeup: task migration/11:25 [0] success=1 [011]
            true-32686 [000]     0.000000: sched_wakeup: task distccd:12793 [125] success=1 [015]
            true-32686 [000]     0.000000: sched_wakeup: task distccd:12793 [125] success=1 [015]
            perf-32685 [000]     0.000000: sched_switch: task perf:32685 [120] (S) ==> swapper:0 [140]
            true-32686 [000]     0.000000: sched_switch: task perf:32686 [120] (R) ==> migration/11:25 [0]
            true-32686 [000]     0.000000: sched_switch: task perf:32686 [120] (R) ==> distccd:12793 [125]
            true-32686 [000]     0.000000: sched_switch: task true:32686 [120] (R) ==> distccd:12793 [125]
            true-32686 [000]     0.000000: sched_process_exit: task true:32686 [120]
            true-32686 [000]     0.000000: sched_stat_wait: task: distccd:12793 wait: 6767985949080 [ns]
            true-32686 [000]     0.000000: sched_stat_wait: task: distccd:12793 wait: 6767986139446 [ns]
            true-32686 [000]     0.000000: sched_stat_sleep: task: distccd:12793 sleep: 132844 [ns]
            true-32686 [000]     0.000000: sched_stat_sleep: task: distccd:12793 sleep: 131724 [ns]

After:

            perf-32685 [001]     0.000000: sched_wakeup_new: task perf:32686 [120] success=1 [011]
            perf-32685 [001]     0.000000: sched_migrate_task: task perf:32685 [120] from: 1  to: 11
            perf-32685 [001]     0.000000: sched_process_fork: parent perf:32685  child perf:32686
            true-32686 [011]     0.000000: sched_wakeup: task migration/11:25 [0] success=1 [011]
            true-32686 [015]     0.000000: sched_wakeup: task distccd:12793 [125] success=1 [015]
            true-32686 [015]     0.000000: sched_wakeup: task distccd:12793 [125] success=1 [015]
            perf-32685 [001]     0.000000: sched_switch: task perf:32685 [120] (S) ==> swapper:0 [140]
            true-32686 [011]     0.000000: sched_switch: task perf:32686 [120] (R) ==> migration/11:25 [0]
            true-32686 [015]     0.000000: sched_switch: task perf:32686 [120] (R) ==> distccd:12793 [125]
            true-32686 [015]     0.000000: sched_switch: task true:32686 [120] (R) ==> distccd:12793 [125]
            true-32686 [015]     0.000000: sched_process_exit: task true:32686 [120]
            true-32686 [015]     0.000000: sched_stat_wait: task: distccd:12793 wait: 6767985949080 [ns]
            true-32686 [015]     0.000000: sched_stat_wait: task: distccd:12793 wait: 6767986139446 [ns]
            true-32686 [015]     0.000000: sched_stat_sleep: task: distccd:12793 sleep: 132844 [ns]
            true-32686 [015]     0.000000: sched_stat_sleep: task: distccd:12793 sleep: 131724 [ns]

So we can now see how this workload migrated between CPUs.

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Li Zefan <lizf@cn.fujitsu.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-02 21:28:50 +02:00
Ingo Molnar
65014ab361 perf tools: Work around strict aliasing related warnings
Older versions of GCC are rather stupid about strict aliasing:

  util/trace-event-parse.c: In function 'parse_cmdlines':
  util/trace-event-parse.c:93: warning: dereferencing type-punned pointer will break strict-aliasing rules
  util/trace-event-parse.c: In function 'parse_proc_kallsyms':
  util/trace-event-parse.c:155: warning: dereferencing type-punned pointer will break strict-aliasing rules
  util/trace-event-parse.c:157: warning: dereferencing type-punned pointer will break strict-aliasing rules
  util/trace-event-parse.c:158: warning: dereferencing type-punned pointer will break strict-aliasing rules
  util/trace-event-parse.c: In function 'parse_ftrace_printk':
  util/trace-event-parse.c:294: warning: dereferencing type-punned pointer will break strict-aliasing rules
  util/trace-event-parse.c:295: warning: dereferencing type-punned pointer will break strict-aliasing rules
  make: *** [util/trace-event-parse.o] Error 1

Make it clear to GCC that we intend with those pointers, by passing
them through via an explicit (void *) cast.

We might want to add -fno-strict-aliasing as well, like the kernel
itself does.

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-02 14:56:33 +02:00
Ingo Molnar
61562445c8 perf tools: Clean up warnings list in the Makefile
Make it easier to turn warnings on/off by using a separate
line for each warning added.

Some of the warnings have too much of a nuisance factor and
we might want to turn them off in the future.

Cc: Arjan van de Ven <arjan@infradead.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <new-submission>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-02 14:50:23 +02:00
Frederic Weisbecker
561f732c12 perf tools: Complete support for dynamic strings
Complete support for __str_loc type strings of ftrace events
which have dynamic offsets values set for each of them inside
their sammples.

Before:
        geany-5759  [000]     0.000000: lock_release: name
        geany-5759  [000]     0.000000: lock_release: name
        geany-5759  [000]     0.000000: lock_release: name
  kondemand/0-362   [000]     0.000000: lock_release: name
      pdflush-421   [000]     0.000000: lock_release: name

After:
        geany-5759  [000]     0.000000: lock_release: &u->lock
        geany-5759  [000]     0.000000: lock_release: key
        geany-5759  [000]     0.000000: lock_release: &group->notification_mutex
  kondemand/0-362   [000]     0.000000: lock_release: &rq->lock
      pdflush-421   [000]     0.000000: lock_release: &rq->lock

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
LKML-Reference: <1251693921-6579-4-git-send-email-fweisbec@gmail.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
2009-08-31 10:04:49 +02:00
Frederic Weisbecker
9b8055a52c perf tools: Unify swapper tasks naming
In perf tools, we hardcode the pid 0 cmdline resolving to
"idle" because the init task is not included in the COMM
events.

But the idle tasks secondary cpus are resolved into their
"init" name through the COMM events.

We have then such strange result in perf report (ditto with
trace):

    19.66%       init    [kernel]          [k] acpi_idle_enter_c1
    17.32%       [idle]  [kernel]          [k] acpi_idle_enter_c1

It's then better to unify the swapper tasks into a single init
name.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
LKML-Reference: <1251693921-6579-3-git-send-email-fweisbec@gmail.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
2009-08-31 10:04:49 +02:00
Frederic Weisbecker
3a2684ca58 perf tools: Resolve idle thread cmdline for perf trace
The cmd-trace tool used the cmdline file and resolved the idle
thread using a hardcoded check for the 0 task pid.

Now we have a centralized way to do that from perf using
register_idle_thread() API.

Before:
	:0-0     [000]     0.000000: irq_handler_entry: irq=0 handler=name
	:0-0     [000]     0.000000: irq_handler_entry: irq=0 handler=name

After:
	[idle]-0     [000]     0.000000: irq_handler_entry: irq=0 handler=name
	[idle]-0     [000]     0.000000: irq_handler_entry: irq=0 handler=name

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
LKML-Reference: <1251693921-6579-2-git-send-email-fweisbec@gmail.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-08-31 10:04:48 +02:00
Frederic Weisbecker
5b447a6a13 perf tools: Librarize idle thread registration
Librarize register_idle_thread() used by annotate and report.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
LKML-Reference: <1251693921-6579-1-git-send-email-fweisbec@gmail.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-08-31 10:04:48 +02:00
Frederic Weisbecker
ec7ba4ea1d perf tools: Add missing parameters documentation
Add missing documentation for the following parameters:

- perf record -R
- perf report -g

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
LKML-Reference: <1251682323-10395-1-git-send-email-fweisbec@gmail.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-08-31 10:04:47 +02:00
Ingo Molnar
19c959627a Merge branch 'perfcounters/tracing' into perfcounters/core
Merge reason: this topic is ready now to merge into the main
              development branch for .32, with functional
              perf trace output.

Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-08-31 10:03:27 +02:00
Pierre Habouzit
119e7a22bb perf tools: do not complain if root is owning perf.data
This improves patch fa6963b24 so that perf.data stuff that has
been dumped as root can be read (annotate/report) by a user
without the use of the --force.

Rationale is that root has plenty of ways to screw us (usually)
that do not require twisted schemes involving specially
crafting a perf.data.

Signed-off-by: Pierre Habouzit <pierre.habouzit@intersec.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: <stable@kernel.org>
LKML-Reference: <20090827075902.GF19653@laphroaig.corp>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-08-28 13:47:43 +02:00
Frederic Weisbecker
d498bc1f62 perf tools: Fix missing string field printing in perf trace
Some string fields are not printed because of a missing printf
in the post-processing.

Before:
	    perf-10070 [000]     0.000000: sched_switch: task :10070 [120] (R) ==> :5720 [120]
           geany-5720  [000]     0.000000: sched_switch: task :5720 [120] (S) ==> :10070 [120]
            perf-10070 [000]     0.000000: sched_switch: task :10070 [120] (R) ==> :5720 [120]
           geany-5720  [000]     0.000000: sched_switch: task :5720 [120] (S) ==> :10070 [120]
          <idle>-0     [000]     0.000000: sched_switch: task :0 [140] (R) ==> :361 [115]

After:
	    perf-10070 [000]     0.000000: sched_switch: task perf:10070 [120] (R) ==> geany:5720 [120]
           geany-5720  [000]     0.000000: sched_switch: task geany:5720 [120] (S) ==> perf:10070 [120]
            perf-10070 [000]     0.000000: sched_switch: task perf:10070 [120] (R) ==> geany:5720 [120]
           geany-5720  [000]     0.000000: sched_switch: task geany:5720 [120] (S) ==> perf:10070 [120]
          <idle>-0     [000]     0.000000: sched_switch: task swapper:0 [140] (R) ==> kondemand/1:361 [115]

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
LKML-Reference: <1251427567-10551-2-git-send-email-fweisbec@gmail.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-08-28 07:58:11 +02:00