From 5e4e1f46c5af5eece661816e8082d0078ad6893a Mon Sep 17 00:00:00 2001 From: Sasha Goldshtein Date: Fri, 12 Feb 2016 06:52:19 -0800 Subject: [PATCH] Updated man and examples with new probe syntax and command-line switches --- README.md | 2 +- man/man8/argdist.8 | 67 ++++---- tools/argdist.py | 10 ++ ...gdist_example.txt => argdist_examples.txt} | 146 +++++++++++------- 4 files changed, 136 insertions(+), 89 deletions(-) rename tools/{argdist_example.txt => argdist_examples.txt} (67%) diff --git a/README.md b/README.md index c41cb90f4cad..c4fcdfefcb3b 100644 --- a/README.md +++ b/README.md @@ -65,6 +65,7 @@ Examples: Tools: +- tools/[argdist](tools/argdist.py): Display function parameter values as a histogram or frequency count. [Examples](tools/argdist_example.txt). - tools/[bashreadline](tools/bashreadline.py): Print entered bash commands system wide. [Examples](tools/bashreadline_example.txt). - tools/[biolatency](tools/biolatency.py): Summarize block device I/O latency as a histogram. [Examples](tools/biolatency_example.txt). - tools/[biotop](tools/biotop.py): Top for disks: Summarize block device I/O by process. [Examples](tools/biotop_example.txt). @@ -79,7 +80,6 @@ Tools: - tools/[filetop](tools/filetop.py): File reads and writes by filename and process. Top for files. [Examples](tools/filetop_example.txt). - tools/[funccount](tools/funccount.py): Count kernel function calls. [Examples](tools/funccount_example.txt). - tools/[funclatency](tools/funclatency.py): Time kernel functions and show their latency distribution. [Examples](tools/funclatency_example.txt). -- tools/[gentrace](tools/gentrace.py): Trace function parameter values as a histogram or raw data. [Examples](tools/gentrace_examples.txt). - tools/[gethostlatency](tools/gethostlatency.py): Show latency for getaddrinfo/gethostbyname[2] calls. [Examples](tools/gethostlatency_example.txt). - tools/[hardirqs](tools/hardirqs.py): Measure hard IRQ (hard interrupt) event time. [Examples](tools/hardirqs_example.txt). - tools/[killsnoop](tools/killsnoop.py): Trace signals issued by the kill() syscall. [Examples](tools/killsnoop_example.txt). diff --git a/man/man8/argdist.8 b/man/man8/argdist.8 index e92756ab2bea..2f745978bfbb 100644 --- a/man/man8/argdist.8 +++ b/man/man8/argdist.8 @@ -1,11 +1,11 @@ -.TH gentrace 8 "2016-02-11" "USER COMMANDS" +.TH argdist 8 "2016-02-11" "USER COMMANDS" .SH NAME -gentrace \- Trace a function and display a histogram or summary of its parameter values. Uses Linux eBPF/bcc. +argdist \- Trace a function and display a histogram or frequency count of its parameter values. Uses Linux eBPF/bcc. .SH SYNOPSIS -.B gentrace [-h] [-p PID] [-z STRING_SIZE] [-i INTERVAL] [-c COUNT] specifier [specifier ...] +.B argdist [-h] [-p PID] [-z STRING_SIZE] [-i INTERVAL] [-n COUNT] [-H specifier [specifier ...]] [-C specifier [specifier ...]] .SH DESCRIPTION -gentrace attaches to function entry and exit points, collects specified parameter -values, and stores them in a histogram or a raw counting collection that counts +argdist attaches to function entry and exit points, collects specified parameter +values, and stores them in a histogram or a frequency collection that counts the number of times a parameter value occurred. It can also filter parameter values and instrument multiple entry points at once. @@ -18,8 +18,7 @@ CONFIG_BPF and bcc. Print usage message. .TP \-p PID -Trace only functions in the process PID. This filter will only apply to user-space -functions. If you only provide kernel-space probes, the filter is ignored. +Trace only functions in the process PID. .TP \-z STRING_SIZE When collecting string arguments (of type char*), collect up to STRING_SIZE @@ -28,88 +27,98 @@ characters. Longer strings will be truncated. -i INTERVAL Print the collected data every INTERVAL seconds. The default is 1 second. .TP --c COUNT +-n NUMBER Print the collected data COUNT times and then exit. .TP -SPECIFIER -One or more probe specifications that instruct gentrace which functions to +-H SPECIFIER, -C SPECIFIER +One or more probe specifications that instruct argdist which functions to probe, which parameters to collect, how to aggregate them, and whether to perform any filtering. See SPECIFIER SYNTAX below. .SH SPECIFIER SYNTAX The general specifier syntax is as follows: -.B [-ret]:[library]:function(signature)[:type:expr[:filter]] +.B {p,r}:[library]:function(signature)[:type:expr[:filter]][;label] .TP -Probe type \- "raw", "hist", "raw-ret", "hist-ret". -Indicates where to place the probe and whether the probe should collect raw -event information, or aggregate the collected values into a histogram. Raw +.B {p,r} +Probe type \- "p" for function entry, "r" for function return; +\-H for histogram collection, \-C for frequency count. +Indicates where to place the probe and whether the probe should collect frequency +count information, or aggregate the collected values into a histogram. Counting probes will collect the number of times every parameter value was observed, whereas histogram probes will collect the parameter values into a histogram. Only integral types can be used with histogram probes; there is no such limitation -for raw probes. Suffix with \-ret to indicate that the probe should be placed -at function return. This probe can only use the pseudo-variable @retval, which +for counting probes. Return probes can only use the pseudo-variable $retval, which is an alias for the function's return value. .TP +.B [library] Library containing the probe. Specify the full path to the .so or executable file where the function to probe resides. Alternatively, you can specify just the lib name: for example, "c" refers to libc. If no library name is specified, the kernel is assumed. .TP +.B function(signature) The function to probe, and its signature. The function name must match exactly for the probe to be placed. The signature, on the other hand, is only required if you plan to collect parameter values based on that signature. For example, if you only want to collect the first parameter, you don't have to specify the rest of the parameters in the signature. .TP +.B [type] The type of the expression to capture. This is the type of the keys in the histogram or raw event collection that are collected by the probes. .TP +.B [expr] The expression to capture. These are the values that are assigned to the histogram or raw event collection. You may use the parameters directly, or valid C expressions that involve the parameters, such as "size % 10". .TP -A filter applied to the captured data. +.B [filter] +The filter applied to the captured data. Only parameter values that pass the filter will be collected. This is any valid C expression that refers to the parameter values, such as "fd == 1 && length > 16". +.TP +.B [label] +The label that will be displayed when printing the probed values. By default, +this is the probe specifier. .SH EXAMPLES .TP Print a histogram of allocation sizes passed to kmalloc: # -.B gentrace.py 'hist::__kmalloc(u64 size):u64:size' +.B argdist.py -H 'p::__kmalloc(u64 size):u64:size' .TP -Print a raw count of how many times process 1005 called malloc with an allocation size of 16 bytes: +Print a count of how many times process 1005 called malloc with an allocation size of 16 bytes: # -.B gentrace.py -p 1005 'raw:c:malloc(size_t size):size_t:size:size==16' +.B argdist.py -p 1005 -C 'p:c:malloc(size_t size):size_t:size:size==16' .TP Snoop on all strings returned by gets(): # -.B gentrace.py 'raw-ret:c:gets():char*:@retval' +.B argdist.py -C 'r:c:gets():char*:$retval' .TP -Print raw counts of how many times writes were issued to a particular file descriptor number, in process 1005: +Print frequency counts of how many times writes were issued to a particular file descriptor number, in process 1005: # -.B gentrace.py -p 1005 'raw:c:write(int fd):int:fd' +.B argdist.py -p 1005 -C 'p:c:write(int fd):int:fd' .TP Print a histogram of error codes returned by read() in process 1005: # -.B gentrace.py -p 1005 'hist-ret:c:read()' +.B argdist.py -p 1005 -H 'r:c:read()' .TP Print a histogram of buffer sizes passed to write() across all processes, where the file descriptor was 1 (STDOUT): # -.B gentrace.py 'hist:c:write(int fd, const void *buf, size_t count):size_t:count:fd==1' +.B argdist.py -H 'p:c:write(int fd, const void *buf, size_t count):size_t:count:fd==1' .TP -Count fork() calls in libc across all processes: +Count fork() calls in libc across all processes, grouped by pid: # -.B gentrace.py 'raw:c:fork' +.B argdist.py -C 'p:c:fork():int:$PID;fork per process' .TP Print histograms of sleep() and nanosleep() parameter values: # -.B gentrace.py 'hist:c:sleep(u32 seconds):u32:seconds' 'hist:c:nanosleep(struct timespec { time_t tv_sec; long tv_nsec; } *req):long:req->tv_nsec' +.B argdist.py -H 'p:c:sleep(u32 seconds):u32:seconds' -H 'p:c:nanosleep(struct timespec { time_t tv_sec; long tv_nsec; } *req):long:req->tv_nsec' .TP Spy on writes to STDOUT performed by process 2780, up to a string size of 120 characters: # -.B gentrace.py -p 2780 -z 120 'raw:c:write(int fd, char* buf, size_t len):char*:buf:fd==1' +.B argdist.py -p 2780 -z 120 -C 'p:c:write(int fd, char* buf, size_t len):char*:buf:fd==1' .SH SOURCE This is from bcc. .IP diff --git a/tools/argdist.py b/tools/argdist.py index baecff79c133..efe3a31fd16e 100755 --- a/tools/argdist.py +++ b/tools/argdist.py @@ -28,6 +28,14 @@ class Specifier(object): } """ next_probe_index = 0 + aliases = { "$PID": "bpf_get_current_pid_tgid()" } + + def _substitute_aliases(self, expr): + if expr is None: + return expr + for alias, subst in Specifier.aliases.items(): + expr = expr.replace(alias, subst) + return expr def __init__(self, type, specifier, pid): self.raw_spec = specifier @@ -66,6 +74,8 @@ def __init__(self, type, specifier, pid): if self.filter is not None: self.filter = self.filter.replace("$retval", "(%s)ctx->ax" % self.expr_type) + self.expr = self._substitute_aliases(self.expr) + self.filter = self._substitute_aliases(self.filter) self.pid = pid self.probe_func_name = "%s_probe%d" % \ (self.function, Specifier.next_probe_index) diff --git a/tools/argdist_example.txt b/tools/argdist_examples.txt similarity index 67% rename from tools/argdist_example.txt rename to tools/argdist_examples.txt index dc30b79f536b..46cb8d925c24 100644 --- a/tools/argdist_example.txt +++ b/tools/argdist_examples.txt @@ -1,36 +1,36 @@ -Demonstrations of gentrace. +Demonstrations of argdist. -gentrace probes functions you specify and collects parameter values into a -histogram or a counting table. This can be used to understand the distribution +argdist probes functions you specify and collects parameter values into a +histogram or a frequency count. This can be used to understand the distribution of values a certain parameter takes, filter and print interesting parameters -without attaching a debugger, and getting general execution statistics on +without attaching a debugger, and obtain general execution statistics on various functions. For example, suppose you want to find what allocation sizes are common in your application: -# ./gentrace.py -p 2420 "raw:c:malloc(size_t size):size_t:size" +# ./argdist.py -p 2420 -C 'p:c:malloc(size_t size):size_t:size' [01:42:29] -raw:c:malloc(size_t size):size_t:size +p:c:malloc(size_t size):size_t:size COUNT EVENT [01:42:30] -raw:c:malloc(size_t size):size_t:size +p:c:malloc(size_t size):size_t:size COUNT EVENT [01:42:31] -raw:c:malloc(size_t size):size_t:size +p:c:malloc(size_t size):size_t:size COUNT EVENT 1 size = 16 [01:42:32] -raw:c:malloc(size_t size):size_t:size +p:c:malloc(size_t size):size_t:size COUNT EVENT 2 size = 16 [01:42:33] -raw:c:malloc(size_t size):size_t:size +p:c:malloc(size_t size):size_t:size COUNT EVENT 3 size = 16 [01:42:34] -raw:c:malloc(size_t size):size_t:size +p:c:malloc(size_t size):size_t:size COUNT EVENT 4 size = 16 ^C @@ -43,9 +43,9 @@ probed and its value was 16, repeatedly. Now, suppose you wanted a histogram of buffer sizes passed to the write() function across the system: -# ./gentrace.py "hist:c:write(int fd, void *buf, size_t len):size_t:len" +# ./argdist.py -H 'p:c:write(int fd, void *buf, size_t len):size_t:len' [01:45:22] -hist:c:write(int fd, void *buf, size_t len):size_t:len +p:c:write(int fd, void *buf, size_t len):size_t:len len : count distribution 0 -> 1 : 0 | | 2 -> 3 : 2 |************* | @@ -54,7 +54,7 @@ hist:c:write(int fd, void *buf, size_t len):size_t:len 16 -> 31 : 0 | | 32 -> 63 : 6 |****************************************| [01:45:23] -hist:c:write(int fd, void *buf, size_t len):size_t:len +p:c:write(int fd, void *buf, size_t len):size_t:len len : count distribution 0 -> 1 : 0 | | 2 -> 3 : 11 |*************** | @@ -64,7 +64,7 @@ hist:c:write(int fd, void *buf, size_t len):size_t:len 32 -> 63 : 28 |****************************************| 64 -> 127 : 12 |***************** | [01:45:24] -hist:c:write(int fd, void *buf, size_t len):size_t:len +p:c:write(int fd, void *buf, size_t len):size_t:len len : count distribution 0 -> 1 : 0 | | 2 -> 3 : 21 |**************** | @@ -81,9 +81,9 @@ bytes, medium writes of 32-63 bytes, and larger writes of 64-127 bytes. But these are writes across the board -- what if you wanted to focus on writes to STDOUT? -# ./gentrace.py "hist:c:write(int fd, void *buf, size_t len):size_t:len:fd==1" +# ./argdist.py -H 'p:c:write(int fd, void *buf, size_t len):size_t:len:fd==1' [01:47:17] -hist:c:write(int fd, void *buf, size_t len):size_t:len:fd==1 +p:c:write(int fd, void *buf, size_t len):size_t:len:fd==1 len : count distribution 0 -> 1 : 0 | | 2 -> 3 : 0 | | @@ -92,7 +92,7 @@ hist:c:write(int fd, void *buf, size_t len):size_t:len:fd==1 16 -> 31 : 0 | | 32 -> 63 : 1 |****************************************| [01:47:18] -hist:c:write(int fd, void *buf, size_t len):size_t:len:fd==1 +p:c:write(int fd, void *buf, size_t len):size_t:len:fd==1 len : count distribution 0 -> 1 : 0 | | 2 -> 3 : 0 | | @@ -102,7 +102,7 @@ hist:c:write(int fd, void *buf, size_t len):size_t:len:fd==1 32 -> 63 : 3 |******************** | 64 -> 127 : 6 |****************************************| [01:47:19] -hist:c:write(int fd, void *buf, size_t len):size_t:len:fd==1 +p:c:write(int fd, void *buf, size_t len):size_t:len:fd==1 len : count distribution 0 -> 1 : 0 | | 2 -> 3 : 0 | | @@ -116,20 +116,20 @@ hist:c:write(int fd, void *buf, size_t len):size_t:len:fd==1 The "fd==1" part is a filter that is applied to every invocation of write(). Only if the filter condition is true, the value is recorded. -You can also use gentrace to trace kernel functions. For example, suppose you +You can also use argdist to trace kernel functions. For example, suppose you wanted a histogram of kernel allocation (kmalloc) sizes across the system, printed twice with 3 second intervals: -# ./gentrace.py -i 3 -c 2 "hist::__kmalloc(size_t size):size_t:size" +# ./argdist.py -i 3 -n 2 -H 'p::__kmalloc(size_t size):size_t:size' [01:50:00] -hist::__kmalloc(size_t size):size_t:size +p::__kmalloc(size_t size):size_t:size size : count distribution 0 -> 1 : 0 | | 2 -> 3 : 0 | | 4 -> 7 : 0 | | 8 -> 15 : 6 |****************************************| [01:50:03] -hist::__kmalloc(size_t size):size_t:size +p::__kmalloc(size_t size):size_t:size size : count distribution 0 -> 1 : 0 | | 2 -> 3 : 0 | | @@ -143,9 +143,9 @@ hist::__kmalloc(size_t size):size_t:size Occasionally, numeric information isn't enough and you want to capture strings. What are the strings printed by puts() across the system? -# ./gentrace.py -i 10 -c 1 "raw:c:puts(char *str):char*:str" +# ./argdist.py -i 10 -n 1 -C 'p:c:puts(char *str):char*:str' [01:53:54] -raw:c:puts(char *str):char*:str +p:c:puts(char *str):char*:str COUNT EVENT 2 str = Press ENTER to start. @@ -153,22 +153,23 @@ It looks like the message "Press ENTER to start." was printed twice during the 10 seconds we were tracing. What about reads? You could trace gets() across the system and print the -strings input by the user: +strings input by the user (note how "r" is used instead of "p" to attach a +probe to the function's return): -# ./gentrace.py -i 10 -c 1 "raw-ret:c:gets():char*:@retval" +# ./argdist.py -i 10 -n 1 -C 'r:c:gets():char*:$retval:$retval!=0' [02:12:23] -raw-ret:c:gets():char*:@retval +r:c:gets():char*:$retval:$retval!=0 COUNT EVENT 1 (char*)ctx->ax = hi there - 1 (char*)ctx->ax = sasha - 1 (char*)ctx->ax = hello + 3 (char*)ctx->ax = sasha + 8 (char*)ctx->ax = hello Similarly, we could get a histogram of the error codes returned by read(): -# ./gentrace.py -i 10 -c 1 "hist-ret:c:read()" +# ./argdist.py -i 10 -c 1 -H 'r:c:read()' [02:15:36] -hist-ret:c:read() - (int)ctx->ax : count distribution +r:c:read() + retval : count distribution 0 -> 1 : 29 |****************************************| 2 -> 3 : 11 |*************** | 4 -> 7 : 0 | | @@ -182,18 +183,35 @@ hist-ret:c:read() 1024 -> 2047 : 0 | | 2048 -> 4095 : 2 |** | +Here's a final example that finds how many write() system calls are performed +by each process on the system: + +# argdist.py -C 'p:c:write():int:$PID;write per process' -n 2 +[06:47:18] +write by process + COUNT EVENT + 3 bpf_get_current_pid_tgid() = 8889 + 7 bpf_get_current_pid_tgid() = 7615 + 7 bpf_get_current_pid_tgid() = 2480 +[06:47:19] +write by process + COUNT EVENT + 9 bpf_get_current_pid_tgid() = 8889 + 23 bpf_get_current_pid_tgid() = 7615 + 23 bpf_get_current_pid_tgid() = 2480 + +As you see, the $PID alias is expanded to the BPF function bpf_get_current_pid_tgid(), +which returns the current process' pid. + USAGE message: -# ./gentrace.py -h -usage: gentrace.py [-h] [-p PID] [-z STRING_SIZE] [-i INTERVAL] [-c COUNT] - specifier [specifier ...] +usage: argdist.py [-h] [-p PID] [-z STRING_SIZE] [-i INTERVAL] [-n COUNT] + [-H [HISTSPECIFIER [HISTSPECIFIER ...]]] + [-C [COUNTSPECIFIER [COUNTSPECIFIER ...]]] [-v] Trace a function and display a summary of its parameter values. -positional arguments: - specifier the probe specifiers (see examples below) - optional arguments: -h, --help show this help message and exit -p PID, --pid PID id of the process to trace (optional) @@ -201,55 +219,65 @@ optional arguments: maximum string size to read from char* arguments -i INTERVAL, --interval INTERVAL output interval, in seconds - -c COUNT, --count COUNT + -n COUNT, --number COUNT number of outputs + -H [HISTSPECIFIER [HISTSPECIFIER ...]], --histogram [HISTSPECIFIER [HISTSPECIFIER ...]] + probe specifier to capture histogram of (see examples + below) + -C [COUNTSPECIFIER [COUNTSPECIFIER ...]], --count [COUNTSPECIFIER [COUNTSPECIFIER ...]] + probe specifier to capture count of (see examples + below) + -v, --verbose print resulting BPF program code before executing Probe specifier syntax: - [-ret]:[library]:function(signature)[:type:expr[:filter]] + {p,r}:[library]:function(signature)[:type:expr[:filter]][;label] Where: - -- collect raw data or a histogram of values - ret -- probe at function exit, only @retval is accessible + p,r -- probe at function entry or at function exit + in exit probes, only $retval is accessible library -- the library that contains the function (leave empty for kernel functions) function -- the function name to trace signature -- the function's parameters, as in the C header type -- the type of the expression to collect expr -- the expression to collect - filter -- a filter that is applied to collected values + filter -- the filter that is applied to collected values + label -- the label for this probe in the resulting output EXAMPLES: -gentrace.py "hist::__kmalloc(u64 size):u64:size" +argdist.py -H 'p::__kmalloc(u64 size):u64:size' Print a histogram of allocation sizes passed to kmalloc -gentrace.py -p 1005 "raw:c:malloc(size_t size):size_t:size:size==16" - Print a raw count of how many times process 1005 called malloc with - an allocation size of 16 bytes +argdist.py -p 1005 -C 'p:c:malloc(size_t size):size_t:size:size==16' + Print a frequency count of how many times process 1005 called malloc + with an allocation size of 16 bytes -gentrace.py "raw-ret:c:gets():char*:@retval" +argdist.py -C 'r:c:gets():char*:$retval;snooped strings' Snoop on all strings returned by gets() -gentrace.py -p 1005 "raw:c:write(int fd):int:fd" - Print raw counts of how many times writes were issued to a particular - file descriptor number, in process 1005 +argdist.py -p 1005 -C 'p:c:write(int fd):int:fd' + Print frequency counts of how many times writes were issued to a + particular file descriptor number, in process 1005 -gentrace.py -p 1005 "hist-ret:c:read()" +argdist.py -p 1005 -H 'r:c:read()' Print a histogram of error codes returned by read() in process 1005 -gentrace.py "hist:c:write(int fd, const void *buf, size_t count):size_t:count:fd==1" +argdist.py -H \ + 'p:c:write(int fd, const void *buf, size_t count):size_t:count:fd==1' Print a histogram of buffer sizes passed to write() across all processes, where the file descriptor was 1 (STDOUT) -gentrace.py "raw:c:fork" +argdist.py -C 'p:c:fork();fork calls' Count fork() calls in libc across all processes Can also use funccount.py, which is easier and more flexible -gentrace.py \ - "hist:c:sleep(u32 seconds):u32:seconds" \ - "hist:c:nanosleep(struct timespec { time_t tv_sec; long tv_nsec; } *req):long:req->tv_nsec" +argdist.py \ + -H 'p:c:sleep(u32 seconds):u32:seconds' \ + -H 'p:c:nanosleep(struct timespec { time_t tv_sec; long tv_nsec; } *req):long:req->tv_nsec' Print histograms of sleep() and nanosleep() parameter values -gentrace.py -p 2780 -z 120 "raw:c:write(int fd, char* buf, size_t len):char*:buf:fd==1" +argdist.py -p 2780 -z 120 \ + -C 'p:c:write(int fd, char* buf, size_t len):char*:buf:fd==1' Spy on writes to STDOUT performed by process 2780, up to a string size of 120 characters