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
18from __future__ import print_function
19from bcc import BPF, USDT
20import sys
21import ctypes as ct
22
23# arguments
24def usage():
25    print("USAGE: mysqld_latency PID [min_ms]")
26    exit()
27if len(sys.argv) < 2:
28    usage()
29if sys.argv[1][0:1] == "-":
30    usage()
31pid = int(sys.argv[1])
32min_ns = 1 * 1000000
33min_ms_text = 1
34if len(sys.argv) == 3:
35    min_ns = float(sys.argv[2]) * 1000000
36    min_ms_text = sys.argv[2]
37debug = 0
38QUERY_MAX = 128
39
40# load BPF program
41bpf_text = """
42#include <uapi/linux/ptrace.h>
43
44#define QUERY_MAX	""" + str(QUERY_MAX) + """
45
46struct start_t {
47    u64 ts;
48    char *query;
49};
50
51struct data_t {
52    u64 pid;
53    u64 ts;
54    u64 delta;
55    char query[QUERY_MAX];
56};
57
58BPF_HASH(start_tmp, u32, struct start_t);
59BPF_PERF_OUTPUT(events);
60
61int 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
70int 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
97u = USDT(pid=pid)
98u.enable_probe(probe="query__start", fn_name="do_start")
99u.enable_probe(probe="query__done", fn_name="do_done")
100if debug:
101    print(u.get_text())
102    print(bpf_text)
103
104# initialize BPF
105b = BPF(text=bpf_text, usdt_contexts=[u])
106
107# header
108print("Tracing MySQL server queries for PID %d slower than %s ms..." % (pid,
109    min_ms_text))
110print("%-14s %-6s %8s %s" % ("TIME(s)", "PID", "MS", "QUERY"))
111
112class 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
121start = 0
122def 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
131b["events"].open_perf_buffer(print_event, page_cnt=64)
132while 1:
133    b.perf_buffer_poll()
134