土曜日 4 25, 2009

こんにちは。今日は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という名前のカラムが1つだけ定義されています。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

土曜日 4 11, 2009

こんにちは。今回はMyISAMでのCOUNT()関数について書いてみたいと思います。

COUNT()は皆さんご存知のように、テーブル中の行数を数える関数です。
MyISAMではテーブル全件を数えるCOUNT(*)関数の実行が非常に速いというのが巷の噂ですが、実際のところはどうなのでしょうか?ちょっと見てみたいと思います。

まずは比較のため、innodbのテーブルでカウントしてみたいと思います。
少しは件数の入ったテーブルが良いので、MySQLのサンプルとして提供されている
WorldデータベースのCityテーブルを使ってみました。

[InnoDB結果]

全件

mysql> alter table city engine=innodb;
Query OK, 4079 rows affected (0.27 sec)
Records: 4079  Duplicates: 0  Warnings: 0

mysql> flush tables;
Query OK, 0 rows affected (0.00 sec)

mysql> select count(*) from city;
+----------+
| count(*) |
+----------+
|     4079 |
+----------+
1 row in set (0.02 sec)

mysql> show profile;
+--------------------+----------+
| Status             | Duration |
+--------------------+----------+
| starting           | 0.000106 |
| Opening tables     | 0.001007 |
| System lock        | 0.000009 |
| Table lock         | 0.000016 |
| init               | 0.000024 |
| optimizing         | 0.000010 |
| statistics         | 0.000018 |
| preparing          | 0.000016 |
| executing          | 0.000012 |
| Sending data       | 0.005298 |
| end                | 0.000022 |
| query end          | 0.000009 |
| freeing items      | 0.000336 |
| logging slow query | 0.000009 |
| cleaning up        | 0.000009 |
+--------------------+----------+

WHERE句付き

mysql> flush tables;
Query OK, 0 rows affected (0.00 sec)

mysql> select count(*) from city where name = 'tokyo'
+----------+
| count(*) |
+----------+
|        1 |
+----------+
1 row in set (0.00 sec)

mysql> show profile;
+--------------------+----------+
| Status             | Duration |
+--------------------+----------+
| starting           | 0.000127 |
| Opening tables     | 0.001020 |
| System lock        | 0.000009 |
| Table lock         | 0.000017 |
| init               | 0.000052 |
| optimizing         | 0.000022 |
| statistics         | 0.000021 |
| preparing          | 0.000022 |
| executing          | 0.000011 |
| Sending data       | 0.006663 |
| end                | 0.000009 |
| query end          | 0.000007 |
| freeing items      | 0.000061 |
| logging slow query | 0.000007 |
| cleaning up        | 0.000008 |
+--------------------+----------+

続けて、MyISAMテーブルでの結果です。

[MyISAM結果]
全件

mysql> flush tables;
Query OK, 0 rows affected (0.00 sec)

mysql> select count(*) from city;
+----------+
| count(*) |
+----------+
|     4079 |
+----------+
1 row in set (0.00 sec)

mysql> show profile;
+--------------------+----------+
| Status             | Duration |
+--------------------+----------+
| starting           | 0.000106 |
| Opening tables     | 0.002326 |
| System lock        | 0.000011 |
| Table lock         | 0.000016 |
| init               | 0.000023 |
| optimizing         | 0.000012 |
| executing          | 0.000021 |
| end                | 0.000010 |
| query end          | 0.000008 |
| freeing items      | 0.000046 |
| logging slow query | 0.000007 |
| cleaning up        | 0.000007 |
+--------------------+----------+


WHERE句付き

mysql> flush tables;
Query OK, 0 rows affected (0.05 sec)

mysql> select count(*) from city where name = 'tokyo';
+----------+
| count(*) |
+----------+
|        1 |
+----------+
1 row in set (0.02 sec)

mysql> show profile;
+--------------------+----------+
| Status             | Duration |
+--------------------+----------+
| starting           | 0.000131 |
| Opening tables     | 0.002439 |
| System lock        | 0.000010 |
| Table lock         | 0.000017 |
| init               | 0.000051 |
| optimizing         | 0.000021 |
| statistics         | 0.000022 |
| preparing          | 0.000024 |
| executing          | 0.000011 |
| Sending data       | 0.003237 |
| end                | 0.000011 |
| query end          | 0.000009 |
| freeing items      | 0.000094 |
| logging slow query | 0.000009 |
| cleaning up        | 0.000012 |
+--------------------+----------+

