straceでwriteやread, fsyncのシステムコール呼び出し状況を記録して、
lsofでファイルディスクリプタ番号と紐付けて、集計して出してくれたりする。
一番単純な使い方は多分こんな感じ。
# pt-ioprofile --cell sizes --run-time 60
2013年 1月 6日 日曜日 17:08:03 JST
Tracing process ID 1824
total read pread64 pwrite64 write open _llseek filename
2191 0 1024 1167 0 0 0 /var/lib/mysql/mysql/user.MYI
1386 0 1386 0 0 0 0 /var/lib/mysql/mysql/proxies_priv.MYD
1320 0 1320 0 0 0 0 /var/lib/mysql/mysql/db.MYD
564 512 24 28 0 0 0 /var/lib/mysql/mysql/user.MYD
81 0 0 0 81 0 0 /var/lib/mysql/bin.000056
0 0 0 0 0 0 0 /var/lib/mysql/mysql/db.opt
デフォルトの計測時間は30秒。--run-timeで上書き。
デフォルトの集計はI/O`回数'。--cellでsizesを指定するとバイト単位のオペレーション量になる。
1分間でこれらのファイルにこれだけのread, writeが発生してた…というのが測れる。
さてさてさて。
pt-ioprofileを走らせて、おもむろに`converting HEAP to MyISAM'が走る様なクエリを流す。
（tmp_table_sizeを1024に設定して、DISK上に出させる）
# pt-ioprofile --cell sizes --run-time 10
2013年 1月 6日 日曜日 17:22:17 JST
Tracing process ID 4904
total read pwrite write open close lseek filename
80400 20100 0 20100 0 0 40200 /tmp/#sql_1328_0.MYD
1782 328 126 1024 0 0 304 /tmp/#sql_1328_0.MYI
おお、取れた…んだけど、この値合ってんのかな。。
なんか違う気がする。
mysql> DESC t1;
+-------+---------------------+------+-----+---------+----------------+
| Field | Type | Null | Key | Default | Extra |
+-------+---------------------+------+-----+---------+----------------+
| num | bigint(20) unsigned | NO | PRI | NULL | auto_increment |
| val | char(32) | YES | | NULL | |
+-------+---------------------+------+-----+---------+----------------+
2 rows in set (0.01 sec)
mysql> DESC t2;
+-------+---------------------+------+-----+---------+----------------+
| Field | Type | Null | Key | Default | Extra |
+-------+---------------------+------+-----+---------+----------------+
| num | bigint(20) unsigned | NO | PRI | NULL | auto_increment |
| val | char(32) | YES | | NULL | |
+-------+---------------------+------+-----+---------+----------------+
2 rows in set (0.00 sec)
mysql> SELECT * FROM t2 LEFT JOIN t1 USING(num) ORDER BY t2.val DESC, t1.val ASC;
+-----+----------------------------------+----------------------------------+
| num | val | val |
+-----+----------------------------------+----------------------------------+
| 83 | fe9fc289c3ff0af142b6d3bead98a923 | fe9fc289c3ff0af142b6d3bead98a923 |
..
| 27 | 02e74f10e0327ad868d138f2b4fdd6f0 | 02e74f10e0327ad868d138f2b4fdd6f0 |
+-----+----------------------------------+----------------------------------+
100 rows in set (0.05 sec)
mysql> SHOW PROFILE;
+--------------------------------+----------+
| Status | Duration |
+--------------------------------+----------+
| starting | 0.001830 |
| Waiting for query cache lock | 0.000587 |
| checking query cache for query | 0.000904 |
| checking permissions | 0.000647 |
| checking permissions | 0.000546 |
| Opening tables | 0.001298 |
| System lock | 0.000778 |
| init | 0.000812 |
| optimizing | 0.004460 |
| statistics | 0.000866 |
| preparing | 0.000701 |
| Creating tmp table | 0.001023 |
| executing | 0.000597 |
| Copying to tmp table | 0.003121 |
| converting HEAP to MyISAM | 0.015940 |
| Copying to tmp table on disk | 0.005196 |
| Sorting result | 0.001541 |
| Sending data | 0.000519 |
| end | 0.000314 |
| removing tmp table | 0.001926 |
| end | 0.000363 |
| query end | 0.000301 |
| closing tables | 0.000289 |
| freeing items | 0.006751 |
| logging slow query | 0.000266 |
| cleaning up | 0.000558 |
+--------------------------------+----------+
26 rows in set (0.05 sec)
(BIGINT 4バイト + CHAR 32バイト) * 2テーブル結合 * 100行だから、
1行ごとのオーバーヘッド入れても20KiB近くも行かなそうなんだけどな。。
でもtmp_table_sizeを上げながら確認すると、
16KiBだとまだMyISAM変換されて、20KiBだとなくなる。
そんなものなのかぁ。
なおpt-ioprofileはstraceとlsofとpidof（だと思う。動き的に。中身は読んでない）を使ってるだけの
シェルスクリプトなので、
# pt-ioprofile --cell sizes --run-time 10 --profile-process rsyslogd
2013年 1月 6日 日曜日 17:25:44 JST
Tracing process ID 1227
total write filename
46 46 /var/log/messages
こんな真似も可能だったりする。
ただし、
tpcc-mysqlで負荷かけながらmysqldにアタッチしてたら、
スレッドが何本かState: Tでハングって
mysqldが動かなくなったことがあるので、
絶対に本番でやってはダメです。
言われなくてもやりませんね、はい。。
0 件のコメント :
コメントを投稿