June 19, 2019

bccとUSDTを使ってMySQL/PostgreSQLのクエリログを取得する

引越しをして落ち着き始めました。一人暮らしの頃の家電を replace する作業をしている。
よろしくおねがいします。


USDT がどのように動作するのかについて調べ、USDT と eBPF(bcc) を使って様々なことができることを知ったのでメモがてら。

まずは USDT (User Statically-Defined Tracing) について簡単に述べる。
USDT はユーザースペースで動作しているアプリケーションに対し、オーバーヘッドを小さく簡単にデバッグを可能とするものだ。
これは DTrace で使われている技術で、元々は Solaris でカーネルに Probe と呼ばれるものを挿入し、Probe を通過した時点でユーザースペースの関数がコールバックさせるもの(SDT)。これにより実行中のアプリケーションをリアルタイムにトレースすることが可能となっている。
この Probe をカーネルだけではなくユーザースペースのプログラム(例えば MySQL や Node.js など ) に実装することで、同様にトレースを可能としている。

Probe 情報は ELF バイナリの .not.stapsdt セクションに配置され、命令は nop 命令としてコンパイルされる。

例として gettimeofday を毎秒実行し、timeval->tv_sec をトレースするために DTRACE_PROBE 命令を挿入したプログラムを下記に示す。

#include <sys/sdt.h>
#include <sys/time.h>
#include <unistd.h>

int main(int argc, char **argv) {
  struct timeval tv;

  while(1) {
    gettimeofday(&tv, NULL);
    DTRACE_PROBE1(test-app, test-probe, tv.tv_sec);
    sleep(1);
  }

  return 0;
}

これをコンパイルすると、 DTRACE_PROBE 自体は確かに nop となっている。

0000000000001149 <main>:
    1149:       55                      push   %rbp
    114a:       48 89 e5                mov    %rsp,%rbp
    114d:       48 83 ec 30             sub    $0x30,%rsp
    1151:       89 7d dc                mov    %edi,-0x24(%rbp)
    1154:       48 89 75 d0             mov    %rsi,-0x30(%rbp)
    1158:       64 48 8b 04 25 28 00    mov    %fs:0x28,%rax
    115f:       00 00
    1161:       48 89 45 f8             mov    %rax,-0x8(%rbp)
    1165:       31 c0                   xor    %eax,%eax
    1167:       48 8d 45 e0             lea    -0x20(%rbp),%rax
    116b:       be 00 00 00 00          mov    $0x0,%esi
    1170:       48 89 c7                mov    %rax,%rdi
    1173:       e8 b8 fe ff ff          callq  1030 <gettimeofday@plt>
    1178:       48 8b 45 e0             mov    -0x20(%rbp),%rax
    117c:       90                      nop    # DTRACE_PROBE
    117d:       bf 01 00 00 00          mov    $0x1,%edi
    1182:       e8 b9 fe ff ff          callq  1040 <sleep@plt>
    1187:       eb de                   jmp    1167 <main+0x1e>
    1189:       0f 1f 80 00 00 00 00    nopl   0x0(%rax)

そして .note-stapsdt セクションが作成されている。

$ readelf -n ./a.out
Displaying notes found in: .note.stapsdt
  Owner                 Data size       Description
  stapsdt              0x00000034       NT_STAPSDT (SystemTap probe descriptors)
    Provider: test-app
    Name: test-probe
    Location: 0x000000000000117c, Base: 0x0000000000002004, Semaphore: 0x0000000000000000
    Arguments: -8@%rax

Location に DTRACE_PROBE の位置が、Arguments にパラメータにアクセスする方法が格納されていることがわかる。

bcc にはこのセクションをパースするための関数 parse_stapsdt_note がある。

Probe が無効化されている(トレースプログラムが走っていない)状態では nop のままだが、トレースプログラム(DTraceなど)が動作し、Probe が有効化されると nopint3c 命令に変更される。

$ sudo gdb -q -p 9037
Attaching to process 9037
Reading symbols from /home/mrtc0/tmp/ebpf/usdt/a.out...
(No debugging symbols found in /home/mrtc0/tmp/ebpf/usdt/a.out)
Reading symbols from /usr/lib/libc.so.6...
(No debugging symbols found in /usr/lib/libc.so.6)
Reading symbols from /lib64/ld-linux-x86-64.so.2...
(No debugging symbols found in /lib64/ld-linux-x86-64.so.2)
0x00007f9738d018d8 in nanosleep () from /usr/lib/libc.so.6
(gdb) disas main
Dump of assembler code for function main:
   0x0000563161b22149 <+0>:     push   %rbp
   0x0000563161b2214a <+1>:     mov    %rsp,%rbp
   0x0000563161b2214d <+4>:     sub    $0x30,%rsp
   0x0000563161b22151 <+8>:     mov    %edi,-0x24(%rbp)
   0x0000563161b22154 <+11>:    mov    %rsi,-0x30(%rbp)
   0x0000563161b22158 <+15>:    mov    %fs:0x28,%rax
   0x0000563161b22161 <+24>:    mov    %rax,-0x8(%rbp)
   0x0000563161b22165 <+28>:    xor    %eax,%eax
   0x0000563161b22167 <+30>:    lea    -0x20(%rbp),%rax
   0x0000563161b2216b <+34>:    mov    $0x0,%esi
   0x0000563161b22170 <+39>:    mov    %rax,%rdi
   0x0000563161b22173 <+42>:    callq  0x563161b22030 <gettimeofday@plt>
   0x0000563161b22178 <+47>:    mov    -0x20(%rbp),%rax
   0x0000563161b2217c <+51>:    int3   # nop が int3 に変わっている
   0x0000563161b2217d <+52>:    mov    $0x1,%edi