まだまだ行数が少なかったようで、体感レスポンスタイムはあまり変わりませんでした。
しかし、プロファイリングしてみると中での動きは全然違うことが分かります。

・結果を出すためのステップがMyISAM-全件ではかなり省略されている
・MyISAM-全件では、特にSending dataのステップがない

以上のことから皆さんも「MyISAMの全件カウントは何か特別なことをしているな~」と感じられるのではないでしょうか。

実はMyISAMでは、テーブル中に現在何件の行があるかの情報をインデックスファイル(MYIファイル)に持っています。そして、MyISAMのテーブルで全件のCOUNT()が来たらMySQLサーバはデータファイルを一切読まず、計算などすることもなくインデックスファイルにある行数を返す仕様になっています。MyISAMテーブルに対するINSERTやDELETEが行われるたびに、この行数カウントが増減するようになっています。なお、InnoDBは構造上このようなフィールドを持つことができないため、件数カウントに時間がかかる仕様となっています(MVCC等のためです。詳しい理由は別の機会に・・・)

もうちょっと細かく見てみましょう。MYIファイルの中身はおおよそ以下のようになっています。

HEADER
  ステート情報
  ベース情報(主にデータ長定義)
  キー定義情報
 ..
  レコード情報
  ..
KEY
  キーセグメント情報(キー長さ、ポインタ情報)
  ..

さらに、[ステート情報]の部分を細かく見てみると以下のようになっています。

ヘッダ:24バイト(1-24)
オープンカウント : 2バイト(25-26)
ステート変更フラグ:1バイト(27)
ソートキー(不使用):1バイト(28)
レコード数:8バイト(29-36)
削除レコード数:8バイト(37-43)
<以下略>

MyISAMでは全件のCOUNT()関数が来るとMYIファイルの[現在の行数]の部分からデータを読みこんで結果を返します。ちょっと実験してみましょう。
MYIファイルの件数をみてCOUNT()関数が結果を返すならば、そこを変えるとテーブルデータはそのままでも結果件数は変わるはずです(不整合となりますが・・・)

何もしないと4079行という結果が返ってきます。

mysql> select count(*) from city;
+----------+
| count(*) |
+----------+
|     4079 |
+----------+
1 row in set (0.01 sec)

ここで、MYIファイルをバイナリエディタでちょっといじってみます。編集するのは、city.MYIという名前のファイルです。下のスクリーンショットのちょうどカーソルがあたっている部分が該当する部分となります。現在値は0FEF(4079)なので、これを適当な数字に変更してみます。

[変更後]
150FEFに変更しました。

さて、COUNT(*)の結果はどうなっているでしょうか。

mysql> select count(*) from city;
+----------+
| count(*) |
+----------+
|  1380335 |
+----------+
1 row in set (0.00 sec)

1380335(150FEF)に変更されています。
今回は実験目的で実施しましたが、通常バイナリを直接編集する機会はあまりないと思います。
もしも、今回のようにMYI(インデックス)の内容とMYD(データ)に差異が出てしまった場合は以下のようにして調査、修復することが可能です。

mysql> check table city;
+------------+-------+----------+----------------------------+
| Table      | Op    | Msg_type | Msg_text                   |
+------------+-------+----------+----------------------------+
| world.city | check | error    | Found 4079 keys of 1380335 |
| world.city | check | error    | Corrupt                    |
+------------+-------+----------+----------------------------+
2 rows in set (0.00 sec)

上記のようにCHECK TABLE文(オンライン用)または、myisamchkユーティリティ(オフライン用)を使ってファイルの状態を検査します。今回はMYIの件数が間違っているので、きちんと1380335ではなく実数は4079であると警告されています。

このように問題を発見した場合、REPAIR TABLE文(オンライン用)もしくはmyisamchkユーティリティ(オフライン用)で修復しましょう。

mysql> repair table city;
+------------+--------+----------+---------------------------------------------+
| Table      | Op     | Msg_type | Msg_text                                    |
+------------+--------+----------+---------------------------------------------+
| world.city | repair | warning  | Number of rows changed from 1380335 to 4079 |
| world.city | repair | status   | OK                                          |
+------------+--------+----------+---------------------------------------------+
2 rows in set (0.03 sec)

mysql> select count(*) from city;
+----------+
| count(*) |
+----------+
|     4079 |
+----------+
1 row in set (0.00 sec)

