Skip to content

Commit

Permalink
include USAGE messages in examples
Browse files Browse the repository at this point in the history
  • Loading branch information
brendangregg committed Jul 31, 2014
1 parent a2128f0 commit ca2708c
Show file tree
Hide file tree
Showing 21 changed files with 362 additions and 3 deletions.
13 changes: 13 additions & 0 deletions examples/bitesize_example.txt
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
Demonstrations of bitesize, the Linux perf_events version.


bitesize traces block I/O issued, and reports a histogram of I/O size. By
default five buckets are used to gather statistics on common I/O sizes:

Expand Down Expand Up @@ -48,3 +49,15 @@ using what is necessary.

To study this I/O in more detail, I can use iosnoop(8) and capture it to a file
for post-processing.


Use -h to print the USAGE message:

# ./bitesize -h
USAGE: bitesize [-h] [-b buckets] [seconds]
-b buckets # specify histogram buckets (Kbytes)
-h # this usage message
eg,
bitesize # trace I/O size until Ctrl-C
bitesize 10 # trace I/O size for 10 seconds
bitesize -b "8 16 32" # specify custom bucket points
55 changes: 55 additions & 0 deletions examples/execsnoop_example.txt
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
Demonstrations of execsnoop, the Linux ftrace version.


Here's execsnoop showing what's really executed by "man ls":

# ./execsnoop
Expand All @@ -14,3 +15,57 @@ Tracing exec()s. Ctrl-C to end.
22912 22907 groff -mtty-char -Tutf8 -mandoc -rLL=164n -rLT=164n
22913 22912 troff -mtty-char -mandoc -rLL=164n -rLT=164n -Tutf8
22914 22912 grotty

Many commands. This is particularly useful for understanding application
startup.


Another use for execsnoop is identifying short-lived processes. Eg, with the -t
option to see timestamps:

# ./execsnoop -t
Tracing exec()s. Ctrl-C to end.
TIMEs PID PPID ARGS
7419756.154031 8185 8181 mawk -W interactive -v o=1 -v opt_name=0 -v name= [...]
7419756.154131 8186 8184 cat -v trace_pipe
7419756.245264 8188 1698 ./run
7419756.245691 8189 1696 ./run
7419756.246212 8187 1689 ./run
7419756.278993 8190 1693 ./run
7419756.278996 8191 1692 ./run
7419756.288430 8192 1695 ./run
7419756.290115 8193 1691 ./run
7419756.292406 8194 1699 ./run
7419756.293986 8195 1690 ./run
7419756.294149 8196 1686 ./run
7419756.296527 8197 1687 ./run
7419756.296973 8198 1697 ./run
7419756.298356 8200 1685 ./run
7419756.298683 8199 1688 ./run
7419757.269883 8201 1696 ./run
[...]

So we're running many "run" commands every second. The PPID is included, so I
can debug this further (they are "supervise" processes).

Short-lived processes can consume CPU and not be visible from top(1), and can
be the source of hidden performance issues.


Run -h to print the USAGE message:

# ./execsnoop -h
USAGE: execsnoop [-hrt] [-a argc] [-d secs] [name]
-d seconds # trace duration, and use buffers
-a argc # max args to show (default 8)
-r # include re-execs
-t # include time (seconds)
-h # this usage message
name # process name to match (REs allowed)
eg,
execsnoop # watch exec()s live (unbuffered)
execsnoop -d 1 # trace 1 sec (buffered)
execsnoop grep # trace process names containing grep
execsnoop 'log$' # filenames ending in "log"

See the man page and example file for more info.
20 changes: 20 additions & 0 deletions examples/funccount_example.txt
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
Demonstrations of funccount, the Linux ftrace version.


Tracing all kernel functions that start with "bio_" (which would be block
interface functions), and counting how many times they were executed until
Ctrl-C is hit:
Expand Down Expand Up @@ -104,3 +105,22 @@ This may be normal, this may not. The purpose of this tool is to give you one
view of how one or many kernel functions are executed. Previously I had little
idea what ext4 was doing internally. Now I know the top 25 functions, and their
rate, and can begin researching them from the source code.


Use -h to print the USAGE message:

# ./funccount -h
USAGE: funccount [-hT] [-i secs] [-d secs] [-t top] funcstring
-d seconds # total duration of trace
-h # this usage message
-i seconds # interval summary
-t top # show top num entries only
-T # include timestamp (for -i)
eg,
funccount 'vfs*' # trace all funcs that match "vfs*"
funccount -d 5 'tcp*' # trace "tcp*" funcs for 5 seconds
funccount -t 10 'ext3*' # show top 10 "ext3*" funcs
funccount -i 1 'ext3*' # summary every 1 second
funccount -i 1 -d 5 'ext3*' # 5 x 1 second summaries

See the man page and example file for more info.
26 changes: 26 additions & 0 deletions examples/funcgraph_example.txt
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
Demonstrations of funcgraph, the Linux ftrace version.


I'll start by showing do_nanosleep(), since it's usually a low frequency
function that can be easily triggered (run "vmstat 1"):