int3 でトラップするとカーネルランドからユーザーランドに処理が渡ることでトレースが可能になっている。(と理解しているが間違っていたらごめんなさい)

このように Probe が有効化されていない場合は nop 命令のため、ほとんどパフォーマンスに影響がないように設計されている。
(この設計めちゃくちゃ感動した…)

bcc を用いてトレースを行う

では先程例に挙げたプログラムで tv.sec を bcc を利用してトレースしてみる。

#!/usr/bin/python
from __future__ import print_function
from bcc import BPF, USDT
import sys

pid = sys.argv[1]

bpf_text = """
#include <uapi/linux/ptrace.h>
int do_trace(struct pt_regs *ctx) {
    long tv_sec;
    long sec;

    bpf_usdt_readarg(1, ctx, &tv_sec);
    bpf_probe_read(&sec, sizeof(sec), (void *)&tv_sec);
    bpf_trace_printk("%lld\\n", sec);
    return 0;
};
"""

u = USDT(pid=int(pid))
u.enable_probe(probe="test-probe", fn_name="do_trace")

b = BPF(text=bpf_text, usdt_contexts=[u])

print("%-18s %-16s %-6s %s" % ("TIME(s)", "COMM", "PID", "tv.sec"))

while 1:
    try:
        (task, pid, cpu, flags, ts, msg) = b.trace_fields()
    except ValueError:
        print("value error")
        continue
    except KeyboardInterrupt:
        exit()
    print("%-18.9f %-16s %-6d %s" % (ts, task, pid, msg))

上記プログラムを実行する。

$ ./a.out

$ ps aux | grep a.out
mrtc0    30614  0.0  0.0   2164   688 pts/25   S+   17:14   0:00 ./a.out

$ sudo python test.py 30614
TIME(s)            COMM             PID    tv.sec
1879.331475000     b'a.out'         30614  b'1560932135'
1880.331681000     b'a.out'         30614  b'1560932136'
1881.331834000     b'a.out'         30614  b'1560932137'
1882.331963000     b'a.out'         30614  b'1560932138'
1883.332120000     b'a.out'         30614  b'1560932139'
1884.332282000     b'a.out'         30614  b'1560932140'

無事トレースすることができた。
DTrace から行うのが一般的かもしれないが、bcc は Python や Go などで書くことが可能なので扱いやすい。

先にも書いた通り、Dynamic Trace のための Probe はパフォーマンス分析のために Node.js や MySQL, その他高級言語等にも実装されている。
ここでは MySQL と PostgreSQL のクエリログを取得する例を挙げてみようと思う。

MySQL のクエリログを取得する

MySQL にも Probe が埋め込まれており、 -DENABLE_DTRACE=1 でコンパイルすると利用できる。

Probe は下記リンクを参照。

例えば query-start Probe を使用すると受け取ったクエリを取得できるため、クエリログに活用できる。

query-start からは5つのパラメータを取得できる。

query-start(query, connectionid, database, user, host)

クエリは1番目の引数なので、 bpf_usdt_readarg(1, ctx, &query) のようにすれば取得できる。
同様に現在の database 名や user, 接続元 client を取得したければ、対応した index を指定すればよい。

余談だが、 query-done Probe も利用することで query-start から query-done までの時間を計算し、スロークエリを見つけることも可能だ。

from __future__ import print_function
from bcc import BPF, USDT
import sys

pid = sys.argv[1]

bpf_text = """
#include <uapi/linux/ptrace.h>
int do_trace(struct pt_regs *ctx) {
    char *query;
    bpf_usdt_readarg(1, ctx, &query);
    bpf_trace_printk("%s\\n", query);
    return 0;
};
"""

u = USDT(pid=int(pid))
u.enable_probe(probe="query__start", fn_name="do_trace")

b = BPF(text=bpf_text, usdt_contexts=[u])
print("%-18s %-16s %-6s %s" % ("TIME(s)", "COMM", "PID", "QUERY"))

while 1:
    try:
        (task, pid, cpu, flags, ts, msg) = b.trace_fields()
    except ValueError:
        print("value error")
        continue
    except KeyboardInterrupt:
        exit()
    print("%-18.9f %-16s %-6d %s" % (ts, task, pid, msg))

上記コードを実行すると次のようにクエリが取得できる。

$ sudo python mysql_query_logger.py `pgrep mysqld`
TIME(s)            COMM             PID    QUERY
8248.324017000     mysqld           1871   show databases
8383.042382000     mysqld           1871   select @@version_comment limit 1
8389.271875000     mysqld           1871   SELECT DATABASE()
8389.280241000     mysqld           1871   show databases
8389.283206000     mysqld           1871   show tables
8395.543780000     mysqld           1871   select * from user

PostgreSQL のクエリログを取得する

PostgreSQL も Probe が存在するため、MySQL と同様にクエリログを取得できる。

query-start の第一引数にクエリが入っているため、上記のコードをそのまま転用できる。

$ sudo python psql_query_logger.py 5174
TIME(s)            COMM             PID    QUERY
9421.690371000     postgres         5174   select * from user;
9508.824765000     postgres         5174   SELECT r.rolname, r.rolsuper, r.rolinherit,

Ref

このエントリーをはてなブックマークに追加

© Kouhei Morita 2018