diff --git a/examples/bitesize_example.txt b/examples/bitesize_example.txt index b599b2b..44a5e5f 100644 --- a/examples/bitesize_example.txt +++ b/examples/bitesize_example.txt @@ -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: @@ -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 diff --git a/examples/execsnoop_example.txt b/examples/execsnoop_example.txt index 8e2cf9b..0fca8e5 100644 --- a/examples/execsnoop_example.txt +++ b/examples/execsnoop_example.txt @@ -1,5 +1,6 @@ Demonstrations of execsnoop, the Linux ftrace version. + Here's execsnoop showing what's really executed by "man ls": # ./execsnoop @@ -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. diff --git a/examples/funccount_example.txt b/examples/funccount_example.txt index 4708945..67f11d3 100644 --- a/examples/funccount_example.txt +++ b/examples/funccount_example.txt @@ -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: @@ -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. diff --git a/examples/funcgraph_example.txt b/examples/funcgraph_example.txt index ef782f9..4b1a0b0 100644 --- a/examples/funcgraph_example.txt +++ b/examples/funcgraph_example.txt @@ -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"): @@ -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. diff --git a/examples/funcslower_example.txt b/examples/funcslower_example.txt index 5d284b1..9955c7e 100644 --- a/examples/funcslower_example.txt +++ b/examples/funcslower_example.txt @@ -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 @@ -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. diff --git a/examples/functrace_example.txt b/examples/functrace_example.txt index 33f7bd9..5a2f9b9 100644 --- a/examples/functrace_example.txt +++ b/examples/functrace_example.txt @@ -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: @@ -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. diff --git a/examples/iolatency_example.txt b/examples/iolatency_example.txt index fb7b042..9950da7 100644 --- a/examples/iolatency_example.txt +++ b/examples/iolatency_example.txt @@ -1,5 +1,6 @@ Demonstrations of iolatency, the Linux ftrace version. + Here's a busy system doing over 4k disk IOPS: # ./iolatency @@ -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. diff --git a/examples/iosnoop_example.txt b/examples/iosnoop_example.txt index 61083dd..0f7b076 100644 --- a/examples/iosnoop_example.txt +++ b/examples/iosnoop_example.txt @@ -1,5 +1,6 @@ Demonstrations of iosnoop, the Linux ftrace version. + Here's Linux 3.16, tracing tar archiving a filesystem: # ./iosnoop @@ -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. diff --git a/examples/kprobe_example.txt b/examples/kprobe_example.txt index 2692ea7..f37e2f2 100644 --- a/examples/kprobe_example.txt +++ b/examples/kprobe_example.txt @@ -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 @@ -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. diff --git a/examples/opensnoop_example.txt b/examples/opensnoop_example.txt index 193663d..afa54fa 100644 --- a/examples/opensnoop_example.txt +++ b/examples/opensnoop_example.txt @@ -1,5 +1,6 @@ Demonstrations of opensnoop, the Linux ftrace version. + # ./opensnoop Tracing open()s. Ctrl-C to end. COMM PID FD FILE @@ -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. diff --git a/examples/perf-stat-hist_example.txt b/examples/perf-stat-hist_example.txt index a231e9c..1484375 100644 --- a/examples/perf-stat-hist_example.txt +++ b/examples/perf-stat-hist_example.txt @@ -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: @@ -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. diff --git a/examples/reset-ftrace_example.txt b/examples/reset-ftrace_example.txt index fbe680e..a531338 100644 --- a/examples/reset-ftrace_example.txt +++ b/examples/reset-ftrace_example.txt @@ -1,5 +1,6 @@ Demonstrations of reset-ftrace, the Linux ftrace tool. + You will probably never need this tool. If you kill -9 an ftrace-based tool, leaving the kernel in a tracing enabled state, you could try using this tool to reset ftrace and disable tracing. Make sure no other ftrace sessions are @@ -74,3 +75,14 @@ Note that reset-ftrace currently only resets a few methods of enabling tracing, such as set_ftrace_filter and kprobe_events. Static tracepoints could be enabled individually, and this script currently doesn't find and disable those. + + +Use -h to print the USAGE message: + +# ./reset-ftrace -h +USAGE: reset-ftrace [-fhq] + -f # force: delete ftrace lock file + -q # quiet: reset, but say nothing + -h # this usage message + eg, + reset-ftrace # disable active ftrace session diff --git a/examples/syscount_example.txt b/examples/syscount_example.txt index 15aa6e5..854b18a 100644 --- a/examples/syscount_example.txt +++ b/examples/syscount_example.txt @@ -273,3 +273,25 @@ getdents 4351 write 25482 So the most frequent syscall by PID 7979 was write(). + + +Use -h to print the USAGE message: + +# ./syscount -h +USAGE: syscount [-chv] [-t top] {-p PID|-d seconds|command} + syscount # count by process name + -c # show counts by syscall name + -h # this usage message + -v # verbose: shows PID + -p PID # trace this PID only + -d seconds # duration of trace + -t num # show top number only + command # run and trace this command + eg, + syscount # syscalls by process name + syscount -c # syscalls by syscall name + syscount -d 5 # trace for 5 seconds + syscount -cp 923 # syscall names for PID 923 + syscount -c ls # syscall names for "ls" + +See the man page and example file for more info. diff --git a/examples/tpoint_example.txt b/examples/tpoint_example.txt index 27be53b..7dba97c 100644 --- a/examples/tpoint_example.txt +++ b/examples/tpoint_example.txt @@ -1,5 +1,6 @@ Demonstrations of tpoint, the Linux ftrace version. + Let's trace block:block_rq_issue, to see block device (disk) I/O requests: # ./tpoint block:block_rq_issue @@ -178,3 +179,31 @@ making it a read: => SyS_read => system_call_fastpath [...] + + +Use -h to print the USAGE message: + +# ./tpoint -h +USAGE: tpoint [-hHsv] [-d secs] [-p PID] tracepoint [filter] + tpoint -l + -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 + -l # list all tracepoints + -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, + tpoint -l | grep open + # find tracepoints containing "open" + tpoint syscalls:sys_enter_open + # trace open() syscall entry + tpoint block:block_rq_issue + # trace block I/O issue + tpoint -s block:black_rq_issue + # show kernel stacks + +See the man page and example file for more info. diff --git a/execsnoop b/execsnoop index 0e190a3..5b3f38b 100755 --- a/execsnoop +++ b/execsnoop @@ -74,6 +74,8 @@ function usage { 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. END exit } diff --git a/kernel/funccount b/kernel/funccount index b10512d..b02ed99 100755 --- a/kernel/funccount +++ b/kernel/funccount @@ -59,6 +59,8 @@ function usage { 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. END exit } diff --git a/kernel/funcslower b/kernel/funcslower index 49ec021..d229af5 100755 --- a/kernel/funcslower +++ b/kernel/funcslower @@ -70,6 +70,8 @@ function usage { -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. END exit } diff --git a/kernel/functrace b/kernel/functrace index 71b3832..3abf4a0 100755 --- a/kernel/functrace +++ b/kernel/functrace @@ -75,6 +75,8 @@ function usage { 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. END exit } diff --git a/misc/perf-stat-hist b/misc/perf-stat-hist index 503b5fe..0ec82a1 100755 --- a/misc/perf-stat-hist +++ b/misc/perf-stat-hist @@ -8,8 +8,6 @@ # # USAGE: perf-stat-hist [-h] [-b buckets|-P power] [-m max] tracepoint # variable [seconds] -# eg, -# ./perf-stat-hist syscalls:sys_enter_read count 10 # # Run "perf-stat-hist -h" for full usage. # @@ -67,6 +65,8 @@ function usage { # ... 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. END exit } diff --git a/opensnoop b/opensnoop index 4023b1b..c456477 100755 --- a/opensnoop +++ b/opensnoop @@ -68,6 +68,8 @@ function usage { 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. END exit } diff --git a/syscount b/syscount index 7ee2432..ab9c4bd 100755 --- a/syscount +++ b/syscount @@ -59,7 +59,6 @@ trap '' INT QUIT TERM PIPE HUP stdout_workaround=1 # needed for older perf versions write_workaround=1 # needed for perf versions that trace their own writes -ulimit -n 32768 # often needed ### parse options while getopts cd:hp:t:v opt @@ -86,6 +85,8 @@ do syscount -d 5 # trace for 5 seconds syscount -cp 923 # syscall names for PID 923 syscount -c ls # syscall names for "ls" + + See the man page and example file for more info. END exit 1 esac @@ -120,6 +121,8 @@ fi echo "Tracing.$ttext.. Ctrl-C to end." (( stdout_workaround )) && opts="-o /dev/stdout" +ulimit -n 32768 # often needed + ### execute syscall name mode if (( opt_count && ! opt_verbose )); then : ${cmd:=sleep 999999}