mattsu6666/isucon4

isucon4's Issues

pprofによるProfiling

net/http/pprofによるprofiling

概要

Webアプリ部分のprofilingをし, 上層から全体のどれに時間がかかっているかを特定
使うツールはこちら　https://github.com/google/pprof

usersテーブルのオンメモリ化

概要

/loginにリクエストが来ると，有効なユーザかどうかをチェックするためにMySQLを参照しているが，新規ユーザの登録やユーザ情報の変更は発生しないので，全てメモリ上で管理する

修正箇所

• db.go#getCurrentUserのロジックをメモリから参照するように置き換える

func getCurrentUser(userId interface{}) *User {
	user := &User{}
	row := db.QueryRow(
		"SELECT id, login, password_hash, salt FROM users WHERE id = ?",
		userId,
	)
	err := row.Scan(&user.ID, &user.Login, &user.PasswordHash, &user.Salt)

	if err != nil {
		return nil
	}

	return user
}

MySQLの参照をメモリに切り替えることでパフォーマンスを改善を見込めるが，重いクエリではないので，インパクトは少ないかもしれない

アプリケーションのリモート化

概要

アプリケーションをGCPにデプロイし, 環境依存しないようにする。

問題

• 現状ベンチマークの結果が各開発者の環境に依存する.
• そもそも環境が本番環境のスペックに合っていないのでそこを合わせる必要がある.

方策

GCPが一年間無料だそうなのでインスタンスを立てる
インスタンス1：アプリケーション・サーバー用の1コア1GBのインスタンス.
インスタンス2：ベンチマークサーバー(スペックは検討).

懸念

ベンチマークサーバーとアプリケーションサーバーのリージョンは分けたほうが良い？
理由はこの２つが同じリージョンであるとネットワークが強固すぎてgzip等の圧縮の効果が消えるため

ISUCONの準備と始まったらやること

準備

• 水風呂・サウナ

やること

• nginxの設定変更
• Redisインストール

BAN IPの特定ロジックが非効率な問題

概要

BANされたIPを判定するロジックの効率が悪いため，改善したい．
また，どのように効率が悪いかを示す

BAN判定の現状のロジック

• BAN判定はログイン時に発生し，ログインの失敗回数が一定回数を超えるとBAN扱いになる

具体的な流れ

1. usersテーブルからloginカラムによってユーザ情報を取得
2. login_logテーブルから最後にログインに成功してから今回のログインまでの失敗した回数を取得
3. ログインの失敗回数が特定回数以上(IPBanThreshold以上)の場合はBANとして扱う

問題点

BANかどうかの判定をするためのクエリにインデックスが効いてない上，クエリ自体が鈍足．BAN情報をわざわざログから判別するのも良くない

• 該当クエリ

SELECT COUNT(1) AS failures FROM login_log WHERE ip = ? AND id > IFNULL((select id from login_log where ip = ? AND succeeded = 1 ORDER BY id DESC LIMIT 1), 0);

エビデンス

• アプリのプロファイリングを行うと，futex/usleepによるIO待ちがボトルネックになっている

(pprof) top1000
Showing nodes accounting for 14.36s, 81.50% of 17.62s total
Dropped 577 nodes (cum <= 0.09s)
      flat  flat%   sum%        cum   cum%
     4.22s 23.95% 23.95%      4.45s 25.26%  syscall.Syscall
     3.28s 18.62% 42.57%      3.28s 18.62%  runtime._ExternalCode
     1.49s  8.46% 51.02%      1.49s  8.46%  runtime.futex
     0.95s  5.39% 56.41%      0.95s  5.39%  runtime.usleep
     0.54s  3.06% 59.48%      0.84s  4.77%  syscall.Syscall6

• 効率の悪いクエリ

mysql> explain SELECT COUNT(1) AS failures FROM login_log WHERE ip = "127.250.0.247" AND id > IFNULL((select id from login_log where ip = "127.250.0.247" AND succeeded = 1 ORDER BY id DESC LIMIT 1), 0);
+----+-------------+-----------+-------+---------------+---------+---------+------+------+-------------+
| id | select_type | table     | type  | possible_keys | key     | key_len | ref  | rows | Extra       |
+----+-------------+-----------+-------+---------------+---------+---------+------+------+-------------+
|  1 | PRIMARY     | login_log | range | PRIMARY       | PRIMARY | 8       | NULL |   57 | Using where |
|  2 | SUBQUERY    | login_log | index | NULL          | PRIMARY | 8       | NULL |    1 | Using where |
+----+-------------+-----------+-------+---------------+---------+---------+------+------+-------------+
2 rows in set (0.00 sec)

解決策

その① - Redisの使用

Redisを使用し，IP毎の最新のログイン失敗回数を記録する
失敗回数を知るために，Redisに問い合わせるだけで良いため，効率が良い

