diff --git a/README.md b/README.md index e0256746aaa0..06f49de0f70e 100644 --- a/README.md +++ b/README.md @@ -64,7 +64,8 @@ Examples: - examples/tracing/[bitehist.py](examples/tracing/bitehist.py): Block I/O size histogram. [Examples](examples/tracing/bitehist_example.txt). - examples/tracing/[disksnoop.py](examples/tracing/disksnoop.py): Trace block device I/O latency. [Examples](examples/tracing/disksnoop_example.txt). - examples/[hello_world.py](examples/hello_world.py): Prints "Hello, World!" for new processes. -- examples/tracing/[nodejs_http_server.py](examples/tracing/nodejs_http_server.py): Trace Node.js HTTP server requests using USDT probes. +- examples/tracing/[mysqld_query.py](examples/tracing/mysqld_query.py): Trace MySQL server queries using USDT probes. [Examples](examples/tracing/mysqld_query_example.txt). +- examples/tracing/[nodejs_http_server.py](examples/tracing/nodejs_http_server.py): Trace Node.js HTTP server requests using USDT probes. [Examples](examples/tracing/nodejs_http_server_example.txt). - examples/tracing/[task_switch.py](examples/tracing/task_switch.py): Count task switches with from and to PIDs. - examples/tracing/[tcpv4connect.py](examples/tracing/tcpv4connect.py): Trace TCP IPv4 active connections. [Examples](examples/tracing/tcpv4connect_example.txt). - examples/tracing/[trace_fields.py](examples/tracing/trace_fields.py): Simple example of printing fields from traced events. @@ -98,6 +99,7 @@ Examples: - 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). - tools/[mdflush](tools/mdflush.py): Trace md flush events. [Examples](tools/mdflush_example.txt). +- tools/[mysqld_qslower](tools/mysqld_qslower.py): Trace MySQL server queries slower than a threshold. [Examples](tools/mysqld_qslower_example.txt). - tools/[memleak](tools/memleak.py): Display outstanding memory allocations to find memory leaks. [Examples](tools/memleak_example.txt). - tools/[offcputime](tools/offcputime.py): Summarize off-CPU time by kernel stack trace. [Examples](tools/offcputime_example.txt). - tools/[offwaketime](tools/offwaketime.py): Summarize blocked time by kernel off-CPU stack and waker stack. [Examples](tools/offwaketime_example.txt). diff --git a/examples/tracing/mysqld_query.py b/examples/tracing/mysqld_query.py new file mode 100755 index 000000000000..20b90cf11ef6 --- /dev/null +++ b/examples/tracing/mysqld_query.py @@ -0,0 +1,61 @@ +#!/usr/bin/python +# +# mysqld_query Trace MySQL server queries. Example of USDT tracing. +# For Linux, uses BCC, BPF. Embedded C. +# +# USAGE: mysqld_query PID +# +# This uses USDT probes, and needs a MySQL server with -DENABLE_DTRACE=1. +# +# Copyright 2016 Netflix, Inc. +# Licensed under the Apache License, Version 2.0 (the "License") + +from __future__ import print_function +from bcc import BPF, USDT +import sys + +if len(sys.argv) < 2: + print("USAGE: mysqld_latency PID") + exit() +pid = sys.argv[1] +debug = 0 + +# load BPF program +bpf_text = """ +#include +int do_trace(struct pt_regs *ctx) { + uint64_t addr; + char query[128]; + /* + * Read the first argument from the query-start probe, which is the query. + * The format of this probe is: + * query-start(query, connectionid, database, user, host) + * see: https://dev.mysql.com/doc/refman/5.7/en/dba-dtrace-ref-query.html + */ + bpf_usdt_readarg(1, ctx, &addr); + bpf_trace_printk("%s\\n", addr); + return 0; +}; +""" + +# enable USDT probe from given PID +u = USDT(pid=int(pid)) +u.enable_probe(probe="query__start", fn_name="do_trace") +if debug: + print(u.get_text()) + print(bpf_text) + +# initialize BPF +b = BPF(text=bpf_text, usdt=u) + +# header +print("%-18s %-16s %-6s %s" % ("TIME(s)", "COMM", "PID", "QUERY")) + +# format output +while 1: + try: + (task, pid, cpu, flags, ts, msg) = b.trace_fields() + except ValueError: + print("value error") + continue + print("%-18.9f %-16s %-6d %s" % (ts, task, pid, msg)) diff --git a/examples/tracing/mysqld_query_example.txt b/examples/tracing/mysqld_query_example.txt new file mode 100644 index 000000000000..630c932b6327 --- /dev/null +++ b/examples/tracing/mysqld_query_example.txt @@ -0,0 +1,8 @@ +# ./mysqld_query.py `pgrep -n mysqld` +TIME(s) COMM PID QUERY +17450459.549910001 mysqld 18608 select @@version_comment limit 1 +17450463.822668001 mysqld 18608 SELECT DATABASE() +17450463.824042998 mysqld 18608 show databases +17450463.824570000 mysqld 18608 show tables +17450465.602717999 mysqld 18608 SELECT COUNT(*) FROM words +17450479.944897000 mysqld 18608 SELECT * FROM words WHERE word REGEXP '^bre.*n$' diff --git a/examples/tracing/nodejs_http_server_example.txt b/examples/tracing/nodejs_http_server_example.txt new file mode 100644 index 000000000000..ae223e05fa00 --- /dev/null +++ b/examples/tracing/nodejs_http_server_example.txt @@ -0,0 +1,5 @@ +# ./nodejs_http_server.py 24728 +TIME(s) COMM PID ARGS +24653324.561322998 node 24728 path:/index.html +24653335.343401998 node 24728 path:/images/welcome.png +24653340.510164998 node 24728 path:/images/favicon.png diff --git a/man/man8/mysqld_qslower.8 b/man/man8/mysqld_qslower.8 new file mode 100644 index 000000000000..5753079a1f96 --- /dev/null +++ b/man/man8/mysqld_qslower.8 @@ -0,0 +1,66 @@ +.TH mysqld_qslower 8 "2016-08-01" "USER COMMANDS" +.SH NAME +mysqld_qslower \- Trace MySQL server queries slower than a threshold. +.SH SYNOPSIS +.B mysqld_qslower PID [min_ms] +.SH DESCRIPTION +This traces queries served by a MySQL server, and prints those that exceed a +custom latency (query duration) threshold. By default, a minimum threshold of 1 +millisecond is used. If a threshold of 0 is used, all queries are printed. + +This uses User Statically-Defined Tracing (USDT) probes, a feature added to +MySQL for DTrace support, but which may not be enabled on a given MySQL +installation. See requirements. + +Since this uses BPF, only the root user can use this tool. +.SH REQUIREMENTS +CONFIG_BPF, bcc, and MySQL server with USDT probe support (when configuring +the build: \-DENABLE_DTRACE=1). +.SH OPTIONS +PID +Trace this mysqld PID. +.TP +min_ms +Minimum query latency (duration) to trace, in milliseconds. Default is 1 ms. +.SH EXAMPLES +.TP +Trace MySQL server queries slower than 1 ms for PID 1981: +# +.B mysqld_qslower 1981 +.TP +Trace slower than 10 ms for PID 1981: +# +.B mysqld_qslower 1981 10 +.SH FIELDS +.TP +TIME(s) +Time of query start, in seconds. +.TP +PID +Process ID of the traced server. +.TP +MS +Milliseconds for the query, from start to end. +.TP +QUERY +Query string, truncated to 128 characters. +.SH OVERHEAD +This adds low-overhead instrumentation to MySQL queries, and only emits output +data from kernel to user-level if they query exceeds the threshold. If the +server query rate is less than 1,000/sec, the overhead is expected to be +negligible. If the query rate is higher, test to gauge overhead. +.SH SOURCE +This is from bcc. +.IP +https://github.com/iovisor/bcc +.PP +Also look in the bcc distribution for a companion _examples.txt file containing +example usage, output, and commentary for this tool. +.SH OS +Linux +.SH STABILITY +Unstable - in development. +.SH AUTHOR +Brendan Gregg +.SH SEE ALSO +biosnoop(8) diff --git a/tools/mysqld_qslower.py b/tools/mysqld_qslower.py new file mode 100755 index 000000000000..612998772485 --- /dev/null +++ b/tools/mysqld_qslower.py @@ -0,0 +1,133 @@ +#!/usr/bin/python +# +# mysqld_qslower MySQL server queries slower than a threshold. +# For Linux, uses BCC, BPF. Embedded C. +# +# USAGE: mysqld_qslower PID [min_ms] +# +# By default, a threshold of 1.0 ms is used. Set this to 0 ms to trace all +# queries (verbose). +# +# This uses USDT probes, and needs a MySQL server with -DENABLE_DTRACE=1. +# +# Copyright 2016 Netflix, Inc. +# Licensed under the Apache License, Version 2.0 (the "License") +# +# 30-Jul-2016 Brendan Gregg Created this. + +from __future__ import print_function +from bcc import BPF, USDT +import sys +import ctypes as ct + +# arguments +def usage(): + print("USAGE: mysqld_latency PID [min_ms]") + exit() +if len(sys.argv) < 2: + usage() +if sys.argv[1][0:1] == "-": + usage() +pid = int(sys.argv[1]) +min_ns = 1 * 1000000 +min_ms_text = 1 +if len(sys.argv) == 3: + min_ns = float(sys.argv[2]) * 1000000 + min_ms_text = sys.argv[2] +debug = 0 +QUERY_MAX = 128 + +# load BPF program +bpf_text = """ +#include + +#define QUERY_MAX """ + str(QUERY_MAX) + """ + +struct start_t { + u64 ts; + char *query; +}; + +struct data_t { + u64 pid; + u64 ts; + u64 delta; + char query[QUERY_MAX]; +}; + +BPF_HASH(start_tmp, u32, struct start_t); +BPF_PERF_OUTPUT(events); + +int do_start(struct pt_regs *ctx) { + u32 pid = bpf_get_current_pid_tgid(); + struct start_t start = {}; + start.ts = bpf_ktime_get_ns(); + bpf_usdt_readarg(1, ctx, &start.query); + start_tmp.update(&pid, &start); + return 0; +}; + +int do_done(struct pt_regs *ctx) { + u32 pid = bpf_get_current_pid_tgid(); + struct start_t *sp; + + sp = start_tmp.lookup(&pid); + if (sp == 0) { + // missed tracing start + return 0; + } + + // check if query exceeded our threshold + u64 delta = bpf_ktime_get_ns() - sp->ts; + if (delta >= """ + str(min_ns) + """) { + // populate and emit data struct + struct data_t data = {.pid = pid, .ts = sp->ts, .delta = delta}; + bpf_probe_read(&data.query, sizeof(data.query), (void *)sp->query); + events.perf_submit(ctx, &data, sizeof(data)); + } + + start_tmp.delete(&pid); + + return 0; +}; + +""" + +# enable USDT probe from given PID +u = USDT(pid=pid) +u.enable_probe(probe="query__start", fn_name="do_start") +u.enable_probe(probe="query__done", fn_name="do_done") +if debug: + print(u.get_text()) + print(bpf_text) + +# initialize BPF +b = BPF(text=bpf_text, usdt=u) + +# header +print("Tracing MySQL server queries for PID %d slower than %s ms..." % (pid, + min_ms_text)) +print("%-14s %-6s %8s %s" % ("TIME(s)", "PID", "MS", "QUERY")) + +class Data(ct.Structure): + _fields_ = [ + ("pid", ct.c_ulonglong), + ("ts", ct.c_ulonglong), + ("delta", ct.c_ulonglong), + ("query", ct.c_char * QUERY_MAX) + ] + +# process event +start = 0 +def print_event(cpu, data, size): + global start + event = ct.cast(data, ct.POINTER(Data)).contents + if start == 0: + start = event.ts + print("%-14.6f %-6d %8.3f %s" % (float(event.ts - start) / 1000000000, + event.pid, float(event.delta) / 1000000, event.query)) + +# loop with callback to print_event +b["events"].open_perf_buffer(print_event) +while 1: + b.kprobe_poll() diff --git a/tools/mysqld_qslower_example.txt b/tools/mysqld_qslower_example.txt new file mode 100644 index 000000000000..73d52fab5020 --- /dev/null +++ b/tools/mysqld_qslower_example.txt @@ -0,0 +1,58 @@ +Demonstrations of mysqld_qslower, the Linux eBPF/bcc version. + + +mysqld_qslower traces queries served by a MySQL server, and prints those that +exceed a latency (query time) threshold. By default a threshold of 1 ms is +used. For example: + +# ./mysqld_qslower.py `pgrep -n mysqld` +Tracing MySQL server queries for PID 14371 slower than 1 ms... +TIME(s) PID MS QUERY +0.000000 18608 130.751 SELECT * FROM words WHERE word REGEXP '^bre.*n$' +2.921535 18608 130.590 SELECT * FROM words WHERE word REGEXP '^alex.*$' +4.603549 18608 24.164 SELECT COUNT(*) FROM words +9.733847 18608 130.936 SELECT count(*) AS count FROM words WHERE word REGEXP '^bre.*n$' +17.864776 18608 130.298 SELECT * FROM words WHERE word REGEXP '^bre.*n$' ORDER BY word + +This traced 5 queries, 4 of which took about 130 milliseconds. + +A pgrep command was used to specify the PID of mysqld. + + +In this example, a lower threshold is used of 0.1 ms: + +# ./mysqld_qslower.py `pgrep -n mysqld` 0.1 +Tracing MySQL server queries for PID 14371 slower than 0.1 ms... +TIME(s) PID MS QUERY +0.000000 18608 24.201 SELECT COUNT(*) FROM words +13.242390 18608 130.378 SELECT * FROM words WHERE word REGEXP '^bre.*n$' +23.601751 18608 119.198 SELECT * FROM words WHERE word REGEXP '^zzzzzzzz$' + +It worked, but I'm not catching any faster queries in this example. Notice I +added a query that searched for "zzzzzzzz": it returned an empty set, and ran +11 ms faster. + + +A 0 ms threshold can be specified to trace all queries: + +# ./mysqld_qslower.py `pgrep -n mysqld` 0 +Tracing MySQL server queries for PID 14371 slower than 0 ms... +TIME(s) PID MS QUERY +0.000000 18608 0.105 select @@version_comment limit 1 +2.049312 18608 0.099 SELECT DATABASE() +2.050666 18608 0.274 show databases +2.051040 18608 0.176 show tables +5.730044 18608 130.365 SELECT count(*) AS count FROM words WHERE word REGEXP '^bre.*n$' +9.273837 18608 0.096 select 1 +9.553742 18608 0.059 select 1 +9.986087 18608 0.080 select 1 + +This includes an initialization of a mysql client command, and selecting the +database. I also added some "select 1;" queries, which do no work and return +quickly. + + +USAGE: + +# ./mysqld_qslower.py -h +USAGE: mysqld_latency PID [min_ms]