Skip to content

Commit d602d6b

Browse files
brendangregg4ast
brendangregg
authored and
4ast
committed
MySQL USDT tool and example (iovisor#642)
* MySQL USDT example and tool * add nodejs example output * add reference to mysqld example
1 parent 3bfbc5f commit d602d6b

File tree

7 files changed

+334
-1
lines changed

7 files changed

+334
-1
lines changed

‎README.md

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -64,7 +64,8 @@ Examples:
6464
- examples/tracing/[bitehist.py](examples/tracing/bitehist.py): Block I/O size histogram. [Examples](examples/tracing/bitehist_example.txt).
6565
- examples/tracing/[disksnoop.py](examples/tracing/disksnoop.py): Trace block device I/O latency. [Examples](examples/tracing/disksnoop_example.txt).
6666
- examples/[hello_world.py](examples/hello_world.py): Prints "Hello, World!" for new processes.
67-
- examples/tracing/[nodejs_http_server.py](examples/tracing/nodejs_http_server.py): Trace Node.js HTTP server requests using USDT probes.
67+
- examples/tracing/[mysqld_query.py](examples/tracing/mysqld_query.py): Trace MySQL server queries using USDT probes. [Examples](examples/tracing/mysqld_query_example.txt).
68+
- 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).
6869
- examples/tracing/[task_switch.py](examples/tracing/task_switch.py): Count task switches with from and to PIDs.
6970
- examples/tracing/[tcpv4connect.py](examples/tracing/tcpv4connect.py): Trace TCP IPv4 active connections. [Examples](examples/tracing/tcpv4connect_example.txt).
7071
- examples/tracing/[trace_fields.py](examples/tracing/trace_fields.py): Simple example of printing fields from traced events.
@@ -98,6 +99,7 @@ Examples:
9899
- tools/[hardirqs](tools/hardirqs.py): Measure hard IRQ (hard interrupt) event time. [Examples](tools/hardirqs_example.txt).
99100
- tools/[killsnoop](tools/killsnoop.py): Trace signals issued by the kill() syscall. [Examples](tools/killsnoop_example.txt).
100101
- tools/[mdflush](tools/mdflush.py): Trace md flush events. [Examples](tools/mdflush_example.txt).
102+
- tools/[mysqld_qslower](tools/mysqld_qslower.py): Trace MySQL server queries slower than a threshold. [Examples](tools/mysqld_qslower_example.txt).
101103
- tools/[memleak](tools/memleak.py): Display outstanding memory allocations to find memory leaks. [Examples](tools/memleak_example.txt).
102104
- tools/[offcputime](tools/offcputime.py): Summarize off-CPU time by kernel stack trace. [Examples](tools/offcputime_example.txt).
103105
- 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

Lines changed: 61 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,61 @@
1+
#!/usr/bin/python
2+
#
3+
# mysqld_query Trace MySQL server queries. Example of USDT tracing.
4+
# For Linux, uses BCC, BPF. Embedded C.
5+
#
6+
# USAGE: mysqld_query PID
7+
#
8+
# This uses USDT probes, and needs a MySQL server with -DENABLE_DTRACE=1.
9+
#
10+
# Copyright 2016 Netflix, Inc.
11+
# Licensed under the Apache License, Version 2.0 (the "License")
12+
13+
from __future__ import print_function
14+
from bcc import BPF, USDT
15+
import sys
16+
17+
if len(sys.argv) < 2:
18+
print("USAGE: mysqld_latency PID")
19+
exit()
20+
pid = sys.argv[1]
21+
debug = 0
22+
23+
# load BPF program
24+
bpf_text = """
25+
#include <uapi/linux/ptrace.h>
26+
int do_trace(struct pt_regs *ctx) {
27+
uint64_t addr;
28+
char query[128];
29+
/*
30+
* Read the first argument from the query-start probe, which is the query.
31+
* The format of this probe is:
32+
* query-start(query, connectionid, database, user, host)
33+
* see: https://dev.mysql.com/doc/refman/5.7/en/dba-dtrace-ref-query.html
34+
*/
35+
bpf_usdt_readarg(1, ctx, &addr);
36+
bpf_trace_printk("%s\\n", addr);
37+
return 0;
38+
};
39+
"""
40+
41+
# enable USDT probe from given PID
42+
u = USDT(pid=int(pid))
43+
u.enable_probe(probe="query__start", fn_name="do_trace")
44+
if debug:
45+
print(u.get_text())
46+
print(bpf_text)
47+
48+
# initialize BPF
49+
b = BPF(text=bpf_text, usdt=u)
50+
51+
# header
52+
print("%-18s %-16s %-6s %s" % ("TIME(s)", "COMM", "PID", "QUERY"))
53+
54+
# format output
55+
while 1:
56+
try:
57+
(task, pid, cpu, flags, ts, msg) = b.trace_fields()
58+
except ValueError:
59+
print("value error")
60+
continue
61+
print("%-18.9f %-16s %-6d %s" % (ts, task, pid, msg))

