21 Sep, 2009
5 commits
-
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' \
$FILESfor N in $(find . -name perf_counter.[ch]); do
M=$(echo $N | sed 's/perf_counter/perf_event/g')
mv $N $M
doneFILES=$(find . -name perf_event.*)
sed -i \
-e 's/COUNTER_MASK/REG_MASK/g' \
-e 's/COUNTER/EVENT/g' \
-e 's/\/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
Acked-by: Peter Zijlstra
Acked-by: Paul Mackerras
Reviewed-by: Arjan van de Ven
Cc: Mike Galbraith
Cc: Arnaldo Carvalho de Melo
Cc: Frederic Weisbecker
Cc: Steven Rostedt
Cc: Benjamin Herrenschmidt
Cc: David Howells
Cc: Kyle McMartin
Cc: Martin Schwidefsky
Cc: "David S. Miller"
Cc: Thomas Gleixner
Cc: "H. Peter Anvin"
Cc:
LKML-Reference:
Signed-off-by: Ingo Molnar -
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
Cc: Peter Zijlstra
Cc: Paul Mackerras
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar -
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
Cc: Peter Zijlstra
Cc: Paul Mackerras
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar -
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
Cc: Peter Zijlstra
Cc: Paul Mackerras
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar -
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
Cc: Peter Zijlstra
Cc: Paul Mackerras
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar
20 Sep, 2009
4 commits
-
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
Cc: fweisbec@gmail.com
Cc: peterz@infradead.org
Cc: Paul Mackerras
LKML-Reference:
[ add a few comments to nearby functions ]
Signed-off-by: Ingo Molnar -
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
Cc: fweisbec@gmail.com
Cc: peterz@infradead.org
Cc: Paul Mackerras
LKML-Reference:
Signed-off-by: Ingo Molnar -
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
Cc: fweisbec@gmail.com
Cc: peterz@infradead.org
Cc: Paul Mackerras
Cc: Arjan van de Ven
LKML-Reference:
Signed-off-by: Ingo Molnar -
Add a command line option to record a trace, similar to "perf sched record".
Signed-off-by: Arjan van de Ven
Cc: fweisbec@gmail.com
Cc: peterz@infradead.org
Cc: Paul Mackerras
LKML-Reference:
Signed-off-by: Ingo Molnar
19 Sep, 2009
7 commits
-
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
Acked-by: Peter Zijlstra
Cc: Paul Mackerras
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar -
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
Acked-by: Peter Zijlstra
Cc: Paul Mackerras
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar -
Add a sample_event type to the event_union so that raw samples can
be processed easily.Signed-off-by: Arjan van de Ven
Acked-by: Peter Zijlstra
Cc: Paul Mackerras
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar -
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
Acked-by: Peter Zijlstra
Cc: Paul Mackerras
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar -
The trace event nameid 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
Acked-by: Peter Zijlstra
Cc: Paul Mackerras
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar -
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
Acked-by: Peter Zijlstra
Cc: Paul Mackerras
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar -
Merge reason: Bring in tracing changes we depend on.
Signed-off-by: Ingo Molnar
18 Sep, 2009
6 commits
-
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
Acked-by: Peter Zijlstra
LKML-Reference:
Signed-off-by: Ingo Molnar -
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=i8042After:
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=eth0Signed-off-by: Li Zefan
Acked-by: Frederic Weisbecker
Cc: Peter Zijlstra
LKML-Reference:
Signed-off-by: Ingo Molnar -
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
Acked-by: Frederic Weisbecker
Cc: Peter Zijlstra
LKML-Reference:
Signed-off-by: Ingo Molnar -
get_tracing_file() should be paired with put_tracing_file().
Signed-off-by: Li Zefan
Acked-by: Frederic Weisbecker
Cc: Peter Zijlstra
LKML-Reference:
Signed-off-by: Ingo Molnar -
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 ]
Cc: Peter Zijlstra
Cc: Mike Galbraith
Cc: Paul Mackerras
Cc: Arnaldo Carvalho de Melo
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar -
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
LKML-Reference:
Signed-off-by: Ingo Molnar
16 Sep, 2009
4 commits
-
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 secsColumns 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
Cc: Mike Galbraith
Cc: Paul Mackerras
Cc: Arnaldo Carvalho de Melo
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar -
Peter noticed that we have 3 ways of referring to the idle thread:
[idle]:0
swapper:0
swapper-0Standardize on 'swapper:0'.
Reported-by: Peter Zijlstra
Cc: Mike Galbraith
Cc: Paul Mackerras
Cc: Arnaldo Carvalho de Melo
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar -
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
Cc: Mike Galbraith
Cc: Paul Mackerras
Cc: Arnaldo Carvalho de Melo
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar -
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
Cc: Mike Galbraith
Cc: Paul Mackerras
Cc: Arnaldo Carvalho de Melo
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar
15 Sep, 2009
3 commits
-
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
Cc: Mike Galbraith
Cc: Paul Mackerras
Cc: Arnaldo Carvalho de Melo
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar -
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
Cc: Mike Galbraith
Cc: Paul Mackerras
Cc: Arnaldo Carvalho de Melo
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar -
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
Cc: Mike Galbraith
Cc: Paul Mackerras
Cc: Arnaldo Carvalho de Melo
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar
14 Sep, 2009
3 commits
-
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
Cc: Mike Galbraith
Cc: Paul Mackerras
Cc: Arnaldo Carvalho de Melo
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar -
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
Cc: Mike Galbraith
Cc: Peter Zijlstra
Cc: Paul Mackerras
Cc: Arnaldo Carvalho de Melo
Signed-off-by: Ingo Molnar -
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
Cc: Peter Zijlstra
Cc: Mike Galbraith
Cc: Paul Mackerras
Cc: Arnaldo Carvalho de Melo
Signed-off-by: Ingo Molnar
13 Sep, 2009
8 commits
-
Alias 'perf sched trace' to 'perf trace', for workflow completeness.
Add a bit of documentation for perf sched.
Cc: Peter Zijlstra
Cc: Mike Galbraith
Cc: Paul Mackerras
Cc: Arnaldo Carvalho de Melo
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar -
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
-
Use a sort list for thread atoms insertion as well - instead of
hardcoded for PID.Cc: Peter Zijlstra
Cc: Mike Galbraith
Cc: Paul Mackerras
Cc: Arnaldo Carvalho de Melo
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar -
- 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
Cc: Mike Galbraith
Cc: Paul Mackerras
Cc: Arnaldo Carvalho de Melo
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar -
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
Cc: Mike Galbraith
Cc: Paul Mackerras
Cc: Arnaldo Carvalho de Melo
Cc: Frederic Weisbecker
LKML-Reference:
Signed-off-by: Ingo Molnar -
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
Cc: Peter Zijlstra
Cc: Mike Galbraith
Cc: Paul Mackerras
Cc: Arnaldo Carvalho de Melo
Signed-off-by: Ingo Molnar -
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
Cc: Peter Zijlstra
Cc: Mike Galbraith
Cc: Paul Mackerras
Cc: Arnaldo Carvalho de Melo
Signed-off-by: Ingo Molnar -
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
Cc: Peter Zijlstra
Cc: Mike Galbraith
Cc: Paul Mackerras
Cc: Arnaldo Carvalho de Melo
Signed-off-by: Ingo Molnar