日々の覚書: percona-toolkit 3.0.12とそれ以前のpt-ioprofileがCentOS 7.xで動かない件 (pt-ioprofile 3.5.0でfix

【2023/02/27 22:44】

pt-ioprofile 3.5.0とそれ以降では直ってるみたい。

PT-1631 fix ioprofile ubuntu18.04, ubuntu16.04 support (#431) · percona/percona-toolkit@60b3750

TL;DR

strace の出力がちょっと変わったのでそれをひっかけられていない
Percona Toolkitへのバグレポはこちら
- [PT-1631] pt-ioprofile doesn’t work in CentOS 7.5 box - Percona JIRA
パッチは以下のとおり
- 3.0.12の /usr/bin/pt-ioprofile では574行目だけど、この行を探せば他のバージョンでも適用できるはず

574c574
< /^Process/ { mode = "strace"; }
—
> /^(strace: )?Process/ { mode = "strace"; }

ちょっと前からなんかおかしいような気はしていた。
MySQL 8.0だからいけないのかなとか思っていたけど、よく考えれば pt-ioprofile はシェルスクリプトだし中で lsof と strace を取って awk で頑張っているだけなので mysqld のバージョンは関係ないはずだ。

CentOSのバージョンのせいかと思って比べてみたらどうやら当たりの様子。

$ cat /etc/centos-release
CentOS release 6.10 (Final)

$ pt-ioprofile
Wed Oct 17 12:24:46 JST 2018
Tracing process ID 365
     total      pread       read     pwrite      write      fsync  fdatasync       open      close   getdents      lseek      fcntl filename
  4.430536   0.000000   0.000000   0.159895   0.000000   4.270641   0.000000   0.000000   0.000000   0.000000   0.000000   0.000000 /var/lib/mysql/ib_logfile0
  0.071731   0.000000   0.000000   0.003155   0.000000   0.061186   0.000000   0.000452   0.000301   0.000000   0.006448   0.000189 /var/lib/mysql/mysqlslap/t1.ibd
  0.052828   0.000000   0.000000   0.004702   0.000000   0.048126   0.000000   0.000000   0.000000   0.000000   0.000000   0.000000 /var/lib/mysql/ibdata1
  0.013654   0.000436   0.001654   0.000204   0.001798   0.000000   0.006763   0.000823   0.000716   0.000000   0.001260   0.000000 /var/lib/mysql/mysqlslap/t1.frm
  0.005068   0.000000   0.000000   0.000000   0.000000   0.005068   0.000000   0.000000   0.000000   0.000000   0.000000   0.000000 /var/lib/mysql/mysql/innodb_index_stats.ibd
  0.002342   0.000000   0.000000   0.000000   0.000000   0.002342   0.000000   0.000000   0.000000   0.000000   0.000000   0.000000 /var/lib/mysql/mysql/innodb_table_stats.ibd
  0.000917   0.000000   0.000176   0.000000   0.000000   0.000000   0.000000   0.000323   0.000233   0.000185   0.000000   0.000000 /dev/urandom
  0.000911   0.000000   0.000000   0.000000   0.000000   0.000000   0.000080   0.000549   0.000141   0.000141   0.000000   0.000000 /var/lib/mysql/mysqlslap/
  0.000628   0.000000   0.000000   0.000000   0.000140   0.000000   0.000000   0.000376   0.000112   0.000000   0.000000   0.000000 /var/lib/mysql/mysqlslap/db.opt
  0.000400   0.000000   0.000000   0.000000   0.000000   0.000000   0.000000   0.000213   0.000000   0.000000   0.000187   0.000000 /var/lib/mysql/mysql/event.MYD
  0.000126   0.000000   0.000000   0.000000   0.000000   0.000000   0.000000   0.000126   0.000000   0.000000   0.000000   0.000000 /var/lib/mysql/mysql/proc.MYD

同じMySQL 5.7.23にmysqlslapをかけながら pt-ioprofile をぶっ放しても、CentOS 7.5の方は何も返してくれない。

$ cat /etc/centos-release
CentOS Linux release 7.5.1804 (Core)

$ pt-ioprofile
Wed Oct 17 12:07:17 JST 2018
Tracing process ID 27170
     total filename

取り敢えずまあ採取した strace と lsof の結果を捨てずに残しておく --save-samples オプションなど使いつつ、 bash -x で何をしているのか調べていく。

$ bash -x /usr/bin/pt-ioprofile --save-samples /tmp/
..
+ _lsof 27170
..
+ strace -T -s 0 -f -p 27170
..
+ awk -f /tmp/pt-ioprofile.7393.52pjmz/tabulate_strace.awk /tmp/pt-ioprofile
+ awk -f /tmp/pt-ioprofile.7393.52pjmz/summarize_strace.awk /tmp/pt-ioprofile.7393.52pjmz/tabulated_samples
+ '[' filename '!=' all ']'
+ head -n1 /tmp/pt-ioprofile.7393.52pjmz/summarized_samples
     total filename
+ tail -n +2 /tmp/pt-ioprofile.7393.52pjmz/summarized_samples
+ sort -rn -k1
+ rm_tmpdir
+ '[' -n /tmp/pt-ioprofile.7393.52pjmz ']'
+ '[' -d /tmp/pt-ioprofile.7393.52pjmz ']'
+ rm -rf /tmp/pt-ioprofile.7393.52pjmz
+ PT_TMPDIR=
+ exit 0

$ ll /tmp/pt-ioprofile
-rw-r--r-- 1 yoku0825 yoku0825 128606368 Oct 17 12:48 /tmp/pt-ioprofile

lsof と strace はちゃんと取れているっぽい。

$ less /tmp/pt-ioprofile
+ local pid=27170
+ lsof -p 27170
COMMAND   PID     USER   FD   TYPE             DEVICE  SIZE/OFF      NODE NAME
mysqld  27170 yoku0825  cwd    DIR              253,0      4096 134572596 /usr/mysql/5.7.23/data
mysqld  27170 yoku0825  rtd    DIR              253,0      4096       128 /
mysqld  27170 yoku0825  txt    REG              253,0 686787152 201877015 /usr/mysql/5.7.23/bin/mysqld
..
strace: Process 27170 attached with 36 threads
[pid 27203] futex(0x7ff4ec03ded4, FUTEX_WAIT_PRIVATE, 347, NULL <unfinished ...>
[pid 27202] futex(0x7ff4ec03de44, FUTEX_WAIT_PRIVATE, 391, NULL <unfinished ...>
[pid 27201] futex(0x7ff4ec03ddb4, FUTEX_WAIT_PRIVATE, 455, NULL <unfinished ...>
..

じゃあまあなんか集計部分がおかしいのかな、と awk を叩いてみようと思うも

$ awk -f /tmp/pt-ioprofile.7393.52pjmz/tabulate_strace.awk /tmp/pt-ioprofile
awk: fatal: can't open source file `/tmp/pt-ioprofile.7393.52pjmz/tabulate_strace.awk' for reading (No such file or directory)

（・３・）アルェー
と思ったら、 bash -x の最後の方で /tmp/pt-ioprofile.7393.52pjmz を消してた。
どうやら一度テンポラリーディレクトリーにawkスクリプトを書き出した後にawk -fで食わせているっぽい。

rm_tmpdir から rm -rf の部分を消し去ってリトライ。

$ bash -x /usr/bin/pt-ioprofile --save-samples /tmp/pt-ioprofile
..
+ awk -f /tmp/pt-ioprofile.7897.sdNdwz/tabulate_strace.awk /tmp/pt-ioprofile
+ awk -f /tmp/pt-ioprofile.7897.sdNdwz/summarize_strace.awk /tmp/pt-ioprofile.7897.sdNdwz/tabulated_samples
..

$ ll /tmp/pt-ioprofile.7897.sdNdwz/
total 12
-rw-r--r-- 1 yoku0825 yoku0825   20 Oct 17 12:57 summarized_samples
-rw-r--r-- 1 yoku0825 yoku0825 3408 Oct 17 12:57 summarize_strace.awk
-rw-r--r-- 1 yoku0825 yoku0825    0 Oct 17 12:57 tabulated_samples
-rw-r--r-- 1 yoku0825 yoku0825 3547 Oct 17 12:57 tabulate_strace.awk

$ awk -f /tmp/pt-ioprofile.7897.sdNdwz/tabulate_strace.awk /tmp/pt-ioprofile

あれ何も起こらない…
比較用のCentOS 6.10では *_samples も0バイトじゃないし、 awk の結果も返ってくる。

$ ll /tmp/pt-ioprofile.812.PmCXAO
total 164
-rw-r--r-- 1 root root   1765 Oct 17 12:59 summarized_samples
-rw-r--r-- 1 root root   3408 Oct 17 12:59 summarize_strace.awk
-rw-r--r-- 1 root root 154779 Oct 17 12:59 tabulated_samples
-rw-r--r-- 1 root root   3547 Oct 17 12:59 tabulate_strace.awk

$ awk -f /tmp/pt-ioprofile.812.PmCXAO/tabulate_strace.awk /tmp/pt-ioprofile
517 open 62 0 0.000032 /dev/urandom
517 read 62 32 0.000016 /dev/urandom
517 close 62 0 0.000015 /dev/urandom
517 open directory) 0 0.000730 /var/lib/mysql/mysqlslap/
517 open 62 0 0.000079 /var/lib/mysql/mysqlslap/db.opt
517 write 62 65 0.000024 /var/lib/mysql/mysqlslap/db.opt
..

ということで、 tabulate_strace.awk のどこかが悪そう。

…というのを頑張った結果、最初に書いたパッチにたどり着いたのでしたん。

日々の覚書

GA

2018/10/17

percona-toolkit 3.0.12とそれ以前のpt-ioprofileがCentOS 7.xで動かない件 (pt-ioprofile 3.5.0でfix

0 件のコメント :

コメントを投稿