2016/04/30 15:36:35

MySQLでINSERTが遅いならストレージを見なおしてみたら良いかも


Warning: Attempt to read property "post_excerpt" on null in /home/kpkyvkzp/public_html/unskilled.site/wp-content/themes/unskilled2/content-header-eyecatch.php on line 5
目次(クリックするとジャンプします）
  • 1:MySQLでINSERTが遅い
  • 2:現状の確認
  • 3:時間が掛かる理由を考察
  • 3.1:一般クエリーログの中身
  • 3.2:データを検証
  • 3.2.1:スパイクの存在
  • 3.2.2:矩形波様の推移
  • 4:別環境での検証
  • 4.1:データを検証
  • 4.1.1:スパイクの量が少ない
  • 4.1.2:あんまり特徴がない
  • 5:ありきたりな結論
  • 6:まとめ
関連するこちらの記事もオススメ

MySQLでINSERTが遅い

おそい！おそい！おそい！

ノートパソコンにDockerでコンテナを立ててろくでもないプログラムを開発しているのですが、データを格納するためにデータベースを使うことが多いです。

でもですね、MySQLのINSERTがすごくおそいよ…。とんでもなく遅いです。

遅くなる原因はいろいろあると思うのですが、素人なりにちょっとした検証をしてみました。

タイトルから結論はお分かりになるかと思いますが、もしかしたらなんかの参考になるかもしれません。

ぜひ暇つぶしにどうぞ。

現状の確認

なにが遅いって言われてもよくわからないでしょうから、実際に遅さを晒してみたいと思います。

テスト環境は以下。

  • MySQL稼働環境
  • Docker公式MySQLコンテナ(5.7.12)
  • Docker公式PHPコンテナ(7.0.6-apache)
  • コンテナにメモリ上限・CPU上限は設定していません
  • Dockerホスト
  • OS:GUN/LINUX Debian8
  • CPU: Pentium B980(泣)
  • メモリ:6GB
  • HDD:250GB

以下のようなコードを書いていろいろ動かしてみようと思います。

ランダムで生成した文字列と数列をプリペアードステートメントでINSERTする単純なコードです。簡単な経過時間タイマーを挟んでINSERTの経過時間を測れるようにしています。

少ない量のINSERTではどんな感じになるかです。100件からテストぉ~。

インサートに3.9636571407318秒かかりました

100件で4秒かかる…遅いよね？これ。100件でこれだから先が思いやられるぜ。

では1000件いってみよう。

インサートに41.069952011108秒かかりました

ああ…。大体10倍じゃないか…。なんならちょっとおまけ付いているし。なんかもう10000件も結果は目に見えているな…。次は400秒ですか？すでにカップラーメン待機時間 を優に越してますよ？

では10000件です…。

インサートに429.5260488987秒かかりました

まじかよ。400秒超えちゃっているよ。件数が増えるごとにマシマシじゃないかい。こんなに時間掛かるの？ウル(ry…。

さてやりたくもないですが、一応100000件をやっておきましょう…。間違いなく一時間以上かかるよね…。

インサートに4290.681718111秒かかりました

10000件のまんま10倍じゃんか。もう少し増えるのかと思ったけど。

さて一応各件数を10回ずつやってみて平均を出してみました。100000件10回やったら10時間以上かかりましたよ…。

ただどの件数もほとんど毎回、秒数が変わらずブレることがなかったです。そういう意味では安定していますね。

改めて表にしてみました。

INSERT件数 経過時間(10回平均) 100件時経過時間を基準にした場合のINSERT1件毎コスト
100件 3.98秒 100%
1000件 41.0秒 103%
10000件 429.6秒 107%
100000件 4290.6秒 108%

こうしてみると件数が増えると、少しずつINSERT1件あたりのコストが増加する傾向があるようですね。

これって件数が増すごとに効率が悪くなるということですよね。メモリの使用量とかに関係あるのかな？

時間が掛かる理由を考察

素人の邪推ですので無能考察ですが、こんなに遅くては考察せずにいられません。

まずlogを確認してみたいと思います。

実はmy.cnfに以下の記述をいれてlogをとっていました。

general_log = 1                                                                                                                                   
general_log_file = /var/lib/mysql/general.log

これは「一般クエリーログ」というもので、MySQLが内部的に処理したSQLを記録してくれるlogです。

MySQLには別にスロークエリログという、遅い（重い？）クエリを記録するlogもありますが、今回は1件1件のINSERTが遅いわけではないので、用途としてはあまり役に立たなかったので…。

一般クエリーログの中身

さて一般クエリーログには実行したクエリがズラッと並びます。

2016-04-29T03:54:48.397347Z  120 Connect    root@172.17.0.3 on testdb using TCP/IP
2016-04-29T03:54:48.397806Z  120 Query  CREATE TABLE IF NOT EXISTS testdb.inserttest (
        id int NOT NULL AUTO_INCREMENT PRIMARY KEY,
        cipher text COLLATE utf8mb4_general_ci NOT NULL,
        numbers int NOT NULL
    ) ENGINE=InnoDB
2016-04-29T03:54:48.398189Z  120 Query  TRUNCATE TABLE testdb.inserttest
2016-04-29T03:54:48.589870Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('ubkxvhzz', 49968446)
2016-04-29T03:54:48.623271Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('wuqlbxwy', 35468813)
2016-04-29T03:54:48.656612Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('mxsnftyh', 71472222)
2016-04-29T03:54:48.733247Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('wdgdyqgm', 26972414)
2016-04-29T03:54:48.801567Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('jgiubvxg', 46285974)
2016-04-29T03:54:48.835137Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('wgrcquak', 87428660)
2016-04-29T03:54:48.868555Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('irtqsxwt', 33006945)
2016-04-29T03:54:48.902010Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('esudinex', 53510753)
2016-04-29T03:54:48.935468Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('gyahveex', 79988357)
2016-04-29T03:54:48.969347Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('sxumycqx', 16392670)
2016-04-29T03:54:49.002476Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('nvtabgun', 50932736)
2016-04-29T03:54:49.036079Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('wkrdiimq', 68907608)
2016-04-29T03:54:49.069494Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('vyfumwml', 75924991)
2016-04-29T03:54:49.103361Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('kacigmxh', 32306552)
2016-04-29T03:54:49.136339Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('udxdobbd', 21351223)
2016-04-29T03:54:49.174059Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('urdxpgtb', 63325929)
2016-04-29T03:54:49.214546Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('sqjgdgrh', 51020142)
2016-04-29T03:54:49.248166Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('awckumft', 95404717)
2016-04-29T03:54:49.281490Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('orokhsfw', 74060032)
2016-04-29T03:54:49.314998Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('gzcritfy', 71167886)
2016-04-29T03:54:49.348426Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('dtosxtti', 43605821)
2016-04-29T03:54:49.381899Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('wcgjrdgn', 52963458)
2016-04-29T03:54:49.415379Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('fuhtxdfw', 95560976)
2016-04-29T03:54:49.448864Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('adrwtlqi', 52981588)
2016-04-29T03:54:49.482252Z  120 Query  INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('badzlypr', 97461706)

軽く説明ですが、クエリ実行時間、コマンドID（例では120っての）実行したqueryの順で並んでいます。

例では最初にConnectがあって、これはPDOの

$pdo = new PDO($dns, $usr, $pas);

に相当する箇所です。その次にテーブル作成のSQLとTRUNCATEのSQLが実行されています。これは今回の経過時間とは関係が無い部分です。

その次からがINSERTがズバッと続いています。

INSERT INTO testdb.inserttest (cipher, numbers) VALUE ('badzlypr', 97461706)

for文でぶん回したquery　がぞくぞくと実行されています。これが今回の経過時間で計っている部分です。

データを検証

さてそれでは集計しやすく量もそれなりな1000件INSERT時のlogを元に少し詳しく見てみます。

まず1件あたりのINSERTのコストの集計です。

最大値 最小値 平均値 中央値
0.5697106481秒 0.0278553241秒 0.0480243067秒 0.0391620370秒

最大値とんでもないことになっていますな…。逆に最小値は平均や中央値と比べるとそんなに小さくない感じです。

どうやら@MINOのシステムでは0.027秒/クエリというのが速さの限界値なのかもしれません。

さて1000件のデータをのせるのは縦に長くなりすぎるので、グラフにて。

＠MINOはもっと平坦なグラフを予想していたのですが、随分特徴のあるグラフになっています。

スパイクの存在

まず1つめとしてスパイクになっている部分が結構ある点です。

最大値を見ていただければわかる通り、えらい時間がかかっているINSERTがあります。そしてそれは後半につれて多くなっている様に見えます。

INSERTの量が増えるとこのようなスパイクの発生も増えるということのようで、件数が増えることにコストが増加することが視覚的にもわかった気がします。

矩形波様の推移

2つめですが、このグラフは矩形波にとても似ています。

＠MINO趣味でシンセサイザーを弾いたりするのですが、矩形波は凸凹と規則正しい波形で、ポーっというような感じの音がなりますよ。木管楽器の波形は矩形波に近いとか言われています。関係ないですけど。

この矩形波パターンがなぜ起きるのかはわかりませんでした。たまたま＠MINOの環境でこういう結果になっただけなのかもしれませんし、こういった挙動が普通なのかもしれません。

非常に規則的で視覚的にはスパイクとは別に存在している特徴のように思えます。ディスクの書き込みとかもこういった感じの速度分布になるようなグラフを見たことがあるような無いような…。

低い部分平均 高い部分平均
0.0398~0.041 0.05

別環境での検証

さて@MINOはの腐ったパソコンだけでは検証にならんので、レンタルサーバでもやってみます。Conohaクラウドを使ってみました。

  • MySQL稼働環境
  • Docker公式MySQLコンテナ(5.7.12)
  • Docker公式PHPコンテナ(7.0.6-apache)
  • コンテナにメモリ上限・CPU上限は設定していません
  • Dockerホスト
  • Conoha
  • CPU2コア
  • メモリ1GB
  • SSD50GB

コードは先ほどと同じです（接続情報以外は）

とりあえず100件

0.092894077301025秒かかりました

ん？ものすごく早いぞ？

1000件では

0.93638491630554秒かかりました

あう…。速度ぜんぜんちゃうやんけ…。1000件でも1秒掛かってないぞ…。@MINOの腐れノートパソコンでは1000件が40秒ですから、40倍以上の速度ですな。

10000件では

9.6642940044403秒かかりました

速度差は量が増えても変わらないですな。

100000件では

100.56400489807秒かかりました

@MINOの腐れノートパソコンでは1時間以上かかっていたのに…。

件数毎の結果をまとめました。

INSERT件数 経過時間(10回平均) 100件時経過時間を基準にした場合のINSERT1件毎コスト
100件 0.0928秒 100%
1000件 0.9363秒 100.7%
10000件 9.6642秒 104%
100000件 100.5640秒 108%

件数が増える毎に1件毎INSERTのコストが増えるのはさっきと同じのようです。

ただ@MINOのノートパソコンと比べると雲泥の差ですね。

データを検証

さっきと同じように1000件INSERT時のlogを検証してみます。

1件あたりのINSERTのコストの集計です。

最大値 最小値 平均値 中央値
50.0462963015647ナノ秒 5.05787037252681ナノ秒 10.8325609481811ナノ秒 10.9490740918261秒

先ほどでは単位が「秒」でしたが、今回は「ナノ秒」ですのでご注意を。平均で10.8ナノ秒でINSERTを処理しているようです。

さてグラフです。

スパイクの量が少ない

見るからにスパイクの量が少ないですね。グラフ自体はギザギザしていますが、パッと見のスパイクは3~4個くらいです。

また先ほど＠MINOのノートと違い、後半にスパイクが多くなるという傾向も見られません。

かなり速度を保っている印象です。

あんまり特徴がない

先ほどのグラフより特徴的ではないですね。さっきのはかなり特徴的に矩形波様になっていましたので、ちょっと期待していた感じとは違いました。

なんとなく視覚的には周期があるようなないような、矩形波様にみえなくもないですが…。

気のせいですか。

ただ@MINOのノートの時の矩形波様のグラフはあくまで@MINOのノートパソコン上での特徴のようですね。

あの矩形波がこちらでも顕著にでたらおもしろかったのですが（なにが？）…

ありきたりな結論

おそらくなんですが、INSERTの速さはストレージの性能が大きく影響しているように感じます。

顕著に違うのってそこなんですよね。

@MINOの腐れノートパソコンのストレージは旧来の5400rpmのHDD、一方ConohaのデフォルトストレージはSSDです。

普通HDDと比べてSSDは書き込みで数倍~数十倍の速さが出るものです。それがそのまま速度差として出ていてもおかしくはないですよね。

今回の検証は元も子もないかもしれませんが「SSDが早い！！」という当たり前の結果なのかもしれません。

もちろん他にも速くなっている要素があると思います。ただメモリはConohaで1GB、＠MINOのノートでは6GB積んでいます。ノートパソコンでは他のアプリもいくつか動いていますが、少くともConohaの方が使えるメモリが多いというわけではありません。

CPUに関してはちょっとベンチマークの仕方がわからなかったので比べていませんが、まさか40倍の差があるとは思えません。（あるの？）

やっぱりストレージの性能差なんだろうな~と一人で納得しています。

まとめ

いやしかし40倍の速度差はかなりビビりました。

今回はMySQLの設定やSQLの書き方でチューニングを行い速度を得るような内容にならなかったので、がっかりした方もおられるかもしれませんが、検証したように、システムが違うとこれほどに差が出る場合があるということは＠MINOには収穫でした。

プログラミングのテスト実行環境もクラウドに移すかと考えている次第です。

だってクラウド借りるの月1000円くらいだもの。それで40倍だもの。

そもそも物理的な速度には抗えないので、まずはハードウエアが最適なのか、次にそのハードを最大限使い切るという心構えが必要ですね。

次回（になるかわかりませんが）はSQLの書き方で速度を確保する方法を試してみたいと思います。

こちらの記事もオススメ