‎examples/tracing/mysqld_query_example.txt

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,8 @@
1+
# ./mysqld_query.py `pgrep -n mysqld`
2+
TIME(s) COMM PID QUERY
3+
17450459.549910001 mysqld 18608 select @@version_comment limit 1
4+
17450463.822668001 mysqld 18608 SELECT DATABASE()
5+
17450463.824042998 mysqld 18608 show databases
6+
17450463.824570000 mysqld 18608 show tables
7+
17450465.602717999 mysqld 18608 SELECT COUNT(*) FROM words
8+
17450479.944897000 mysqld 18608 SELECT * FROM words WHERE word REGEXP '^bre.*n$'

‎examples/tracing/nodejs_http_server_example.txt

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,5 @@
1+
# ./nodejs_http_server.py 24728
2+
TIME(s) COMM PID ARGS
3+
24653324.561322998 node 24728 path:/index.html
4+
24653335.343401998 node 24728 path:/images/welcome.png
5+
24653340.510164998 node 24728 path:/images/favicon.png

‎man/man8/mysqld_qslower.8

Lines changed: 66 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,66 @@
1+
.TH mysqld_qslower 8 "2016-08-01" "USER COMMANDS"
2+
.SH NAME
3+
mysqld_qslower \- Trace MySQL server queries slower than a threshold.
4+
.SH SYNOPSIS
5+
.B mysqld_qslower PID [min_ms]
6+
.SH DESCRIPTION
7+
This traces queries served by a MySQL server, and prints those that exceed a
8+
custom latency (query duration) threshold. By default, a minimum threshold of 1
9+
millisecond is used. If a threshold of 0 is used, all queries are printed.
10+
11+
This uses User Statically-Defined Tracing (USDT) probes, a feature added to
12+
MySQL for DTrace support, but which may not be enabled on a given MySQL
13+
installation. See requirements.
14+
15+
Since this uses BPF, only the root user can use this tool.
16+
.SH REQUIREMENTS
17+
CONFIG_BPF, bcc, and MySQL server with USDT probe support (when configuring
18+
the build: \-DENABLE_DTRACE=1).
19+
.SH OPTIONS
20+
PID
21+
Trace this mysqld PID.
22+
.TP
23+
min_ms
24+
Minimum query latency (duration) to trace, in milliseconds. Default is 1 ms.
25+
.SH EXAMPLES
26+
.TP
27+
Trace MySQL server queries slower than 1 ms for PID 1981:
28+
#
29+
.B mysqld_qslower 1981
30+
.TP
31+
Trace slower than 10 ms for PID 1981:
32+
#
33+
.B mysqld_qslower 1981 10
34+
.SH FIELDS
35+
.TP
36+
TIME(s)
37+
Time of query start, in seconds.
38+
.TP
39+
PID
40+
Process ID of the traced server.
41+
.TP
42+
MS
43+
Milliseconds for the query, from start to end.
44+
.TP
45+
QUERY
46+
Query string, truncated to 128 characters.
47+
.SH OVERHEAD
48+
This adds low-overhead instrumentation to MySQL queries, and only emits output
49+
data from kernel to user-level if they query exceeds the threshold. If the
50+
server query rate is less than 1,000/sec, the overhead is expected to be
51+
negligible. If the query rate is higher, test to gauge overhead.
52+
.SH SOURCE
53+
This is from bcc.
54+
.IP
55+
https://github.com/iovisor/bcc
56+
.PP
57+
Also look in the bcc distribution for a companion _examples.txt file containing
58+
example usage, output, and commentary for this tool.
59+
.SH OS
60+
Linux
61+
.SH STABILITY
62+
Unstable - in development.
63+
.SH AUTHOR
64+
Brendan Gregg
65+
.SH SEE ALSO
66+
biosnoop(8)

