MySQL USDT tool and example (#642)

* MySQL USDT example and tool

* add nodejs example output

* add reference to mysqld example

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).

examples/tracing/mysqld_query.py

+#!/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 <uapi/linux/ptrace.h>
+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))

examples/tracing/mysqld_query_example.txt

+# ./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$'

examples/tracing/nodejs_http_server_example.txt

+# ./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

man/man8/mysqld_qslower.8

+.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)

tools/mysqld_qslower.py

+#!/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 <uapi/linux/ptrace.h>
+
+#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()

tools/mysqld_qslower_example.txt

+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]