tools/dbslower.py

   1 #!/usr/bin/python
   2 #
   3 # dbslower      Trace MySQL and PostgreSQL queries slower than a threshold.
   4 #
   5 # USAGE: dbslower [-v] [-p PID [PID ...]] [-b PATH_TO_BINARY] [-m THRESHOLD] {mysql,postgres}
   6 #
   7 # By default, a threshold of 1ms is used. Set the threshold to 0 to trace all
   8 # queries (verbose).
   9 #
  10 # Script works in two different modes:
  11 # 1) USDT probes, which means it needs MySQL and PostgreSQL built with
  12 # USDT (DTrace) support.
  13 # 2) uprobe and uretprobe on exported function of binary specified by
  14 # PATH_TO_BINARY parameter. (At the moment only MySQL support)
  15 #
  16 # If no PID or PATH_TO_BINARY is provided, the script attempts to discover
  17 # all MySQL or PostgreSQL database processes and uses USDT probes.
  18 #
  19 # Strongly inspired by Brendan Gregg's work on the mysqld_qslower script.
  20 #
  21 # Copyright 2017, Sasha Goldshtein
  22 # Licensed under the Apache License, Version 2.0
  23 #
  24 # 15-Feb-2017   Sasha Goldshtein   Created this.
  25
  26 from bcc import BPF, USDT
  27 import argparse
  28 import re
  29 import ctypes as ct
  30 import subprocess
  31
  32 examples = """examples:
  33     dbslower postgres            # trace PostgreSQL queries slower than 1ms
  34     dbslower postgres -p 188 322 # trace specific PostgreSQL processes
  35     dbslower mysql -p 480 -m 30  # trace MySQL queries slower than 30ms
  36     dbslower mysql -p 480 -v     # trace MySQL queries & print the BPF program
  37     dbslower mysql -x $(which mysqld)  # trace MySQL queries with uprobes
  38 """
  39 parser = argparse.ArgumentParser(
  40     description="",
  41     formatter_class=argparse.RawDescriptionHelpFormatter,
  42     epilog=examples)
  43 parser.add_argument("-v", "--verbose", action="store_true",
  44     help="print the BPF program")
  45 parser.add_argument("db", choices=["mysql", "postgres"],
  46     help="the database engine to use")
  47 parser.add_argument("-p", "--pid", type=int, nargs='*',
  48     dest="pids", metavar="PID", help="the pid(s) to trace")
  49 parser.add_argument("-x", "--exe", type=str,
  50     dest="path", metavar="PATH", help="path to binary")
  51 parser.add_argument("-m", "--threshold", type=int, default=1,
  52     help="trace queries slower than this threshold (ms)")
  53 args = parser.parse_args()
  54
  55 threshold_ns = args.threshold * 1000000
  56
  57 mode = "USDT"
  58 if args.path and not args.pids:
  59     if args.db == "mysql":
  60         symbols = BPF.get_user_functions_and_addresses(args.path, "\\w+dispatch_command\\w+")
  61
  62         if len(symbols) == 0:
  63             print("Can't find function 'dispatch_command' in %s" % (args.path))
  64             exit(1)
  65
  66         (mysql_func_name, addr) = symbols[0]
  67
  68         if mysql_func_name.find("COM_DATA") >= 0:
  69             mode = "MYSQL57"
  70         else:
  71             mode = "MYSQL56"
  72     else:
  73         # Placeholder for PostrgeSQL
  74         # Look on functions initStringInfo, pgstat_report_activity, EndCommand, NullCommand
  75         print("Sorry at the moment PostgreSQL supports only USDT")
  76         exit(1)
  77
  78 program = """
  79 #include <uapi/linux/ptrace.h>
  80
  81 DEFINE_THRESHOLD
  82 DEFINE_USDT
  83 DEFINE_MYSQL56
  84 DEFINE_MYSQL57
  85
  86 struct temp_t {
  87     u64 timestamp;
  88 #ifdef USDT
  89     char *query;
  90 #else
  91     /*
  92     MySQL clears query packet before uretprobe call - so copy query in advance
  93     */
  94     char query[256];
  95 #endif //USDT
  96 };
  97
  98 struct data_t {
  99     u64 pid;
 100     u64 timestamp;
 101     u64 duration;
 102     char query[256];
 103 };
 104
 105 BPF_HASH(temp, u64, struct temp_t);
 106 BPF_PERF_OUTPUT(events);
 107
 108 int query_start(struct pt_regs *ctx) {
 109
 110 #if defined(MYSQL56) || defined(MYSQL57)
 111 /*
 112 Trace only packets with enum_server_command == COM_QUERY
 113 */
 114     #ifdef MYSQL56
 115     u64 command  = (u64) PT_REGS_PARM1(ctx);
 116     #else //MYSQL57
 117     u64 command  = (u64) PT_REGS_PARM3(ctx);
 118     #endif
 119     if (command != 3) return 0;
 120 #endif
 121
 122     struct temp_t tmp = {};
 123     tmp.timestamp = bpf_ktime_get_ns();
 124
 125 #if defined(MYSQL56)
 126     bpf_probe_read(&tmp.query, sizeof(tmp.query), (void*) PT_REGS_PARM3(ctx));
 127 #elif defined(MYSQL57)
 128     void* st = (void*) PT_REGS_PARM2(ctx);
 129     char* query;
 130     bpf_probe_read(&query, sizeof(query), st);
 131     bpf_probe_read(&tmp.query, sizeof(tmp.query), query);
 132 #else //USDT
 133     bpf_usdt_readarg(1, ctx, &tmp.query);
 134 #endif
 135
 136     u64 pid = bpf_get_current_pid_tgid();
 137     temp.update(&pid, &tmp);
 138     return 0;
 139 }
 140
 141 int query_end(struct pt_regs *ctx) {
 142     struct temp_t *tempp;
 143     u64 pid = bpf_get_current_pid_tgid();
 144     tempp = temp.lookup(&pid);
 145     if (!tempp)
 146         return 0;
 147
 148     u64 delta = bpf_ktime_get_ns() - tempp->timestamp;
 149 #ifdef THRESHOLD
 150     if (delta >= THRESHOLD) {
 151 #endif //THRESHOLD
 152         struct data_t data = {};
 153         data.pid = pid >> 32;   // only process id
 154         data.timestamp = tempp->timestamp;
 155         data.duration = delta;
 156         bpf_probe_read(&data.query, sizeof(data.query), tempp->query);
 157         events.perf_submit(ctx, &data, sizeof(data));
 158 #ifdef THRESHOLD
 159     }
 160 #endif //THRESHOLD
 161     temp.delete(&pid);
 162     return 0;
 163 };
 164 """.replace("DEFINE_USDT", "#define USDT" if mode == "USDT" else "") \
 165    .replace("DEFINE_MYSQL56", "#define MYSQL56" if mode == "MYSQL56" else "") \
 166    .replace("DEFINE_MYSQL57", "#define MYSQL57" if mode == "MYSQL57" else "") \
 167    .replace("DEFINE_THRESHOLD", ("#define THRESHOLD " + str(threshold_ns)) if threshold_ns > 0 else "")
 168
 169 if mode.startswith("MYSQL"):
 170     # Uprobes mode
 171     bpf = BPF(text=program)
 172     bpf.attach_uprobe(name=args.path, sym=mysql_func_name, fn_name="query_start")
 173     bpf.attach_uretprobe(name=args.path, sym=mysql_func_name, fn_name="query_end")
 174 else:
 175     # USDT mode
 176     if not args.pids or len(args.pids) == 0:
 177         if args.db == "mysql":
 178             args.pids = map(int, subprocess.check_output(
 179                                             "pidof mysqld".split()).split())
 180         elif args.db == "postgres":
 181             args.pids = map(int, subprocess.check_output(
 182                                             "pidof postgres".split()).split())
 183
 184     usdts = map(lambda pid: USDT(pid=pid), args.pids)
 185     for usdt in usdts:
 186         usdt.enable_probe("query__start", "query_start")
 187         usdt.enable_probe("query__done", "query_end")
 188     if args.verbose:
 189         print('\n'.join(map(lambda u: u.get_text(), usdts)))
 190
 191     bpf = BPF(text=program, usdt_contexts=usdts)
 192
 193 if args.verbose:
 194     print(program)
 195
 196 class Data(ct.Structure):
 197     _fields_ = [
 198         ("pid", ct.c_ulonglong),
 199         ("timestamp", ct.c_ulonglong),
 200         ("delta", ct.c_ulonglong),
 201         ("query", ct.c_char * 256)
 202     ]
 203
 204 start = BPF.monotonic_time()
 205
 206 def print_event(cpu, data, size):
 207     event = ct.cast(data, ct.POINTER(Data)).contents
 208     print("%-14.6f %-6d %8.3f %s" % (
 209         float(event.timestamp - start) / 1000000000,
 210         event.pid, float(event.delta) / 1000000, event.query))
 211
 212 if mode.startswith("MYSQL"):
 213     print("Tracing database queries for application %s slower than %d ms..." %
 214         (args.path, args.threshold))
 215 else:
 216     print("Tracing database queries for pids %s slower than %d ms..." %
 217         (', '.join(map(str, args.pids)), args.threshold))
 218
 219 print("%-14s %-6s %8s %s" % ("TIME(s)", "PID", "MS", "QUERY"))
 220
 221 bpf["events"].open_perf_buffer(print_event, page_cnt=64)
 222 while True:
 223     bpf.kprobe_poll()