おれ、エンジニアになるよ。

エンジニア志望の大学生がISUCON7出場を目指す成長日記

第2回模擬ISUCONやりました

こんにちは。

今回は、一昨日行った第2回模擬ISUCONの模様をお届けします。

題材はISUCON5予選問題。

github.com

 

マニュアルがこちら。

ISUCON5予選マニュアル · GitHub

 

そして会場は、沖縄で一番インターネットに近い場所、ぼくらのお師匠さんであるさぼさんの城、ギークハウス沖縄

f:id:matsuda-juri:20170801150732j:plain

 

 

 

前置きはこれぐらいにして、早速内容の方に。

 

 

1.Azure童貞卒業

 

はい、卒業しました。

今回はAWSではなく、さぼさんの提案でMicrosoftのAzureを使いました。

 

ってことでAWSと同じく、サーバーにSSHでログインできるユーザーとしてマサとディックス君を追加します。

 

.ssh下にあるauthorized_keysに、2人の公開鍵を登録します。

これでおっけー。

 

 

 

2.ログファイルの設定

 

前回のハッカーズチャンプルーで行ったpixivさんの第1回模擬ISUCON同様、ログファイルの設定を行なっていく。

過去記事にて割愛。

 

matsuda-juri.hatenablog.com

 

 

Nginxのログファイルは前回よりスムーズにできた。

「}(閉じ括弧)」忘れによるエラーが出たこともあったけどww

 

mysqlは、myprofilerを使ってのスロークエリの監視が最後までできなかった。

原因は、ディックス君がインストールしたものが古いバージョンだったためww

バージョンって大事ね。

 

 

 

3.ボトルネックはどこだ!?

 

とりあえずnginxのログtopコマンドで怪しそうなところを探った。

 

f:id:matsuda-juri:20170801164421p:plain

 

まずはnginxのaccess.log。

alpで整形したらこんな感じ。

下のほうを見ていくと、

 

f:id:matsuda-juri:20170801164551p:plain

 

ん、何か重そうなのがある!?

/initializeとはなんぞや。

 

get '/initialize' do
db.query("DELETE FROM relations WHERE id > 500000")
db.query("DELETE FROM footprints WHERE id > 500000")
db.query("DELETE FROM entries WHERE id > 500000")
db.query("DELETE FROM comments WHERE id > 1500000")
end

 

初期化を行なってるみたい。

でもなんだろう、なんかイケてない感じがするのはぼくだけだろうか。

 

とりあえずもうちょっとログ見てみることに。

 

f:id:matsuda-juri:20170801165009p:plain

 

お、"/"がなんか大変だぞ。

ってことでソースコードに。

 

get '/' do
authenticated!

profile = db.xquery('SELECT * FROM profiles WHERE user_id = ?', current_user[:id]).first

entries_query = 'SELECT * FROM entries WHERE user_id = ? ORDER BY created_at LIMIT 5'
entries = db.xquery(entries_query, current_user[:id])
.map{ |entry| entry[:is_private] = (entry[:private] == 1); entry[:title], entry[:content] = entry[:body].split(/\n/, 2); entry }

comments_for_me_query = <<SQL
SELECT c.id AS id, c.entry_id AS entry_id, c.user_id AS user_id, c.comment AS comment, c.created_at AS created_at
FROM comments c
JOIN entries e ON c.entry_id = e.id
WHERE e.user_id = ?
ORDER BY c.created_at DESC
LIMIT 10
SQL
comments_for_me = db.xquery(comments_for_me_query, current_user[:id])

entries_of_friends = []
db.query('SELECT * FROM entries ORDER BY created_at DESC LIMIT 1000').each do |entry|
next unless is_friend?(entry[:user_id])
entry[:title] = entry[:body].split(/\n/).first
entries_of_friends << entry
break if entries_of_friends.size >= 10
end

comments_of_friends = []
db.query('SELECT * FROM comments ORDER BY created_at DESC LIMIT 1000').each do |comment|
next unless is_friend?(comment[:user_id])
entry = db.xquery('SELECT * FROM entries WHERE id = ?', comment[:entry_id]).first
entry[:is_private] = (entry[:private] == 1)
next if entry[:is_private] && !permitted?(entry[:user_id])
comments_of_friends << comment
break if comments_of_friends.size >= 10
end