これで、もとの行数に戻りました。MYIファイルが消失してしまった場合でもMYDからREPAIR TABLEコマンドでMYIが復活できますので便利です(消失したときはUSE_FRMオプションをつけてください)。

注:DISTINCTやWHEREを使うとMYIから件数を持って来なくなります(それはそうですね)。

日曜日 4 05, 2009

こんにちは。今回はMyISAMストレージエンジンの並列インサート機能(Concurrent Insert)についてちょっと書いてみたいと思います。

MyISAMは皆さんご存知のように、テーブルレベルのロックのみで行レベルでのロックがサポートされていません。MySQLではSELECTコマンドの実行時に暗黙的リードロック(Shared Read lock)がかかるようになっており、一般的にはこのロックが対象のテーブルに存在している場合には、書き込み処理(INSERT,UPDATE,DELETE,ALTER TABLEなど)がロック待ちとなります。SELECTの実行が完了してからINSERTなどが実行される形になります。

MyISAMはテーブルロックなので、SELECTの対象としている行以外への更新も同様に待たされてしまい、同時処理性能に影響を与えているであろうことは容易に想像できると思います。

MyISAMには、コンカレントインサート(Concurrent Insert)と呼ばれる機能があります。コンカレントインサートとは、他のコネクション(スレッド)がSELECT文を発行もしくはLOCK文を実行している時であってもコンカレントインサート処理が対象のテーブルに対して書き込みロックを獲得できる(=Shared Read lockがかかっている状態のテーブルにINSERTできる)機能です。なおSELECTのShared Read lock要求は既にターゲットのテーブルにコンカレントインサートが書き込みロックをかけていても通るようになっています。

要するに、1つまたは複数のSELECTと1つのINSERTを同時実行できるようにする機能です。

コンカレントインサートが使用可能になるLOCKコマンドは以下となります。
LOCK TABLE テーブル名 READ LOCAL;
(LOCALをつけないとコンカレントインサートは利用不可になります。)

[設定方法]

グローバルサーバ変数:concurrent_insertを設定します。

0 : コンカレントインサートを使用しません。(使用できる状況でも使用しない)
1 : 対象のMyISAMテーブルに「穴」がない場合に限り(最後尾にインサートできる場合)、コンカレントインサートを実施します。
2 : 対象のMyISAMテーブルに「穴」があっても、レコードを強制的に最後尾にインサートし、コンカレントインサートを実施します。

ここで言う「穴」とは、ストレージのレコードシーケンスの途中に「穴」がある場合のことを言います。
MyISAMでは、一度DELETEしたデータは物理的には消去されず削除フラグを立てるだけとなっています。INSERTのみで作られたテーブルデータには「穴」はありませんが一度最後尾以外の行をDELETEすると削除フラグが立ちそこが「穴」となります。MyISAMは次回インサート時になるべくその「穴」の場所にデータを挿入しようとします。

concurrent_insert=2の場合は、対象のテーブルに既にリードロックがかけられていた場合のみ「穴」ではなく最後尾へデータを挿入します(穴はそのまま)。テーブルに何もロックがない場合は「穴」の場所にデータが挿入されます。concurrent_insert=1に比べて領域の使用効率が悪くはなります。なお、「穴」は次のコマンドで物理的になくすことが出来ます。

mysql> optimize table test.locktest;
+---------------+----------+----------+----------+
| Table         | Op       | Msg_type | Msg_text |
+---------------+----------+----------+----------+
| test.locktest | optimize | status   | OK       |
+---------------+----------+----------+----------+
1 row in set (0.00 sec)

[設定コマンド例]
set global concurrent_insert=0;
set global concurrent_insert=1;
set global concurrent_insert=2;
※デフォルトは1となっています。

グローバルサーバ変数なので、次回コネクション作成時から有効になります。
または、my.cnfなどの設定ファイルに書いておくと良いでしょう。

こう書いてみると常時1か2に設定したくなるような機能ですが実際のところはどうなのでしょうか。
ソース分析後に手元の環境で簡単なベンチマークをしてみました。

まずは、sysbenchでのテスト結果です。

コンカレントインサート有の場合(強制使用)
concurrent_insert=2;

OLTP test statistics:
    queries performed:
        read:                            1400
        write:                           500
        other:                           0
        total:                           1900
    transactions:                        100    (473.84 per sec.)
    deadlocks:                           0      (0.00 per sec.)
    read/write requests:                 1900   (9002.99 per sec.)
    other operations:                    0      (0.00 per sec.)