‎tools/mysqld_qslower.py

Lines changed: 133 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,133 @@
1+
#!/usr/bin/python
2+
#
3+
# mysqld_qslower MySQL server queries slower than a threshold.
4+
# For Linux, uses BCC, BPF. Embedded C.
5+
#
6+
# USAGE: mysqld_qslower PID [min_ms]
7+
#
8+
# By default, a threshold of 1.0 ms is used. Set this to 0 ms to trace all
9+
# queries (verbose).
10+
#
11+
# This uses USDT probes, and needs a MySQL server with -DENABLE_DTRACE=1.
12+
#
13+
# Copyright 2016 Netflix, Inc.
14+
# Licensed under the Apache License, Version 2.0 (the "License")
15+
#
16+
# 30-Jul-2016 Brendan Gregg Created this.
17+
18+
from __future__ import print_function
19+
from bcc import BPF, USDT
20+
import sys
21+
import ctypes as ct
22+
23+
# arguments
24+
def usage():
25+
print("USAGE: mysqld_latency PID [min_ms]")
26+
exit()
27+
if len(sys.argv) < 2:
28+
usage()
29+
if sys.argv[1][0:1] == "-":
30+
usage()
31+
pid = int(sys.argv[1])
32+
min_ns = 1 * 1000000
33+
min_ms_text = 1
34+
if len(sys.argv) == 3:
35+
min_ns = float(sys.argv[2]) * 1000000
36+
min_ms_text = sys.argv[2]
37+
debug = 0
38+
QUERY_MAX = 128
39+
40+
# load BPF program
41+
bpf_text = """
42+
#include <uapi/linux/ptrace.h>
43+
44+
#define QUERY_MAX """ + str(QUERY_MAX) + """
45+
46+
struct start_t {
47+
u64 ts;
48+
char *query;
49+
};
50+
51+
struct data_t {
52+
u64 pid;
53+
u64 ts;
54+
u64 delta;
55+
char query[QUERY_MAX];
56+
};
57+
58+
BPF_HASH(start_tmp, u32, struct start_t);
59+
BPF_PERF_OUTPUT(events);
60+
61+
int do_start(struct pt_regs *ctx) {
62+
u32 pid = bpf_get_current_pid_tgid();
63+
struct start_t start = {};
64+
start.ts = bpf_ktime_get_ns();
65+
bpf_usdt_readarg(1, ctx, &start.query);
66+
start_tmp.update(&pid, &start);
67+
return 0;
68+
};
69+
70+
int do_done(struct pt_regs *ctx) {
71+
u32 pid = bpf_get_current_pid_tgid();
72+
struct start_t *sp;
73+
74+
sp = start_tmp.lookup(&pid);
75+
if (sp == 0) {
76+
// missed tracing start
77+
return 0;
78+
}
79+
80+
// check if query exceeded our threshold
81+
u64 delta = bpf_ktime_get_ns() - sp->ts;
82+
if (delta >= """ + str(min_ns) + """) {
83+
// populate and emit data struct
84+
struct data_t data = {.pid = pid, .ts = sp->ts, .delta = delta};
85+
bpf_probe_read(&data.query, sizeof(data.query), (void *)sp->query);
86+
events.perf_submit(ctx, &data, sizeof(data));
87+
}
88+
89+
start_tmp.delete(&pid);
90+
91+
return 0;
92+
};
93+
94+
"""
95+
96+
# enable USDT probe from given PID
97+
u = USDT(pid=pid)
98+
u.enable_probe(probe="query__start", fn_name="do_start")
99+
u.enable_probe(probe="query__done", fn_name="do_done")
100+
if debug:
101+
print(u.get_text())
102+
print(bpf_text)
103+
104+
# initialize BPF
105+
b = BPF(text=bpf_text, usdt=u)
106+
107+
# header
108+
print("Tracing MySQL server queries for PID %d slower than %s ms..." % (pid,
109+
min_ms_text))
110+
print("%-14s %-6s %8s %s" % ("TIME(s)", "PID", "MS", "QUERY"))
111+
112+
class Data(ct.Structure):
113+
_fields_ = [
114+
("pid", ct.c_ulonglong),
115+
("ts", ct.c_ulonglong),
116+
("delta", ct.c_ulonglong),
117+
("query", ct.c_char * QUERY_MAX)
118+
]
119+
120+
# process event
121+
start = 0
122+
def print_event(cpu, data, size):
123+
global start
124+
event = ct.cast(data, ct.POINTER(Data)).contents
125+
if start == 0:
126+
start = event.ts
127+
print("%-14.6f %-6d %8.3f %s" % (float(event.ts - start) / 1000000000,
128+
event.pid, float(event.delta) / 1000000, event.query))
129+
130+
# loop with callback to print_event
131+
b["events"].open_perf_buffer(print_event)
132+
while 1:
133+
b.kprobe_poll()

