diff --git a/README.markdown b/README.markdown index 6969a0f..72823ac 100644 --- a/README.markdown +++ b/README.markdown @@ -20,6 +20,7 @@ Table of Contents * [Shorthands](#shorthands) * [@pfunc(FUNCTION)](#pfuncfunction) * [Samples](#samples) + * [file-io-blocking](#file-io-blocking) * [ngx-rps](#ngx-rps) * [ngx-req-latency-distr](#ngx-req-latency-distr) * [ctx-switches](#ctx-switches) @@ -238,6 +239,61 @@ Samples [Back to TOC](#table-of-contents) +file-io-blocking +---------------- + +Calculates the distribution of the file IO operation blocking latencies. +The file IO operations include: `syscall.lseek`, `syscall.renameat`, +`syscall.open`, `syscall.close`, `syscall.sendfile*`, `vfs.read*`, +`vfs.write*`, `syscall.*stat*`, `syscall.unlink`, `syscall.mkdir`, +`syscall.rmdir`. + + # making the ./stap++ tool visible in PATH: + $ export PATH=$PWD:$PATH + + $ ./samples/file-io-blocking.sxx -x 7367 + WARNING: Start tracing process 7367 (/path/to/some/program)... + Hit Ctrl-C to end. + ^C + Distribution of file IO blocking latencies (in microseconds) + pid 7367: + max/avg/min: 15412/8/0 + value |-------------------------------------------------- count + 0 | 60 + 1 |@ 920 + 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 30009 + 4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 30862 + 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 25383 + 16 |@@@@@@@@@@@@@@@ 9384 + 32 |@ 965 + 64 | 115 + 128 | 2 + 256 | 0 + 512 | 0 + 1024 | 1 + 2048 | 0 + 4096 | 0 + 8192 | 2 + 16384 | 0 + 32768 | 0 + +Also we can use `-m xxxx` to specify the Nginx master process id, +then it will monitor all of the Nginx worker processes. For example: + +```shell +# making the ./stap++ tool visible in PATH: +$ ps -ef | grep nginx +resty 70084 1 0 Mar10 ? 00:00:00 nginx: master process nginx +resty 70085 70084 0 Mar10 ? 00:00:06 nginx: worker process +resty 70086 70084 0 Mar10 ? 00:00:06 nginx: worker process +$ ./samples/file-io-blocking.sxx -m 70084 --arg time=20 +``` + +We can also see from the example above that we can limit the sampling period by +specifying the `--arg time=SECONDS` option. + +[Back to TOC](#table-of-contents) + ngx-rps ------- @@ -274,58 +330,58 @@ Nginx worker process at real time: # making the ./stap++ tool visible in PATH: $ export PATH=$PWD:$PATH - $ ./samples/ngx-req-latency-distr.sxx -x 28078 - WARNING: Start tracing process 28078 (/path/to/some/program)... + $ ./samples/ngx-req-latency-distr.sxx -x 28574 + Start tracing process (28574) (/usr/local/openresty/nginx/sbin/nginx)... + Hit Ctrl-C to end. ^C - Distribution of the main request latencies (in microseconds) - (min/avg/max: 92/242181/42808832) - value |-------------------------------------------------- count - 16 | 0 - 32 | 0 - 64 | 8 - 128 | 1 - 256 | 3 - 512 |@@@@@ 274 - 1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2474 - 2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1547 - 4096 |@@@@@@@@@@@@@@@@@@@ 952 - 8192 |@@@@@@@@@@ 500 - 16384 |@@@@@@@ 359 - 32768 |@@@@@@@@ 414 - 65536 |@@@@@@@@@@@@ 644 - 131072 |@@@@@@@@@@@@@@@@@ 851 - 262144 |@@@@@@@@@@@@ 614 - 524288 |@@@@@@ 334 - 1048576 |@@ 147 - 2097152 | 46 - 4194304 | 24 - 8388608 |@ 64 - 16777216 | 1 - 33554432 | 1 - 67108864 | 0 - 134217728 | 0 - -One can also filter out requests by a specified request method name via the `--arg method=METHOD` option. For instance, - - $ ./samples/ngx-req-latency-distr.sxx -x 5447 --arg method=POST --arg time=60 - Start tracing process 5447 (/opt/nginx/sbin/nginx)... - Please wait for 60 seconds... - (Tracing only POST request methods) - - Distribution of the main request latencies (in microseconds) for 52 samples: - (min/avg/max: 1167/8373/28281) + Distribution of the request latencies (in microseconds) for 24304 samples: + (pid: 28574 min/avg/max: 25/118/12426) value |-------------------------------------------------- count - 256 | 0 - 512 | 0 - 1024 |@@ 2 - 2048 |@@@@@@@@ 8 - 4096 |@@@@@@@@@@@@@@@@@@@@@@@ 23 - 8192 |@@@@@@@@@@@@@@ 14 - 16384 |@@@@@ 5 - 32768 | 0 - 65536 | 0 + 4 | 0 + 8 | 0 + 16 | 4 + 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 14054 + 64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 9552 + 128 |@ 431 + 256 | 27 + 512 | 5 + 1024 | 28 + 2048 | 51 + 4096 | 97 + 8192 | 55 + 16384 | 0 + 32768 | 0 + + + Distribution of latencies between different requests (in microseconds) for 24303 samples: + (pid: 28574 min/avg/max: 4/87/3722) + value |-------------------------------------------------- count + 1 | 0 + 2 | 0 + 4 | 136 + 8 | 104 + 16 | 74 + 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 8065 + 64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 13463 + 128 |@@@@@@@@ 2269 + 256 | 174 + 512 | 7 + 1024 | 2 + 2048 | 9 + 4096 | 0 + 8192 | 0 + +* `--arg method=METHOD`: filter requests by a specified request method name. +* `--arg uri=URI`: filter requests by a specified request uri. +* `--arg time=SECONDS`: limit the sampling period. +* `-m xxxx`: monitor all of the Nginx worker processes by a specified Nginx master process. -We can also see from the example above that we can limit the sampling period by specifying the `--arg time=SECONDS` option. +For instance, + + $ ./samples/ngx-req-latency-distr.sxx -m 28573 --arg time=20 --arg uri=/test --arg method=GET + Start tracing process (28574 28575 28577) (/usr/local/openresty/nginx/sbin/nginx)... + Please wait for 20 seconds... + ...... [Back to TOC](#table-of-contents) diff --git a/samples/file-io-blocking.sxx b/samples/file-io-blocking.sxx new file mode 100755 index 0000000..77c085b --- /dev/null +++ b/samples/file-io-blocking.sxx @@ -0,0 +1,56 @@ +#!/usr/bin/env stap++ + +# Measure the distribution of the VFS read/write latency. + +global begin, stats, found + +probe syscall.lseek, syscall.renameat, syscall.open, syscall.close, + syscall.sendfile*, vfs.read*, vfs.write*, syscall.*stat*, + syscall.unlink, syscall.mkdir, syscall.rmdir +{ + if ($^pid_ok) { + begin[pid()] = gettimeofday_us() + } +} + +probe syscall.lseek.return, syscall.renameat.return, syscall.open.return, + syscall.close.return, syscall.sendfile*.return, vfs.read*.return, + vfs.write*.return, syscall.*stat*.return, syscall.unlink.return, + syscall.mkdir.return, syscall.rmdir.return +{ + if ($^pid_ok && begin[pid()] > 0) { + stats[pid()] <<< gettimeofday_us() - begin[pid()] + found = 1 + } +} + +%( "$^arg_time :default()" != "" %? +probe timer.s($^arg_time) { + exit() +} +%) + +probe end { + + if (!found) { + printf("No samples observed so far.\n"); + + } else { + printf("Distribution of file IO blocking latencies (in microseconds)\n") + + foreach (pid in stats) { + printf("pid %d:\n", pid) + printf("max/avg/min: %d/%d/%d\n", @max(stats[pid]), @avg(stats[pid]), @min(stats[pid])) + print(@hist_log(stats[pid])) + } + } +} + +probe begin { + printf("Start tracing ($^target) ($^exec_path)...\n") + %( "$^arg_time :default()" != "" %? + printf("Please wait for $^arg_time seconds...\n\n") + %: + printf("Hit Ctrl-C to end.\n\n") + %) +} diff --git a/samples/ngx-req-latency-distr.sxx b/samples/ngx-req-latency-distr.sxx index 1c68119..56c7ea8 100755 --- a/samples/ngx-req-latency-distr.sxx +++ b/samples/ngx-req-latency-distr.sxx @@ -1,72 +1,115 @@ #!/usr/bin/env stap++ -global begin_times -global latencies -global method_id - -probe @pfunc(ngx_http_handler) { - if (pid() == target() && $r == $r->main) { - if ("$^arg_method :default()" != "") { - if (method_id == 0) { - if ($r->method_name->len > 0) { - method = user_string_n($r->method_name->data, $r->method_name->len) - //printf("found method %s\n", method) - if (method == "$^arg_method") { - method_id = $r->method - //printf("found method id %d\n", method_id) - } +@use nginx.request + +global begin_times, pre_end_time +global latencies, req_latencies +global init_conns +global pid, matched_r, matched +global log_r + +probe @pfunc(ngx_http_create_request) +{ + if ($^pid_ok) { + init_conns[$c, pid()] = gettimeofday_us() + } +} + +probe @pfunc(ngx_http_close_connection) { + delete init_conns[$c, pid()] +} + +probe @pfunc(ngx_http_process_request) { + pid = pid() + + if ($^pid_ok) { + begin_time = init_conns[$r->connection, pid()] + if (begin_time) { + matched_r[$r] = 1 + %( "$^arg_uri :default()" == "" %? + %: + if (ngx_req_uri($r) != "$^arg_uri") { + delete matched_r[$r] } - } + %) - if (method_id && method_id == $r->method) { - begin_times[$r] = gettimeofday_us() - } + %( "$^arg_method :default()" == "" %? + %: + if (ngx_req_method($r) != "$^arg_method") { + delete matched_r[$r] + } + %) + + if (matched_r[$r]) { + begin_times[$r] = begin_time - } else { - begin_times[$r] = gettimeofday_us() + if (pre_end_time) { + req_latencies[pid] <<< begin_times[$r] - pre_end_time + pre_end_time = 0 + } + } } } } probe @pfunc(ngx_http_log_request) { - if (pid() == target()) { - begin = begin_times[$r] - if (begin) { - latencies <<< gettimeofday_us() - begin - delete begin_times[$r] + if ($^pid_ok && matched_r[$r]) { + log_r = $r + } +} + +probe @pfunc(ngx_http_log_request).return { + if ($^pid_ok && log_r) { + begin_time = begin_times[log_r] + if (begin_time) { + pre_end_time = gettimeofday_us() + latencies[pid()] <<< pre_end_time - begin_time + matched = 1 + delete begin_times[log_r] } + + delete matched_r[log_r] + log_r = 0 } } probe begin { - printf("Start tracing process %d ($^exec_path)...\n", target()) + printf("Start tracing process ($^target) ($^exec_path)...\n") %( "$^arg_time :default()" != "" %? printf("Please wait for $^arg_time seconds...\n") %: printf("Hit Ctrl-C to end.\n") %) - - if ("$^arg_method" != "") { - printf("(Tracing only $^arg_method request methods)\n") - } } -%( "$^arg_time" != "" %? +%( "$^arg_time :default()" != "" %? probe timer.s($^arg_time) { exit() } %) probe end { - count = @count(latencies) - if (count == 0) { + if (!matched) { printf("\nNo samples found so far.\n") } else { - printf("\nDistribution of the main request latencies (in microseconds) for %d samples:\n", - count) - printf("(min/avg/max: %d/%d/%d)\n", @min(latencies), @avg(latencies), - @max(latencies)) - print(@hist_log(latencies)) + + foreach(pid in latencies) { + count = @count(latencies[pid]) + printf("\nDistribution of the request latencies (in microseconds) for %d samples:\n", count) + printf("(pid: %d min/avg/max: %d/%d/%d)\n", pid, @min(latencies[pid]), @avg(latencies[pid]), + @max(latencies[pid])) + print(@hist_log(latencies[pid])) + print("\n") + } + + foreach(pid in req_latencies) { + count = @count(req_latencies[pid]) + printf("\nDistribution of latencies between different requests (in microseconds) for %d samples:\n", + count) + printf("(pid: %d min/avg/max: %d/%d/%d)\n", pid, @min(req_latencies[pid]), + @avg(req_latencies[pid]), @max(req_latencies[pid])) + print(@hist_log(req_latencies[pid])) + } } }