friends_query = 'SELECT * FROM relations WHERE one = ? OR another = ? ORDER BY created_at DESC'
friends_map = {}
db.xquery(friends_query, current_user[:id], current_user[:id]).each do |rel|
key = (rel[:one] == current_user[:id] ? :another : :one)
friends_map[rel[key]] ||= rel[:created_at]
end
friends = friends_map.map{|user_id, created_at| [user_id, created_at]}

query = <<SQL
SELECT user_id, owner_id, DATE(created_at) AS date, MAX(created_at) AS updated
FROM footprints
WHERE user_id = ?
GROUP BY user_id, owner_id, DATE(created_at)
ORDER BY updated DESC
LIMIT 10
SQL
footprints = db.xquery(query, current_user[:id])

locals = {
profile: profile || {},
entries: entries,
comments_for_me: comments_for_me,
entries_of_friends: entries_of_friends,
comments_of_friends: comments_of_friends,
friends: friends,
footprints: footprints
}
erb :index, locals: locals
end

 

 

"/"のモリモリ感がすごい。

ここでとりあえずベンチマークを走らせるのだが、同じようなクエリがめっちゃ走ってることに気づく。(キャプチャするの忘れてました。)

この時思ったのが、「N+1問題」

 

確信はなかったが、DBのボトルネックになりがちなのがどうやらこの「N+1問題」らしい。

qiita.com

 

ここも臭いと思いつつももうちょい探る。

"/"に戻るけど、このブロック内で使われてるメソッドを見てみる。

やはり臭そうなところがあった。

 

def get_user(user_id)
user = db.xquery('SELECT * FROM users WHERE id = ?', user_id).first
raise Isucon5::ContentNotFound unless user
user
end

 

f:id:matsuda-juri:20170801170537p:plain

 

topコマンドからもわかるように、mysqlがまず最初のボトルネックだったみたい。

 

第1回模擬ISUCONで学んだのは、

「DBから取ってくる情報は必要なやつだけ」

 

この get_userメソッドではユーザー情報を全部取ってきてるのがイケてない。

よって、"/"がモリモリになっちゃうって予測。

 

とりあえずキャッシュさせてみるが変わらず。(試しにやってみただけww)

 

次にやろうとしたのがsql文の書き換え。

さっきの「N+1問題」の記事に書いてあるが、テーブル同士をJOINさせようというもの。

 

なんですが、ここで終了間際wwwww

「ベンチ行ってらっしゃぁぁぁぁい!!!」

 

f:id:matsuda-juri:20170801172547p:plain

 

19.8点wwwwwwwwwwwwwwww

しかもタマキって誰や。勝手に出てくんなよ。

 

最後にもう一回ベンチ走らせるが、最悪の0点.....。

キャプチャはあえて憚らさせていただきます....。

 

 

............................終了。

 

 

 

4.反省

 

最初のサーバー立ち上げはスムーズにできたのでよかったかなと。

ユーザー追加も難なくできたので、前回のAWS触った経験が活きててよかった。

あとはもっと早くできるようになること。

 

実際のチューニング作業に移るまでに相当の時間がかかった。

それもログファイルの設定。

バージョン違いによる動作不良は、本番では勘弁したい。

よってここの設定をいかに早くできるかが重要。

そもそもボトルネックはまずぼくらにあった感じwww

 

第2回模擬ISUCONのソースコードは初見。(本番環境とほぼ同じ)

じっくりソースコードを読んでる時間はないので、やはりログ解析をしっかり行えることが先決かな。ログは嘘つかないので。

 

個人的に、今回はエディタを使わずにvimを使ってイジイジしてた。

こうでもしないと慣れないのでwww

結果的にまぁまぁ使えるようになったのでよかったかな。

 

あとは、分業できるところは分業させて効率化を図りたいところ。

なんだけど、やはり初歩的なミスがまだ多いので、お互いフォロー・チェックし合いながらの方がよさそう。

 

 

とまぁ、こんな感じです。

スコア0はさすがに面喰らったwww