利用strace & Perf分析MySQL
strace介绍及用途
strace是一个用于诊断，分析linux用户态进程的工具
类似的工具pstrace,lsof,gdb,pstrack
strace观察mysqld对my.cnf 配置文件的加载顺序
命令如下：
strace -T -tt -s 100 -o start.log /usr/local/mysql/bin/mysqld
# cat -n start.log |sed -n '152,165p'
152 03:43:41.399411 futex(0x7fb060f058b8, FUTEX_WAKE_PRIVATE, 2147483647) = 0 <0.000013>
153 03:43:41.400839 stat("/etc/my.cnf", {st_mode=S_IFREG|0644, st_size=11064, ...}) = 0 <0.000015>
154 03:43:41.400951 open("/etc/my.cnf", O_RDONLY) = 3 <0.000024>
155 03:43:41.401026 fstat(3, {st_mode=S_IFREG|0644, st_size=11064, ...}) = 0 <0.000009>
156 03:43:41.401068 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb061d94000 <0.000016>
157 03:43:41.401116 read(3, "[client]\nport = 3306\n\n[mysql]\nauto-rehash\nprompt=\"\\\\u@\\\\h [\\\\d]>\"\n#pager=\"less -i -n -S\"\n"..., 4096) = 4096 <0.000016>
158 03:43:41.401211 read(3, " # 0\n#rpl_semi_sync_master_timeout =1000 # 1000(1 second)\n#plu"..., 4096) = 4096 <0.000011>
159 03:43:41.401303 read(3, " #\ton\ninnodb_change_buffering =all #\tall\ninnodb"..., 4096) = 2872 <0.000011>
160 03:43:41.401376 read(3, "", 4096) = 0 <0.000010>
161 03:43:41.401423 close(3) = 0 <0.000052>
162 03:43:41.401564 munmap(0x7fb061d94000, 4096) = 0 <0.000080>
163 03:43:41.401777 stat("/etc/mysql/my.cnf", 0x7fff5ec1c170) = -1 ENOENT (No such file or directory) <0.000022>
164 03:43:41.402070 stat("/usr/local/mysql/etc/my.cnf", 0x7fff5ec1c170) = -1 ENOENT (No such file or directory) <0.000016>
165 03:43:41.402134 stat("/root/.my.cnf", 0x7fff5ec1c170) = -1 ENOENT (No such file or directory) <0.000012>
MySQL启动后默认会启动多少线程
操作系统查看：
# ps -T `pidof mysqld`
PID SPID TTY STAT TIME COMMAND
72371 72371 pts/0 Sl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72377 pts/0 Rl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72378 pts/0 Rl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72379 pts/0 Rl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72380 pts/0 Rl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72381 pts/0 Rl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72382 pts/0 Rl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72383 pts/0 Rl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72384 pts/0 Rl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72385 pts/0 Rl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72386 pts/0 Rl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72387 pts/0 Rl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72388 pts/0 Rl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72389 pts/0 Rl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72390 pts/0 Rl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72391 pts/0 Rl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72392 pts/0 Sl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72393 pts/0 Rl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72394 pts/0 Rl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72395 pts/0 Sl 0:01 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72396 pts/0 Sl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72397 pts/0 Sl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72398 pts/0 Sl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72399 pts/0 Rl 1:45 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72400 pts/0 Rl 0:03 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72401 pts/0 Rl 0:03 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72402 pts/0 Rl 0:03 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72403 pts/0 Rl 0:03 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72404 pts/0 Rl 0:03 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72405 pts/0 Sl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72406 pts/0 Sl 0:02 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72407 pts/0 Sl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72408 pts/0 Sl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72409 pts/0 Sl 0:01 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72410 pts/0 Sl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72411 pts/0 Sl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72412 pts/0 Sl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72413 pts/0 Sl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72414 pts/0 Sl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72415 pts/0 Sl 0:01 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72416 pts/0 Sl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72419 pts/0 Sl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72420 pts/0 Sl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72421 pts/0 Sl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72422 pts/0 Sl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72423 pts/0 Sl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72424 pts/0 Sl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
72371 72425 pts/0 Sl 0:00 /usr/local/mysql/bin/mysqld --defaults-file=/app/mysqldata/3306/my.cnf --basedir=/usr
利用pstack
pstack `pidof mysql` 或者pstack `pidof mysqld` 2>&1|tee /tmp/pstack.log
select thread_id, name from performance_schema.threads;
select name,count(*) from performance_schema.threads group by name;
mysql> select name,count(*) from performance_schema.threads group by name; +---------------------------------------------+----------+ | name | count(*) | +---------------------------------------------+----------+ | thread/sql/main | 1 | | thread/innodb/io_write_thread | 8 | | thread/innodb/io_read_thread | 8 | | thread/innodb/io_ibuf_thread | 1 | | thread/innodb/io_log_thread | 1 | | thread/innodb/page_flush_coordinator_thread | 1 | | thread/innodb/page_flush_thread | 3 | | thread/innodb/log_checkpointer_thread | 1 | | thread/innodb/log_closer_thread | 1 | | thread/innodb/log_writer_thread | 1 | | thread/innodb/log_flusher_thread | 1 | | thread/innodb/log_write_notifier_thread | 1 | | thread/innodb/log_flush_notifier_thread | 1 | | thread/innodb/srv_lock_timeout_thread | 1 | | thread/innodb/srv_error_monitor_thread | 1 | | thread/innodb/srv_monitor_thread | 1 | | thread/innodb/buf_resize_thread | 1 | | thread/innodb/srv_master_thread | 1 | | thread/innodb/buf_dump_thread | 1 | | thread/innodb/dict_stats_thread | 1 | | thread/innodb/fts_optimize_thread | 1 | | thread/mysqlx/worker | 2 | | thread/mysqlx/acceptor_network | 2 | | thread/innodb/srv_purge_thread | 2 | | thread/innodb/srv_worker_thread | 6 | | thread/sql/signal_handler | 1 | | thread/sql/event_scheduler | 1 | | thread/sql/compress_gtid_table | 1 | | thread/sql/one_connection | 1 | +---------------------------------------------+----------+ 29 rows in set (0.01 sec)
如何匹配conn_id和os_thread_id
MySQL 5.7 & 8.0时代采用的方法：
可以利用sys.processlist 和performance_schema.threads进行关联
mysql> select thd_id, conn_id, thread_os_id, name from sys.processlist a ,performance_schema.threads b where a.thd_id =b.thread_id and conn_id >0; +--------+---------+--------------+--------------------------------+ | thd_id | conn_id | thread_os_id | name | +--------+---------+--------------+--------------------------------+ | 55 | 6 | 72425 | thread/sql/compress_gtid_table | | 60 | 11 | 76698 | thread/sql/one_connection | | 54 | 4 | 72423 | thread/sql/event_scheduler | +--------+---------+--------------+--------------------------------+ 3 rows in set (0.12 sec)
利用strace观察client的SQL执行
strace -T -tt -e trace=recvfrom,write,access,read,open,pwrite64,pread64 -p 76698
利用strace观察server端执行
MySQL 5.7后可以利用sys.processlist:
select thd_id, conn_id,user, pid,program_name,command,current_statement from processlist where conn_id>0 and pid>0;
strace -o /tmp/test.log -T -tt -ff -p `pidof mysqld`
-ff 参数，在跟踪的线程fork出新的thread时，会产生一个新文件存放
select thread_id, thread_os_id,name from threads where thread_os_id in (15871,15872,15874,15901);
strace -T -tt -o /tmp/strace.log CMD
strace -T -tt CMD 2>&1 |tee /tmp/strace.log
strace -T -tt -s 100 -o /tmp/strace.log CMD
strace -T -tt -s 100 -ff -o /tmp/strace.log CMD
strace -T -tt -s 100 -e trace=XXXX -o /tmp/strace.log CMD
strace -T -tt -s 100 -ff -o /root/strace.log /usr/local/mysql/bin/mysqld
strace -T -tt -s 100 -e trace=write -o /root/strace.log /usr/local/mysql/bin/mysqld
annotate Read perf.data (created by perf record) and display annotated code
archive Create archive with object files with build-ids found in perf.data file
bench General framework for benchmark suites
buildid-cache Manage build-id cache.
buildid-list List the buildids in a perf.data file
diff Read two perf.data files and display the differential profile
evlist List the event names in a perf.data file
inject Filter to augment the events stream with additional information
kmem Tool to trace/measure kernel memory(slab) properties
kvm Tool to trace/measure kvm guest os
list List all symbolic event types
lock Analyze lock events
record Run a command and record its profile into perf.data
report Read perf.data (created by perf record) and display the profile
sched Tool to trace/measure scheduler properties (latencies)
script Read perf.data (created by perf record) and display trace output
stat Run a command and gather performance counter statistics
test Runs sanity tests.
timechart Tool to visualize total system behavior during a workload
top System profiling tool.
trace strace inspired tool
probe Define new dynamic tracepoints
perf 包含了：perf-stat (perf stat), perf-top (perf top), perf-record (perf record), perf-list (perf list)
perf list 主要是用于列出有哪些可用的event，可以供 perf top -e eventname 来分析。
上面的 perf list [hw|sw...] 可以知道所有的 tracepoint events, 接下来我们就可以使用 perf top -e tracepoint-event 来专门获得指定的tracepoint的信息：
perf top常用选项有：
-e <event>：指明要分析的性能事件。
-p <pid>：Profile events on existing Process ID (comma sperated list). 仅分析目标进程及其创建的线程。
-k <path>：Path to vmlinux. Required for annotation functionality. 带符号表的内核映像所在的路径。
-K：不显示属于内核或模块的符号。
-U：不显示属于用户态程序的符号。
-d <n>：界面的刷新周期，默认为2s，因为perf top默认每2s从mmap的内存区域读取一次性能数据。
-g：得到函数的调用关系图。
# perf top -p `pidof mysqld`
Samples: 221 of event 'cycles', Event count (approx.): 10810377, UID: mysql
10.34% mysqld [.] my_strnncollsp_utf8
5.70% [kernel] [k] _spin_lock_irqsave
5.66% libc-2.12.so [.] __memset_sse2
5.55% [kernel] [k] remove_wait_queue
5.16% libc-2.12.so [.] __GI___strcmp_ssse3
4.36% [kernel] [k] __audit_syscall_exit
3.39% [kernel] [k] lookup_ioctx
3.28% [kernel] [k] find_next_bit
3.22% mysqld [.] lex_one_token(YYSTYPE*, THD*)
2.69% mysqld [.] Item::val_bool()
2.60% [kernel] [k] __do_softirq
2.53% mysqld [.] Protocol::send_result_set_row(List<Item>*)
2.52% [kernel] [k] local_bh_enable_ip
2.51% mysqld [.] my_strnncoll_binary
2.51% libc-2.12.so [.] memcpy
第一列：符号引发的性能事件的比例，默认指占用的cpu周期比例。
第二列：符号所在的DSO(Dynamic Shared Object)，可以是应用程序、内核、动态链接库、模块。
第三列：DSO的类型。[.]表示此符号属于用户态的ELF文件，包括可执行文件与动态链接库)。[k]表述此符号属于内核或模块。
第四列：符号名。有些符号不能解析为函数名，只能用地址表示。