‎tools/mysqld_qslower_example.txt

Lines changed: 58 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,58 @@
1+
Demonstrations of mysqld_qslower, the Linux eBPF/bcc version.
2+
3+
4+
mysqld_qslower traces queries served by a MySQL server, and prints those that
5+
exceed a latency (query time) threshold. By default a threshold of 1 ms is
6+
used. For example:
7+
8+
# ./mysqld_qslower.py `pgrep -n mysqld`
9+
Tracing MySQL server queries for PID 14371 slower than 1 ms...
10+
TIME(s) PID MS QUERY
11+
0.000000 18608 130.751 SELECT * FROM words WHERE word REGEXP '^bre.*n$'
12+
2.921535 18608 130.590 SELECT * FROM words WHERE word REGEXP '^alex.*$'
13+
4.603549 18608 24.164 SELECT COUNT(*) FROM words
14+
9.733847 18608 130.936 SELECT count(*) AS count FROM words WHERE word REGEXP '^bre.*n$'
15+
17.864776 18608 130.298 SELECT * FROM words WHERE word REGEXP '^bre.*n$' ORDER BY word
16+
17+
This traced 5 queries, 4 of which took about 130 milliseconds.
18+
19+
A pgrep command was used to specify the PID of mysqld.
20+
21+
22+
In this example, a lower threshold is used of 0.1 ms:
23+
24+
# ./mysqld_qslower.py `pgrep -n mysqld` 0.1
25+
Tracing MySQL server queries for PID 14371 slower than 0.1 ms...
26+
TIME(s) PID MS QUERY
27+
0.000000 18608 24.201 SELECT COUNT(*) FROM words
28+
13.242390 18608 130.378 SELECT * FROM words WHERE word REGEXP '^bre.*n$'
29+
23.601751 18608 119.198 SELECT * FROM words WHERE word REGEXP '^zzzzzzzz$'
30+
31+
It worked, but I'm not catching any faster queries in this example. Notice I
32+
added a query that searched for "zzzzzzzz": it returned an empty set, and ran
33+
11 ms faster.
34+
35+
36+
A 0 ms threshold can be specified to trace all queries:
37+
38+
# ./mysqld_qslower.py `pgrep -n mysqld` 0
39+
Tracing MySQL server queries for PID 14371 slower than 0 ms...
40+
TIME(s) PID MS QUERY
41+
0.000000 18608 0.105 select @@version_comment limit 1
42+
2.049312 18608 0.099 SELECT DATABASE()
43+
2.050666 18608 0.274 show databases
44+
2.051040 18608 0.176 show tables
45+
5.730044 18608 130.365 SELECT count(*) AS count FROM words WHERE word REGEXP '^bre.*n$'
46+
9.273837 18608 0.096 select 1
47+
9.553742 18608 0.059 select 1
48+
9.986087 18608 0.080 select 1
49+
50+
This includes an initialization of a mysql client command, and selecting the
51+
database. I also added some "select 1;" queries, which do no work and return
52+
quickly.
53+
54+
55+
USAGE:
56+
57+
# ./mysqld_qslower.py -h
58+
USAGE: mysqld_latency PID [min_ms]

0 commit comments

Comments
 (0)