Tracing MySQL Slow Queries with eBPF and bpftrace: A Step‑by‑Step Guide

Problem Statement

MySQL slow‑query logging is useful for identifying inefficient SQL, but enabling the log can degrade performance, so it should be turned on only when needed. When the log cannot be enabled, we need a way to capture slow queries without affecting the server.

Why eBPF?

eBPF can trace the execution of MySQL functions in the kernel without modifying MySQL itself. By attaching probes to the dispatch_command function, which dispatches client commands, we can record the start time of a query, retrieve the SQL string, and calculate its latency.

Initial bpftrace Exploration

The dispatch_command function is the entry point for command handling. A simple bpftrace script can attach an uprobe to this function, store the timestamp in a map, and an uretprobe to compute the elapsed time and print the SQL.

#!/usr/bin/env bpftrace

uprobe:/usr/sbin/mysqld:dispatch_command {
    @start_times[tid] = nsecs;
    printf("MySQL command executed by PID %d: ", pid);
    printf("%s
", str(arg3));
}

uretprobe:/usr/sbin/mysqld:dispatch_command {
    $start = @start_times[tid];
    $delta = (nsecs - $start) / 1000000;
    printf("Latency: %u ms
", $delta);
    delete(@start_times[tid]);
}

This script works on some Linux distributions and MySQL versions, but on newer MySQL releases the probe fails to fire because the function signature changed and the symbol is mangled.

Version‑Specific Issues

In MySQL 5.6 the SQL string is the third argument of dispatch_command. Starting with MySQL 5.7 the SQL string moves to the second argument. On Ubuntu 24.04 with MySQL 8.0.39 the function is compiled with C++ name mangling, producing the symbol _Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command. Probing the unmangled name therefore attaches to nothing, and no SQL is printed.

Solution Overview

We write a custom eBPF program that probes the mangled symbol directly. The steps are:

Identify the correct mangled symbol using bpftrace -l 'u:/usr/sbin/mysqld:*' | grep dispatch_command or objdump -T /usr/sbin/mysqld | grep dispatch_command.

Attach an uprobe to record the start timestamp and read the SQL string with bpf_probe_read_user_str.

Attach an uretprobe to compute the latency, retrieve the stored SQL, and submit an event via a ring buffer.

The eBPF program defines a struct event that holds PID, TID, latency (nanoseconds) and a 256‑byte buffer for the query.

#include "vmlinux.h"
#include <bpf/bpf_helpers.h>
#include <bpf/bpf_core_read.h>
#include <bpf/bpf_tracing.h>

char LICENSE[] SEC("license") = "Dual BSD/GPL";

struct event {
    u32 pid;
    u32 tid;
    u64 delta_ns;
    char query[256];
};

struct {
    __uint(type, BPF_MAP_TYPE_HASH);
    __uint(max_entries, 10240);
    __type(key, u32);
    __type(value, u64);
} start_times SEC(".maps");

struct {
    __uint(type, BPF_MAP_TYPE_HASH);
    __uint(max_entries, 10240);
    __type(key, u32);
    __type(value, char[256]);
} comm_sql SEC(".maps");

struct {
    __uint(type, BPF_MAP_TYPE_RINGBUF);
    __uint(max_entries, 1 << 24);
} events SEC(".maps");

SEC("uprobe//usr/sbin/mysqld:_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command")
int uprobe_mysql_dispatch_command(struct pt_regs *ctx) {
    u32 tid = bpf_get_current_pid_tgid() >> 32;
    u64 ts = bpf_ktime_get_ns();
    void *st = (void *) PT_REGS_PARM2(ctx);
    char query[256];
    char *query_ptr;
    bpf_probe_read_user(&query_ptr, sizeof(query_ptr), st);
    bpf_probe_read_user_str(query, sizeof(query), query_ptr);
    bpf_map_update_elem(&comm_sql, &tid, query, BPF_ANY);
    bpf_map_update_elem(&start_times, &tid, &ts, BPF_ANY);
    return 0;
}

SEC("uretprobe//usr/sbin/mysqld:_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command")
int uretprobe_mysql_dispatch_command(struct pt_regs *ctx) {
    u32 tid = bpf_get_current_pid_tgid() >> 32;
    char *query = bpf_map_lookup_elem(&comm_sql, &tid);
    if (!query) return 0;
    bpf_map_delete_elem(&comm_sql, &tid);
    u64 *start_ts = bpf_map_lookup_elem(&start_times, &tid);
    if (!start_ts) return 0;
    u64 delta = bpf_ktime_get_ns() - *start_ts;
    bpf_map_delete_elem(&start_times, &tid);
    struct event *e = bpf_ringbuf_reserve(&events, sizeof(*e), 0);
    if (!e) return 0;
    e->pid = bpf_get_current_pid_tgid() & 0xFFFFFFFF;
    e->tid = tid;
    e->delta_ns = delta;
    if (query)
        bpf_probe_read_kernel_str(e->query, sizeof(e->query), query);
    else
        e->query[0] = '\0';
    bpf_ringbuf_submit(e, 0);
    return 0;
}

User‑Space Consumer (Go)

The Go program loads the compiled eBPF object, attaches the probes, opens a ring‑buffer reader, and prints each event.

func main() {
    if err := rlimit.RemoveMemlock(); err != nil {
        log.Fatal(err)
    }
    spec, err := loadBpf()
    if err != nil {
        log.Fatalf("loading BPF program: %v", err)
    }
    objs := bpfObjects{}
    if err := spec.LoadAndAssign(&objs, nil); err != nil {
        log.Fatalf("loading objects: %v", err)
    }
    defer objs.Close()

    ex, err := link.OpenExecutable("/usr/sbin/mysqld")
    if err != nil {
        log.Fatalf("opening executable: %v", err)
    }
    up, err := ex.Uprobe("_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command", objs.UprobeMysqlDispatchCommand, nil)
    if err != nil {
        log.Fatalf("creating uprobe: %v", err)
    }
    defer up.Close()
    upret, err := ex.Uretprobe("_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command", objs.UretprobeMysqlDispatchCommand, nil)
    if err != nil {
        log.Fatalf("creating uretprobe: %v", err)
    }
    defer upret.Close()

    rb, err := ringbuf.NewReader(objs.Events)
    if err != nil {
        log.Fatalf("opening ringbuf reader: %v", err)
    }
    defer rb.Close()

    sig := make(chan os.Signal, 1)
    signal.Notify(sig, syscall.SIGINT, syscall.SIGTERM)
    fmt.Println("listening for events...")

    go func() {
        for {
            record, err := rb.Read()
            if err != nil {
                log.Printf("reading from ringbuf: %v", err)
                return
            }
            var data Event
            err = binary.Read(bytes.NewReader(record.RawSample), binary.LittleEndian, &data)
            if err != nil {
                log.Printf("parsing event: %v", err)
                return
            }
            fmt.Printf("PID: %d, TID: %d, Latency: %v, SQL: %s
", data.Pid, data.Tid, time.Duration(data.DeltaNs), data.GetQuery())
        }
    }()
    <-sig
    fmt.Println("Exiting...")
}

Running this program while executing queries in another terminal prints the PID, TID, latency, and the actual SQL statement for any query whose execution time exceeds the optional threshold (e.g., 10 ms).

Discussion of bpftrace

bpftrace is a high‑level tracing language built on BPF. It can dynamically attach probes, use simple awk -like syntax, and provides built‑in functions such as bpf_probe_read_user_str and bpf_probe_read_kernel_str for reading strings from user and kernel space. Example:

bpftrace -e 'uprobe:/usr/sbin/mysqld:_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command { printf("%s
", str(arg2)); }'

While bpftrace is convenient, it requires a kernel with BPF support (≥ 4.1), clang/llvm toolchain, and possibly libbpf, which can be a barrier on some distributions.

With the custom eBPF program and the Go consumer, we obtain a lightweight, production‑ready solution for monitoring MySQL slow queries without enabling the built‑in slow‑query log.