Jumper の新着ステージのロードが異常に遅いです。

待てども、待てどもステージ一覧が表示されない。
しまいにはタイムアウトしてしまう。

どうしよう。。。

プログラムが遅い原因

そんなときに、考えるべきはこちら。

プログラムが遅い原因は、主に以下の2つです。

• データの取得が遅い
• データの処理が遅い

まず、1つめ。「データの取得が遅い」。

データ容量が重かったり、複雑な命令によって
データを取りにいったりすると遅くなります。

コンピュータの仕組みを考えると解るのですが、
CPU の中での処理は一番早く、そこから、
メモリに行って、HDD(SSD)に行くわけです。

CPU がナノ秒での世界だとすると、
メモリはマイクロ秒の世界、
そして、HDD(SSD)はもうミリ秒の世界になります。

極力、大きな容量のデータや、複雑なロジックで、
データをこねくり回して取るような方法は、
避けて通りたいものです。

次に、2つめ。「データの処理が遅い」。

取ってきたデータを複雑な処理で加工したり、
何段階にもネストしたループの中で処理したりすると遅くなります。

今回は、2つめではないことが、
わかっています。Haskell というコンパイラ型言語で、
書かれたプログラムでそもそも、めちゃくちゃ早いです。

さらに、ステージのロードは、ループもせいぜい２段階しか
必要のないシンプルなプログラムです。

よって、今回は、1を最初に疑うことになりました。

スロークエリログを取る

そして、データを取ってくるところですが、
Jumper は DB に MySQL を採用しているので、
MySQL での遅い場所を探らないといけません。

それには、スロークエリログ(slow query log)が役に立ちます。

文字通り、遅いクエリを記録しておくためのログです。

/etc/my.cnf の [mysqld] セクションの中に、

slow_query_log=ON
long_query_time=1
slow_query_log_file=/var/log/mysql/mysql_slow.log

などと書けばよいです。

long_query_timeは、
何秒以上かかったら記録するというもので、
今回は、1秒にしてあります。

slow_query_log_fileは、
ログを保存する場所です。

この設定を採用する場合は、
/var/log/mysqlディレクトリがあることを確認してください。

そして、

service mysqld restart

などとして、MySQL を再起動です。

そして、アプリを動かしながら、 /var/log/mysql/mysql_slow.log を監視します。

tail -f /var/log/mysql/mysql_slow.log

とすると、便利です。

そして、しばらくすると。。。

お、早速、なんかでた。

# Time: 2016-08-18T07:26:15.137652Z
# User@Host: xxx[xxx] @ xxx []  Id:    xxx
# Query_time: 35.089036  Lock_time: 0.000472 Rows_sent: 7  Rows_examined: 123919
SET timestamp=1471505175;
SELECT s.id, ... , 
    (SELECT COUNT(1) FROM plays p WHERE s.id = p.stage_id AND p.player_id = 1 AND p.is_successful = 1 AND p.is_test = 0 LIMIT 1) AS is_cleared,
    (SELECT COUNT(1) FROM plays p WHERE s.id = p.stage_id AND p.is_test = 0 AND p.created_at >= DATE_SUB(NOW(), INTERVAL 7 DAY)) AS recent_plays_count, ...
FROM stages s 
    LEFT JOIN users u ON u.id = s.author_id
    LEFT JOIN stage_summaries ss ON ss.stage_id = s.id 
WHERE 1=1 AND s.is_published = 1 AND s.is_deleted = 0 AND s.version <= 2.2 AND s.author_id != 1
GROUP BY s.id ORDER BY s.updated_at DESC LIMIT 0,7;

35秒もかかっている。これが原因ですね。
ステージがいつまでたっても表示されないわけです。

スロークエリの原因を調べる その１

そして、スロークエリが特定できたら、
次は、スロークエリがなんで遅いのかを、
知らなければいけません。

スロークエリの主な原因は、

• インデックスの貼り忘れ
• クエリ自体が複雑過ぎる

最初の「インデックスの貼り忘れ」はよくある話です。

まずは、インデックス貼り忘れてないかをチェックします。
WHERE句とか、JOIN ON の中で指定されたカラムを一つ一つ見ていきます。

とても地道な作業ですが、がんばりましょう。

今回、張り忘れていたインデックスは、
stages.versionと
stages.updated_atの2つでした。

ということで、

ALTER TABLE `stages` ADD INDEX `stages_version` (`version`);
ALTER TABLE `stages` ADD INDEX `stages_updated_at` (`updated_at`);

しちゃいます。

しかし、今回は、これでは、全然解決しませんでした。
スロークエリは30秒台のまま、いっこうに改善しませんでした。

がっかり。

でも、ここで諦めるわけにはいきません。
ユーザが待っている！！

スロークエリの原因を調べる その２

2つめは、「クエリ自体が複雑過ぎる」ことでした。

ここでは、クエリを複雑にしている要素に関して見てみます。

今回やったことは、実際のサーバで、
部分的にクエリを簡単にして、
実行速度が変わるかを見ていきました。

取っては、実行して、取っては実行してという、
とても地道な作業をしていると、
やっと見えてくるものがありました。

    (SELECT COUNT(1) FROM plays p WHERE s.id = p.stage_id AND p.player_id = 1 AND p.is_successful = 1 AND p.is_test = 0 LIMIT 1) AS is_cleared,

この部分を取り除くと非常に早く結果が返ってくることが解りました。

SELECT の中に SELECT があることがまずかったようです。
それでも、こんなに遅くなるとは不思議ですね。

スロークエリを退治する

遅かったクエリを修正して、

SELECT s.id, ..., cp.is_successful AS is_cleared, 
    (SELECT COUNT(1) FROM plays p WHERE s.id = p.stage_id AND p.is_test = 0 AND p.created_at >= DATE_SUB(NOW(), INTERVAL 7 DAY)) AS recent_plays_count, ...
FROM stages s
    LEFT JOIN users u ON u.id = s.author_id
    LEFT JOIN stage_summaries ss ON ss.stage_id = s.id
    LEFT JOIN plays cp ON s.id = cp.stage_id AND cp.player_id = 1 AND cp.is_successful = 1 AND cp.is_test = 0
WHERE 1=1 AND s.is_published = 1 AND s.is_deleted = 0 AND s.version <= 2.2 AND s.author_id != 1
GROUP BY s.id ORDER BY s.updated_at DESC LIMIT 0,7;

のようにしました。

    (SELECT COUNT(1) FROM plays p WHERE s.id = p.stage_id AND p.player_id = 1 AND p.is_successful = 1 AND p.is_test = 0 LIMIT 1) AS is_cleared,

の部分を

LEFT JOIN plays cp ON s.id = cp.stage_id AND cp.player_id = 1 AND cp.is_successful = 1 AND cp.is_test = 0

として、SELECT の部分を、

cp.is_successful AS is_cleared,

としたわけです。

ほとんど同じ結果を返すクエリですが、
結果はどうなったでしょうか。

めでたし。めでたし

期待の結果は。。。

# Time: 2016-08-18T08:47:03.763935Z
# User@Host: jumper[jumper] @ localhost []  Id:    69
# Query_time: 1.658192  Lock_time: 0.000354 Rows_sent: 7  Rows_examined: 121264
SET timestamp=1471510023;

1.6秒まで改善しました！

そして、ほら、ちゃんと表示できた！

さらに、改善できそうな結果ではありますが、
今回はここまで。

スロークエリ改善の何か手がかりになれば嬉しいです。

この記事を読んだあとに

• 書いた人のツイッター - Follow me!
• 『売上を3年連続20%成長させた18の秘訣』
• 運営しているアクションゲーム