Test execution summary:
    total time:                          0.2110s
    total number of events:              100
    total time taken by event execution: 9.3607
    per-request statistics:
         min:                                 35.74ms
         avg:                                 93.61ms
         max:                                155.12ms
         approx.  95 percentile:             140.13ms

Threads fairness:
    events (avg/stddev):           1.0000/0.40
    execution time (avg/stddev):   0.0936/0.04

コンカレントインサート無しの場合
concurrent_insert=0;

OLTP test statistics:
    queries performed:
        read:                            1400
        write:                           500
        other:                           0
        total:                           1900
    transactions:                        100    (532.79 per sec.)
    deadlocks:                           0      (0.00 per sec.)
    read/write requests:                 1900   (10122.93 per sec.)
    other operations:                    0      (0.00 per sec.)

Test execution summary:
    total time:                          0.1877s
    total number of events:              100
    total time taken by event execution: 7.4302
    per-request statistics:
         min:                                 34.88ms
         avg:                                 74.30ms
         max:                                152.66ms
         approx.  95 percentile:             128.75ms

Threads fairness:
    events (avg/stddev):           1.0000/0.76
    execution time (avg/stddev):   0.0743/0.05

コンカレントインサート無しの方が若干ですがスループットが良いという結果となりました。
今回たまたまというわけではなく、ほぼ毎回このような結果となります。
実行時間の短いSELECTとINSERTは比較的効率的に処理されているためと推測されます。
逆にコンカレントインサートのオーバヘッドが目立つ形になったといったところでしょうか。

(sysbenchでは、INSERT,DELETE,UPDATEがミックスされてしまうので、INSERT以外の文が発生させるロックが多少結果に影響を与えると考えられます。念のためにmysqlslapでSELECTとINSERTのみのベンチを実施し結果は同様になるのを確認しました。詳細はここでは割愛します)

MyISAMの処理フローから逆算すると、コンカレントインサート機能が真価を発揮するのは実行時間の長いSELECT文が頻繁に流れているような状況下と仮定することができます。

そのような状況をシミュレートしてベンチマークテストを実施してみました。
今回は複雑なシナリオなので、JMeterを使ってみました。(SuperSmackなどでも良いと思います)

以下のスレッドを同時実行して性能を見るシナリオです。

・SELECT文(短い)とINSERT文をたくさん実行するスレッド(複数)
・長いSELECT文(ランダムで最大約1秒リードロックを保持する)を何度も実行するスレッド(1つ)

こんな感じです。

実行時間の長いSELECTはそれだけ長くリードロックを保持するので、コンカレントではないインサートは待ちとなってしまいます。

結果を見てみましょう。

concurrent_insert=2;
コンカレントインサート強制使用

テーブルロックの状況

mysql> show status like 'Table%';
+-----------------------+-------+
| Variable_name         | Value |
+-----------------------+-------+
| Table_locks_immediate | 1185  |
| Table_locks_waited    | 20    |
+-----------------------+-------+
2 rows in set (0.00 sec)

コンカレントインサートを使用しない
concurrent_insert=0;

テーブルロックの状況

mysql> show status like 'Table%';
+-----------------------+-------+
| Variable_name         | Value |
+-----------------------+-------+
| Table_locks_immediate | 865   |
| Table_locks_waited    | 390   |
+-----------------------+-------+
2 rows in set (0.01 sec)

コンカレントインサート使用時はINSERTのスループットは113.2、不使用時は66.6となっています。(SELECT REQ/SELECT REQ2はINSERTと同じスレッドなのでINSERTのスループットに引っ張られます)
※並列スレッドを100程度に絞り込んでいるのと、スレッド間での処理のずれを作り出すためにランダムでの待ち時間を入れているため絶対的なスループットは少なめとなっています。

長いSELECTが稼動していると、コンカレントインサートなしでは(当然ですが)ロック待ちになるケースが増えています。このロック待ちがスループットを落とす原因となっています。逆にコンカレントインサートを使っているとほとんどロック待ちが出ないのが観測されました。

結論としては、よく現在のMySQLの使われ方を分析した上でコンカレントインサート機能の使用/不使用を決定した方が良いでしょう。FITするケースにはパフォーマンスチューニングの一手段として使っても良いと思います。場合によってはOFFにすることも有効だと考えられます。

This blog copyright 2009 by naokitakemura