こんにちは。今日はMyISAMの内部動作をトレースする方法をご紹介します。
MyISAMはデバッグ目的に内部動作をログに書き出す機能を持っています。これを使う機会はあまり無いと思いますが、環境の動作分析やパフォーマンスチューニングの参考情報にはなると思います。
[myisam-logの出力方法]
my.cnfもしくはmy.iniファイルの[mysqld]セクションに以下のように設定します。
[mysqld]
log-isam=c:/temp/mysql_isam.log
c:/temp/mysql_isam.logの部分はmyisam動作トレースログを出力したいファイルパスに書き換えて設定を行ってください。設定後、MySQLサーバを再起動します。
早速mysql_isam.logを見てみましょう。myisamlogはバイナリ形式で出力されているので、MySQLに付属している専用の閲覧ツールで内容を確認してみます。
[myisamlogの使用例]
C:\MySQLEntServer5.1\bin>myisamlog -i -vvv c:\temp\mysql_isam.log
-vvvを指定すると最も詳細な情報を出力することができます。-v, -vv, -vvvの三段階で出力レベルを調節できます。
[出力例]
C:\MySQLEntServer5.1\bin>myisamlog -i -vvv c:\temp\mysql_isam.log
0: 5180 ./mysql/host: open -> 12
27: 5180 ./mysql/host: extra(13) -> 0
37: 5180 ./mysql/host: extra(12) -> 0
47: 5180 ./mysql/host: extra(5) -> 0
57: 5180 ./mysql/user: open -> 14
84: 5180 ./mysql/user: extra(13) -> 0
94: 5180 ./mysql/user: extra(12) -> 0
104: 5180 ./mysql/user: extra(5) -> 0
114: 5180 ./mysql/db: open -> 16
139: 5180 ./mysql/db: extra(13) -> 0
149: 5180 ./mysql/db: extra(12) -> 0
159: 5180 ./mysql/db: extra(5) -> 0
169: 5180 ./mysql/host: extra(3) -> 0
179: 5180 ./mysql/host: extra(4) -> 0
189: 5180 ./mysql/user: extra(3) -> 0
199: 5180 ./mysql/user: extra(4) -> 0
209: 5180 ./mysql/db: extra(3) -> 0
219: 5180 ./mysql/db: extra(4) -> 0
229: 5180 ./mysql/time_zone_leap_second: open -> 18
273: 5180 ./mysql/time_zone_leap_second: extra(13) -> 0
283: 5180 ./mysql/time_zone_leap_second: extra(12) -> 0
293: 5180 ./mysql/time_zone_leap_second: extra(5) -> 0
303: 5180 ./mysql/time_zone_name: open -> 20
340: 5180 ./mysql/time_zone_name: extra(13) -> 0
350: 5180 ./mysql/time_zone_name: extra(12) -> 0
360: 5180 ./mysql/time_zone_name: extra(5) -> 0
370: 5180 ./mysql/time_zone: open -> 22
402: 5180 ./mysql/time_zone: extra(13) -> 0
412: 5180 ./mysql/time_zone: extra(12) -> 0
422: 5180 ./mysql/time_zone: extra(5) -> 0
432: 5180 ./mysql/time_zone_transition_type: open -> 24
480: 5180 ./mysql/time_zone_transition_type: extra(13) -> 0
490: 5180 ./mysql/time_zone_transition_type: extra(12) -> 0
500: 5180 ./mysql/time_zone_transition_type: extra(5) -> 0
510: 5180 ./mysql/time_zone_transition: open -> 26
553: 5180 ./mysql/time_zone_transition: extra(13) -> 0
563: 5180 ./mysql/time_zone_transition: extra(12) -> 0
573: 5180 ./mysql/time_zone_transition: extra(5) -> 0
583: 5180 ./mysql/time_zone_transition: close -> 0
592: 5180 ./mysql/time_zone_transition_type: close -> 0
601: 5180 ./mysql/time_zone: close -> 0
610: 5180 ./mysql/time_zone_name: close -> 0
619: 5180 ./mysql/time_zone_leap_second: close -> 0
628: 5180 ./mysql/tables_priv: open -> 18
662: 5180 ./mysql/tables_priv: extra(13) -> 0
672: 5180 ./mysql/tables_priv: extra(12) -> 0
682: 5180 ./mysql/tables_priv: extra(5) -> 0
692: 5180 ./mysql/columns_priv: open -> 20
727: 5180 ./mysql/columns_priv: extra(13) -> 0
737: 5180 ./mysql/columns_priv: extra(12) -> 0
747: 5180 ./mysql/columns_priv: extra(5) -> 0
757: 5180 ./mysql/procs_priv: open -> 22
790: 5180 ./mysql/procs_priv: extra(13) -> 0
800: 5180 ./mysql/procs_priv: extra(12) -> 0
810: 5180 ./mysql/procs_priv: extra(5) -> 0
820: 5180 ./mysql/servers: open -> 24
850: 5180 ./mysql/servers: extra(13) -> 0
860: 5180 ./mysql/servers: extra(12) -> 0
870: 5180 ./mysql/servers: extra(5) -> 0
880: 5180 ./mysql/servers: extra(3) -> 0
890: 5180 ./mysql/servers: extra(4) -> 0
900: 5180 ./mysql/func: open -> 26
927: 5180 ./mysql/func: extra(13) -> 0
937: 5180 ./mysql/func: extra(12) -> 0
947: 5180 ./mysql/func: extra(5) -> 0
957: 5180 ./mysql/func: extra(3) -> 0
967: 5180 ./mysql/func: extra(4) -> 0
977: 5180 ./mysql/func: close -> 0
986: 5180 ./mysql/event: open -> 26
1014: 5180 ./mysql/event: extra(13) -> 0
1024: 5180 ./mysql/event: extra(12) -> 0
1034: 5180 ./mysql/event: extra(5) -> 0
1044: 5180 ./mysql/event: extra(4) -> 0
Commands Used count Errors Recover errors
open 14 0 0
close 6 0 0
extra 53 0 0
Total 73 0 0
まだ何もテーブル操作を行っていないので、ユーザテーブルは一覧に出て来ていないのがわかります。以下にログの見方を説明します。
isamlogのファイルポジション プロセス番号 ファイル名： 操作ごとのログ
「操作ごとのログ」には例えば以下のようなものがあります。
open -> ファイルオープン数
extra(操作関数番号) -> リターンコード
write at ファイル中の行位置, length=0 -> 行自体に使用したバイト数
update at ファイル中の行位置, length=0 -> 行自体に使用したバイト数
openは、MYDファイルのオープン時、extraはSELECT、updateはUPDATE、writeはINSERT、deleteはDELETE文発行時にログに出力されます。
ここで、試しにtest.testというテーブルに対してアクセスをしてみたいと思います。mysqlクライアントでselectをしてみます。
mysql> use test;
Database changed
mysql> select * from test;
Empty set (0.00 sec)
ログの方はどうなっているでしょうか。
<中略>
967: 5180 ./mysql/func: extra(4) -> 0
977: 5180 ./mysql/func: close -> 0
986: 5180 ./mysql/event: open -> 26
1014: 5180 ./mysql/event: extra(13) -> 0
1024: 5180 ./mysql/event: extra(12) -> 0
1034: 5180 ./mysql/event: extra(5) -> 0
1044: 5180 ./mysql/event: extra(4) -> 0
1054: 5180 ./test/test: open -> 28
1080: 5180 ./test/test: extra(13) -> 0
1090: 5180 ./test/test: extra(12) -> 0
1100: 5180 ./test/test: extra(5) -> 0
Commands Used count Errors Recover errors
open 15 0 0
close 6 0 0
extra 56 0 0
Total 77 0 0
testテーブルにアクセスされたという情報がログの最後の部分に出ています。括弧中はselect実行時に使用されたメソッドの種類になります。クエリキャッシュが効いている場合などログにselect操作の結果が出てこないこともあります。
テストのため、テーブルにデータを一行挿入してみます。
mysql> insert into test values(1);
[myisamlog]
1321: 576 ./test/test: write at 0, length=0 -> 5
1347: 576 ./test/test: extra(4) -> 0
最初の一行なので、データが0の場所から5バイト書き込まれています。さらにもう一行挿入してみます。
3384: 576 ./test/test: write at 7, length=0 -> 5
3410: 576 ./test/test: extra(4) -> 0
今度は7バイト目から5バイト書き込まれました。ちなみにtestの構造は以下のようになっています。Row_formatはFixedとなっています。
mysql> show create table test;
+-------+-------------------------------------
| Table | Create Table
+-------+-------------------------------------
| test | CREATE TABLE `test` (
`a` int(11) DEFAULT NULL
) ENGINE=MyISAM DEFAULT CHARSET=utf8 |
+-------+-------------------------------------
1 row in set (0.00 sec)
int型のaという名前のカラムが１つだけ定義されています。int型はストレージを4バイト使用し、行ヘッダーはこのテーブルの場合1バイト使用します。ヘッダー1バイト + int型ストレージ4バイト=5バイトが 「length=0 -> 5」の意味するところです。さらにMyISAMの場合、最小行バイト数はグローバルサーバ変数myisam_data_pointer_sizeに指定された値+1(削除リンク分）に設定されます。デフォルト値は6ですので、6+1=7バイトが最小バイト数になります。myisam_data_pointer_sizeはCREATE TABLE時に使用されるので、もしこの値を変更する場合はCREATE TABLE前である必要があります。
この操作を行っている部分のソースは以下になります。
mi_create.c
if (!(options & (HA_OPTION_COMPRESS_RECORD | HA_OPTION_PACK_RECORD)))
{
if (reclength <= pointer)
reclength=pointer+1; /* reserve place for delete link */
}
実際にストレージに書き込まれるのは、ヘッダー1バイト + int型ストレージ4バイト+最小7バイトに足りない分を00値でパッディングする2バイト = 7バイトとなります。これはmyisamlogからも観測することができます。何行もデータを挿入してみます。
mysql> delete from test;
Query OK, 4 rows affected (0.00 sec)
mysql> insert into test values(1);
Query OK, 1 row affected (0.00 sec)
mysql> insert into test values(2);
Query OK, 1 row affected (0.00 sec)
mysql> insert into test values(3);
Query OK, 1 row affected (0.00 sec)
mysql> insert into test values(4);
Query OK, 1 row affected (0.00 sec)
mysql> insert into test values(5);
Query OK, 1 row affected (0.00 sec)
myisamlogは以下です。
8679: 576 ./test/test: re-open -> 0
8688: 576 ./test/test: write at 0, length=0 -> 5
8714: 576 ./test/test: extra(4) -> 0
8724: 576 ./test/test: write at 7, length=0 -> 5
8750: 576 ./test/test: extra(4) -> 0
8760: 576 ./test/test: write at 14, length=0 -> 5
8786: 576 ./test/test: extra(4) -> 0
8796: 576 ./test/test: write at 21, length=0 -> 5
8822: 576 ./test/test: extra(4) -> 0
8832: 576 ./test/test: write at 28, length=0 -> 5
8858: 576 ./test/test: extra(4) -> 0
書き込みは5バイトで、実際は7バイトずつストレージに書かれていることがわかります。またmyisamlogを見れば、データが実際にどの位置に挿入されたかがわかります。MyISAMでは行の削除はレコードヘッダに削除フラグが立てられるだけというのは以前書きましたが、実際にmyisamlogで挙動を確認することが可能です。試しにaの値が3(テーブルの中ごろに入っている）を削除してから新しいレコードをインサートしてみましょう。
mysql> delete from test where a = 3;
Query OK, 1 row affected (0.00 sec)
mysql> insert into test values(6);
Query OK, 1 row affected (0.00 sec)
myisamlogには以下が出力されています。
8952: 576 ./test/test: delete at 14 -> 0
8969: 576 ./test/test: extra(4) -> 0
8979: 576 ./test/test: write at 14, length=0 -> 5
9005: 576 ./test/test: extra(4) -> 0
一度削除された部分に対してインサートが行われているのが確認できます。
[オマケ]
myisamlogユーティリティには、出力されたmyisamログからMyISAMデータファイル（MYD)を再構築する機能もあります（使うかどうかはまた別問題として）。以下の手順で行います。
[ログの最初から最後までを再適用して、テーブルデータをリカバリする場合]
最初に、データを全部消してみます。
mysql> delete from test;
Query OK, 15 rows affected (0.02 sec)
バッファ内容をディスクにFlushします。
mysql> flush tables;
Query OK, 0 rows affected (0.00 sec)
以下のコマンドで、myisamlogからリカバリを行います。
C:\MySQLEntData\data>c:\mysqlentserver5.1\bin\myisamlog -i -r -vvv c:\temp2\mysql_isam.log ./test/test
バッファをクリアします。
mysql> flush tables;
Query OK, 0 rows affected (0.00 sec)
テーブルを見ると、ログからリプレイされデータが復活しているのがわかります。
mysql> select * from test;
+------+
| a |
+------+
| 1 |
| 2 |
| 6 |
| 4 |
| 5 |
+------+
5 rows in set (0.00 sec)
-oオプションを使うと、特定Log番号以降のログのみをリプレイに使うこともできます。（deleteもログに記録されているので削除される前のログをどこかに退避しないと、再び全行消えます 。。）他にもいくつかオプションがあるので試して見るのも趣がありますね。まあ、公式にはバイナリログを使うべきだと思いますのであくまで情報収集やデバッグ目的で行う方が良いと思います。
ちなみに、myisamlog -?とやると簡単な使用方法がプリントされるのですが、By Montyっていうあたり、ウケました。。。
C:\MySQLEntServer5.1\bin>myisamlog -?
myisamlog Ver 1.4 for Win32 at ia32
By Monty, for your professional use