引越しをして落ち着き始めました。一人暮らしの頃の家電を 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 が有効化されると nop が int3c 命令に変更される。
$ 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,