その② - BAN情報をテーブルに持たせる

BANされていることを示すカラムをusersテーブルに追加する．
BANされているかどうかはアプリ側の設定値にてコントロールする必要があるため，あまり実用的ではないが，ISUCONにおいては既定値は変わらないので有効

Lockユーザの特定ロジックが非効率な問題

概要

Lockされたユーザを判定するロジックの効率が悪いことを示す
概ね#6 と同等の問題を抱えており，同等の方法で解決可能と思われる

nginxの設定

https://gist.github.com/koudaiii/386eb55a29b1adc19c5e

こちらの記事を参考にしてnginxの設定を良くしてみる

/mypageを参照する予定が/が返って来ている問題

概要

/loginにて有効なusernameおよびパスワードを受け取ったにもかかわらず/を返してしまっている問題.

仮説

/mypageを見るためにはattemptLoginにてErrorが発生しないことが条件である。
今回はattemptLoginにて正しいユーザーにもかかわらずこれらのエラーが起きていることが要因であると考えられる.
Errorが発生する条件は以下の通り
Banされた: ErrBannedIP
ロックされた: ErrLockedUser
Passwordの違う: ErrWrongPassword
loginNameの存在しない: ErrUserNotFound

上記の事から以下のことが考えられる

• あるユーザーに対して他のユーザーの結果を返してきてしまっている
  ** mysqlの非同期処理速度がリクエスト速度に負けている

方策

どのエラーが発生しているかを確認し、事象を捉える.
mysqlのクエリ速度改善, 同期的処理の追加

nginx conf設定

nginxのconfを設定する

worker process の数などをautoに設定

自動デプロイ

概要

Githubからのデプロイや自動ベンチマークができると理想
最悪，手動でやればいいので優先度は普通

logijn_logの初期データのRedisにロードする機能の追加

概要

#6, #7 のissueに関連して，開発が必要となる．
上記のissueはlogin_logをRedis化し，パフォーマンス改善を目的にした修正となる．そのため，ログインが試行された場合にはRedisへのIOを行う．しかし，ベンチマーク時には予め，ダミーデータを読み込んで置く必要がある．

詳細

• dummy_log.sqlをinit.shにてRedisに反映するバッチを用意する

Redis移行はパフォーマンスにインパクトがあると考えられるので，優先度はhigh

login_logの書き込みが同期実行されている問題

概要

login_logの出力は同期実行されているため，効率が悪いと考えられる．
とはいえ，ログ書き込み程度はそんなに問題にならなそうなので，とりあえずラベルはlowにしといた．

現状のロジック

• attemptLoginの実行終了時にcreateLoginLogを実行し，ログインログを出力する

問題点

• 同期実行になっているので，ログの書き込みを待つ必要がある

defer func() {                                            
	createLoginLog(succeeded, remoteAddr, loginName, user)
}()                                                       

エビデンス

解決策

その① - Redis化によるlogin_logの削除

#6 で示される方法を実施すれば，login_logをMySQLに書き込む必要が無くなりそう

その② - 非同期化

• go修飾子をつけて別スレッドで実行する

usersテーブルの改善

概要

usersテーブルの構成とそれに対するクエリを見直す．
loginカラムを使った検索をしているが，該当カラムにはインデックスがなく，
さらに文字列で検索しているためパフォーマンスがでない原因と思われる

エビデンス

• アプリのプロファイリングを行うと，futex/usleepによるIO待ちがボトルネックになっている

(pprof) top1000
Showing nodes accounting for 14.36s, 81.50% of 17.62s total
Dropped 577 nodes (cum <= 0.09s)
      flat  flat%   sum%        cum   cum%
     4.22s 23.95% 23.95%      4.45s 25.26%  syscall.Syscall
     3.28s 18.62% 42.57%      3.28s 18.62%  runtime._ExternalCode
     1.49s  8.46% 51.02%      1.49s  8.46%  runtime.futex
     0.95s  5.39% 56.41%      0.95s  5.39%  runtime.usleep
     0.54s  3.06% 59.48%      0.84s  4.77%  syscall.Syscall6

• 効率の悪いクエリが実行されている

mysql> EXPLAIN SELECT id, login, password_hash, salt FROM users WHERE login = "isucon1";
+----+-------------+-------+-------+---------------+-------+---------+-------+------+-------+
| id | select_type | table | type  | possible_keys | key   | key_len | ref   | rows | Extra |
+----+-------------+-------+-------+---------------+-------+---------+-------+------+-------+
|  1 | SIMPLE      | users | const | login         | login | 767     | const |    1 |       |
+----+-------------+-------+-------+---------------+-------+---------+-------+------+-------+
1 row in set (0.00 sec)