この記事はHamee Advent Calendar 2017の17日目の記事です。

概要

処理が止まる系(または、リロードしてるっぽい挙動がずっと続く)の調査をして見たので抑えていたところをまとめて見た。足りないところがあればコメントお願いします。

前提

ローカルで処理待ちが再現する。
ローカルで再現しない時に本番にログを仕込まねばならず、
調整(社内での政治的なあれこれ・・・)についてはベテランの方にお任せしましょ。

疑うべき点をざっくり

1. ネットワークが遅い

2. クエリが遅い

3. データベース側でテーブルをロックしている（デッドロック)

4. プログラミング言語の処理が遅い

1. ネットワークが遅い

これは言わずもがなかもしれません。

ping -l [データサイズ] [調査するURL]

などで少し大きめのpingを送って見て遅いようならまずこれが原因となっているかも。

2. クエリが遅い

クエリが遅いかどうかは発行されているクエリが見れれば良いです。
スロークエリを出すようにしておけば、基本的には見れるはず。

スロークエリの設定についてはMySQLにログインした状態で

show variables like 'slow%';

例としては以下の通り。

slow_query_log がOFFになっているとスロークエリの出力は行われない。

スロークエリ出力の設定方法

set global slow_query_log_file = '/tmp/mysql-slow.log';
set global long_query_time = 5;
set global slow_query_log = ON;

my.cnfの設定

$ sudo vim /etc/my.cnf

[mysqld]
slow_query_log 
slow_query_log-file = /var/log/mysql/mysql-slow.sql # これらを追加する
long_query_time = 5

設定を変更したら反映させるためにrestartする。

3. データベース側でテーブルをロックしている（デッドロック)

これは実はなってました。パターンもあるので必ずチェックしておく。

まずはデッドロックがログで出力されるかを見る。

show variables like 'innodb_print_all_deadlocks';

設定方法

mysql> set global innodb_print_all_deadlocks=ON;

Query OK, 0 rows affected (0.00 sec)

mysql> show variables like 'innodb_print_all_deadlocks';

my.cnf設定

sudo vi /etc/my.cnf

[mysqld]
innodb_print_all_deadlocks=ON # この行を追加する

4. プログラミング言語の処理が遅い

フロント側

Javascript系統 => for文、while文や処理が重そうなところにtimeを仕込んで計測。またはconsole.logで中身を表示させることで重くなっている原因となりそうな要素がないかを探す。この辺りは自分の中でうまくまとまっていないので後日まとめ出すかも。

フロントエンドデバッグの参考 @mo4_9 さん

バックエンド側

PHP => こちらもMVCフレームワークなど使っていれば、使っている箇所はわかりやすいのでその辺りにログを仕込んでいく。(仕込めるという前提ではある)

最初のログの設計時点でこれをしなくて良いようにするのが最善。

参考(ログ設計指針) @nanasess さん