あいつの日誌β

働きながら旅しています。

ISUCON6 予選を今年も無事敗退しました

ブログに投稿するまでが ISUCON なので書き記します。

チーム名: パジャマ飯 最終スコア: 15000 前後

当日の流れ

時刻 行動 詳細 スコア
9:00 起床 - -
9:30 朝ごはん - -
10:00 スタート - -
10:15 VM を起動し SSH でログインできるようになる - -
10:25 ベンチマーク実行 Perl 300 前後
10:30 BitBucket での管理 - -
10:35 アプリ構成を確認 Nginx:80 -> Isuda:5000, Isutar:50001 -> MySQL -
10:40 計測コードを追加 - -
11:00 処理が重い箇所をピックアップ GET /, htmlify, POST /stars -
11:30 ベンチが走りきらないので対処を開始 POST /login, GET /keyword がタイムアウトしている -
12:00 POST /login の対処 random_string を都度生成するのをやめる 3000
12:30 POST /keyword の対処 keyword と description をつなげて is_spam_contents へのリクエストを2回から1回にする 3366
13:00 POST /keyword の対処 keyword_length を追加(これは後で Revert) 3000 前後
13:30 POST /keyword の対処(Revert) そもそもベンチが走りきっていない事に疑問を抱く 3000 前後
14:00 top コマンドでプロセスの挙動を調べる perl の worker 数が少ない事に気づく -
14:30 Isuda の Woker数を増やす 5 -> 15 9488 前後
15:00 htmlify の対処 keyword だけを selectするように修正 14834
15:15 GET / の対処 entry の updated_at にインデックスをつける 15869
15:30 POST '/stars' の対処 keyword の有無だけを確認する API を追加 16685
15:45 set_name の対処 user テーブルを Redis 化 18044
16:30 htmlify の対処(2) sha1 使わずに keyword.id にしようとする -
17:50 アクセスログを出力しないようにする MySQL と Nginx の conf を修正。なぜかスコアが落ちる? 15000前後
18:00 終了 - -

使用した言語: Perl

私は業務で使用してきた言語が経歴が長い順に Perl, Node.js, Python となっているのと前日に ISUCON5 予選の練習をした時に Perl で練習したので今回は Perl を選択しています。

あと今回負荷を計測する方法として Perl の DESTROY 関数を使いたかったというの理由の一つです。Prefork しておいたプロセスが一定期間で役目を終えて kill されるので、そのタイミングまで経過時間をプロセス内に保存しておき kill されるタイミングで DESTROY にエラー出力に経過時間を吐き出す関数を用意し臨みました。

/var/log/syslogtail -f していると時々その情報が出てくるのでそれを眺めながら予選に臨みました。

10:00 -> 15:00(スタート地点に立つまで)

事前に何度か練習していたため portal.azure.com での作業は割と順調で無事 SSH でログインして作業開始までスムーズに行えました。

最初に MySQL の databases に isudaisutar が存在しているのを確認し、nginx.conf を見ておそらくこのような構成だろうなという予測をしました。

nginx -> /     :5000 isuda.psgi  -> MySQL
      -> /star :5001 isutar.psgi -> MySQL

実際には後 localhost:5050 がいたのですがこの時点ではまだ気づいていませんでした。

ベンチマークを実行すると POST /login, POST /keyword, GET /starsタイムアウトしているとのメッセージが表示されます。

また、前述の計測ツールから GET /, htmlify, POST /stars の処理に時間がかかっているようです。なんですがこれはあくまでベンチが走りきっていないので参考になっているか分かっていませんでした。

まずはベンチが走りきらないといけないのですが、ベンチマークタイムアウトしている箇所を順番にソースコードの改修を行いました。これは大幅にタイムロスしました。

ソースコードを改修してもなかなかベンチマークツールが走りきらないので他に原因があるのではないかと思い top -c コマンドをよくよく見てみると Perl の worker 数が少ない気がしました。

isuda の worker 数を 5 -> 10 にすると点数が跳ね上がりベンチマークツールが完走しました。さらに 15, 20 と試して最終的に 15 に設定して数値が 9488 をマークしました。

真っ先に worker 数を増やしておけばベンチマークツールが完走するので負荷の高い場所を重点的に修正できたのですが、ベンチマークツールを完走させるために is_spam_contents でのリクエストを keyword, content を結合して2回のリクエストを1回にするなど、序盤は比較的負荷の少ない部分の改修(そうだと知りつつもベンチマークが回りきらないと話にならないので)を頑張っていました。

というわけで開始5時間経過してやっと ISUCON6 のスタート地点に立つ事ができました。

15:00 -> 16:00(順風満帆)

というわけで後は以下の通り順調に作業が進みました。

時刻 行動 詳細 スコア
15:00 htmlify の対処 keyword だけを select するように修正 14834
15:15 GET / の対処 entry の updated_at にインデックスをつける 15869
15:30 POST '/stars' の対処 keyword の有無だけを確認する API を追加 16685
15:45 set_name の対処 user テーブルを Redis 化 18044

本当はまだまだ改修したいポイントはあったんですが、いかんせん手がたりない。

当初の予定では16:00以降は MySQL, Nginx の設定を修正したり VM 再起動した後にちゃんと動くかどうかの確認をしてコードをいじらない予定でした。

なんですが 16:00 ぐらいまでリーダーズボードに少しだけ登場したりしていたのでなんとなく欲がでてきました。そして後際立って重い処理である htmlify が残っていました。こちらの改修ポイントは以下の2点

A: 1プロセスがここの処理を 2 秒前後時間かかっている keyword を取得する処理と

my $keywords = $self->dbh->select_all(qq[
  SELECT keyword FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC
 ]);

B: 1プロセスがここの処理を 10 秒以上時間かかっているここの処理

$content =~ s{($re)}{
  my $kw = $1;
  $kw2sha{$kw} = "isuda_" . sha1_hex(encode_utf8($kw));
}eg;

せっかくのチャレンジだったので、残り時間は B のために全部使いました。うまくいけば大幅なスコアアップが望めるかも...

で、残念ながら結果が出ませんでした。sha1_hex しないで id そのまま使えばいいんじゃないかと思ったんですがあんまり速くならず。

感想

今回の目標は負荷の高い処理を計測して、そこにちゃんと対処する。という事がちゃんとできるかどうかを自分に課していました。

とりあえず幾つかはボトルネックを発見して修正する事ができました。なんですが序盤でソースコードばかり見すぎていて OS のリソースがどれぐらい利用されているかなどなどを全く見ていなかったのは反省点です。

あと終盤で htmlfiy で経過する時間が大きいからその関数自体を速くしようとしてしましましたが、そもそもその関数を呼び出している箇所がどこで、何度もそこを呼ぶ必要が本当にあるのか?という点を考慮しませんでした。視野が狭くなっていたのが反省点です。もういいおっさんなので目先の事よりももっと遠く、広く見渡せるようにならないとなあ。

とはいえ今回も楽しめて、いっぱい知識的なお土産を手に入れる事ができました。このような機会を今年も提供していただいた運営者と出題者の皆さまありがとうございました。あとはベンチマークツールが公開されたらしっかり復習したいと思います。