Expand Down Expand Up @@ -2149,3 +2150,28 @@ Ending tracing...

Understanding whether the time is on-CPU or blocked off-CPU directs the
performance investigation.


Use -h to print the USAGE message:

# ./funcgraph -h
USAGE: funcgraph [-acDhHPtT] [-m maxdepth] [-p PID] [-d secs] funcstring
-a # all info (same as -HPt)
-c # measure on-CPU time only
-d seconds # trace duration, and use buffers
-D # do not show function duration
-h # this usage message
-H # include column headers
-m maxdepth # max stack depth to show
-p PID # trace when this pid is on-CPU
-P # show process names & PIDs
-t # show timestamps
-T # comment function tails
eg,
funcgraph do_nanosleep # trace do_nanosleep() and children
funcgraph -m 3 do_sys_open # trace do_sys_open() to 3 levels only
funcgraph -a do_sys_open # include timestamps and process name
funcgraph -p 198 do_sys_open # trace vfs_read() for PID 198 only
funcgraph -d 1 do_sys_open >out # trace 1 sec, then write to file

See the man page and example file for more info.
19 changes: 19 additions & 0 deletions examples/funcslower_example.txt
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
Demonstrations of funcslower, the Linux ftrace version.


Show me ext3_readpages() calls slower than 1000 microseconds (1 ms):

# ./funcslower ext3_readpages 1000
Expand Down Expand Up @@ -88,3 +89,21 @@ Ending tracing...
This is an example where I did not use -P, but ftrace has included process
information anyway. Look for the lines containing "=>", which indicate a process
switch on the given CPU.


Use -h to print the USAGE message:

# ./funcslower -h
USAGE: funcslower [-achHPt] [-p PID] [-d secs] funcstring latency_us
-a # all info (same as -HPt)
-c # measure on-CPU time only
-d seconds # trace duration, and use buffers
-h # this usage message
-H # include column headers
-p PID # trace when this pid is on-CPU
-P # show process names & PIDs
-t # show timestamps
eg,
funcslower vfs_read 10000 # trace vfs_read() slower than 10 ms

See the man page and example file for more info.
19 changes: 19 additions & 0 deletions examples/functrace_example.txt
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
Demonstrations of functrace, the Linux ftrace version.


A (usually) good example to start with is do_nanosleep(), since it is not called
frequently, and easily triggered. Here's tracing it using functrace:

Expand Down Expand Up @@ -319,3 +320,21 @@ This greatly reduces overheads. For example:
Note that the buffer has a limited size. Check the timestamps to see if the
range does not match your duration, as one clue that the buffer was exhausted
and events were missed.


Use -h to print the USAGE message:

# ./functrace -h
USAGE: functrace [-hH] [-p PID] [-d secs] funcstring
-d seconds # trace duration, and use buffers
-h # this usage message
-H # include column headers
-p PID # trace when this pid is on-CPU
eg,
functrace do_nanosleep # trace the do_nanosleep() function
functrace '*sleep' # trace functions ending in "sleep"
functrace -p 198 'vfs*' # trace "vfs*" funcs for PID 198
functrace 'tcp*' > out # trace all "tcp*" funcs to out file
functrace -d 1 'tcp*' > out # trace 1 sec, then write out file

See the man page and example file for more info.
22 changes: 22 additions & 0 deletions examples/iolatency_example.txt
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
Demonstrations of iolatency, the Linux ftrace version.


Here's a busy system doing over 4k disk IOPS:

# ./iolatency
Expand Down Expand Up @@ -326,3 +327,24 @@ Tracing block I/O. Output every 5 seconds. Ctrl-C to end.
Ending tracing...

Much better looking distribution.


Use -h to print the USAGE message:

# ./iolatency -h
USAGE: iolatency [-hQT] [-d device] [-i iotype] [interval [count]]
-d device # device string (eg, "202,1)
-i iotype # match type (eg, '*R*' for all reads)
-Q # use queue insert as start time
-T # timestamp on output
-h # this usage message
interval # summary interval, seconds (default 1)
count # number of summaries
eg,
iolatency # summarize latency every second
iolatency -Q # include block I/O queue time
iolatency 5 2 # 2 x 5 second summaries
iolatency -i '*R*' # trace reads
iolatency -d 202,1 # trace device 202,1 only

See the man page and example file for more info.
27 changes: 27 additions & 0 deletions examples/iosnoop_example.txt
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
Demonstrations of iosnoop, the Linux ftrace version.


Here's Linux 3.16, tracing tar archiving a filesystem:

# ./iosnoop
Expand Down Expand Up @@ -273,3 +274,29 @@ system (Xen guest) it looks like there is a shared queue. (Having just
discovered this using iosnoop, I can't yet tell you which queue, but I'd hope
that after identifying it there would be a way to tune its queueing behavior,
so that we can eliminate or reduce the severity of these outliers.)


Use -h to print the USAGE message:

# ./iosnoop -h
USAGE: iosnoop [-hQst] [-d device] [-i iotype] [-p PID] [-n name]
[duration]
-d device # device string (eg, "202,1)
-i iotype # match type (eg, '*R*' for all reads)
-n name # process name to match on I/O issue
-p PID # PID to match on I/O issue
-Q # use queue insert as start time
-s # include start time of I/O (s)
-t # include completion time of I/O (s)
-h # this usage message
duration # duration seconds, and use buffers
eg,
iosnoop # watch block I/O live (unbuffered)
iosnoop 1 # trace 1 sec (buffered)
iosnoop -Q # include queueing time in LATms
iosnoop -ts # include start and end timestamps
iosnoop -i '*R*' # trace reads
iosnoop -p 91 # show I/O issued when PID 91 is on-CPU
iosnoop -Qp 91 # show I/O queued by PID 91, queue time

See the man page and example file for more info.
33 changes: 33 additions & 0 deletions examples/kprobe_example.txt
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
Demonstrations of kprobe, the Linux ftrace version.


This traces the kernel do_sys_open() function, when it is called:

# ./kprobe p:do_sys_open
Expand Down Expand Up @@ -340,3 +341,35 @@ Tracing kprobe mytcp. Ctrl-C to end.
=> system_call_fastpath

This makes use of the kernel options/stacktrace feature.


Use -h to print the USAGE message:

# ./kprobe -h
USAGE: kprobe [-hHsv] [-d secs] [-p PID] kprobe_definition [filter]
-d seconds # trace duration, and use buffers
-p PID # PID to match on I/O issue
-v # view format file (don't trace)
-H # include column headers
-s # show kernel stack traces
-h # this usage message

Note that these examples may need modification to match your kernel
version's function names and platform's register usage.
eg,
kprobe p:do_sys_open
# trace open() entry
kprobe r:do_sys_open
# trace open() return
kprobe 'r:do_sys_open $retval'
# trace open() return value
kprobe 'r:myopen do_sys_open $retval'
# use a custom probe name
kprobe 'p:myopen do_sys_open mode=%cx:u16'
# trace open() file mode
kprobe 'p:myopen do_sys_open filename=+0(%si):string'
# trace open() with filename
kprobe -s 'p:myprobe tcp_retransmit_skb'
# show kernel stacks

See the man page and example file for more info.
22 changes: 22 additions & 0 deletions examples/opensnoop_example.txt
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
Demonstrations of opensnoop, the Linux ftrace version.


# ./opensnoop
Tracing open()s. Ctrl-C to end.
COMM PID FD FILE
Expand All @@ -22,3 +23,24 @@ supervise 1686 0x9 supervise/status.new
[...]

The first several lines show opensnoop catching itself initializing.


Use -h to print the USAGE message:

# ./opensnoop -h
USAGE: opensnoop [-htx] [-d secs] [-p PID] [-n name] [filename]
-d seconds # trace duration, and use buffers
-n name # process name to match on I/O issue
-p PID # PID to match on I/O issue
-t # include time (seconds)
-x # only show failed opens
-h # this usage message
filename # match filename (partials, REs, ok)
eg,
opensnoop # watch open()s live (unbuffered)
opensnoop -d 1 # trace 1 sec (buffered)
opensnoop -p 181 # trace I/O issued by PID 181 only
opensnoop conf # trace filenames containing "conf"
opensnoop 'log$' # filenames ending in "log"

See the man page and example file for more info.
27 changes: 27 additions & 0 deletions examples/perf-stat-hist_example.txt
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
Demonstrations of perf-stat-hist, the Linux perf_events version.


Tracing the net:net_dev_xmit tracepoint, and building a power-of-4 histogram
for the "len" variable, for 10 seconds:

Expand Down Expand Up @@ -120,3 +121,29 @@ Tracing syscalls:sys_exit_read, specified buckets, until Ctrl-C...

This has the lowest overhead for collection, since only two tracepoint
filter pairs are used.


Use -h to print the USAGE message:

# ./perf-stat-hist -h
USAGE: perf-stat-hist [-h] [-b buckets|-P power] [-m max] tracepoint
variable [seconds]
-b buckets # specify histogram bucket points
-P power # power-of (default is 4)
-m max # max value for power-of
-h # this usage message
eg,
perf-stat-hist syscalls:sys_enter_read count 5
# read() request histogram, 5 seconds
perf-stat-hist syscalls:sys_exit_read ret 5
# read() return histogram, 5 seconds
perf-stat-hist -P 10 syscalls:sys_exit_read ret 5
# ... use power-of-10
perf-stat-hist -P 2 -m 1024 syscalls:sys_exit_read ret 5
# ... use power-of-2, max 1024
perf-stat-hist -b "10 50 100 500" syscalls:sys_exit_read ret 5
# ... histogram based on these bucket ranges
perf-stat-hist -b 10 syscalls:sys_exit_read ret 5
# ... bifurcate by the value 10 (lowest overhead)

See the man page and example file for more info.
Loading

0 comments on commit ca2708c

Please sign in to comment.