#isucon 8 で 惨敗してきました

以下のレポートは書いてる途中で力尽きてしまい不完全なものです・・・。あらかじめご了承ください。

2018/09/15(土)にISUCON8に参加して、ボロ負けしてきたのでそのレポートです。

SlackでのやりとりやGitHubのコードをベースに、時間ごとに何をやったかをざっくり書いていきたいと思います。

メンバー

@serinuntius アプリケーション・エンジニア

@dozen (会社の同期) インフラ・エンジニア

@kazasiki (会社の先輩) アプリケーション・エンジニア

面倒なので、このレポートでは敬称略とさせていただきます。

10:00~10:30

ポータルログインして、レギュレーションを読む。同時にSSHのコンフィグを書いてました。

次のようなことを確認しました。

  • ベンチマーが側の帯域がかなりでかい!
  • PHPは動かすのにH2Oのコンフィグ書き換えなきゃいけないのか〜大変そうだな〜(まだ、このときはGo実装でもH2Oが動いてるとはしらず・・・。ちゃんと「PHP以外の実装」という言葉がでてきているのにね
  • GET /initialize は10秒以内に返す
  • なお、問題ページの内容はできるだけ最新の状態を反映させる必要がありますが、1秒以内の遅延は許されます。 非同期処理をおすすめするような文言
  • アプリケーションは全て、保存データを永続化する必要があります。 これも気になった。

あと、ポータルを確認すると、ベンチマーカのIPアドレスが1つしか設定できないので、ロードバランスしないといけないんだろうな〜という話はしていました。

僕が alp, pt-query-diegest,dstat,notify_slack を事前に用意してた温かみのあるコマンドの羅列を直接打って入れましたw

僕がGoの初期実装に変更して、ベンチ回すと1194でした。

f:id:serinuntius:20180917083831p:plain

topとかで負荷を確認したところ、すごくMySQLが支配的で、ループとかIndexやばそうだねっていう話をしました。

@kazasiki が、Redisを全台に入れてくれました。

10:30~

@kazasiki のMacがフリーズする

@dozen が ホスト名をつけてくれて、今何でログインしているかとか、通信もisu2とかでいけるようになる。

@dozenがスペックを貼ってくれる

スペック
CPU: 2コア
MEM: 1GB / swap 2GB

@serinuntius が alpの設定をNginxに入れようと思ったら、H2Oで動いていることに気がつく。

H2O全然わからんし、剥がしてNginx(open resty)で行こう!ってなった。

けど、この判断は結論からいうとミスだったかもしれない。 そもそも、H2Oはボトルネックではないし、ちゃんと動いてたし、なんならNginxよりパフォーマンスがいいという話を聞く。 alp形式のログにするのも、ちょっと調べてみるべきだった。

alpでボトルネックを調査して、初動を決めるというムーブが完全にできなくなってしまったので、レコード数の調査やアプリを読むことにした。 @dozenに、Nginx移行を進めてもらいながら、@serinuntius, @kazasikiはアプリを読むという割り振りになった。

MySQLのレコード数やIndexのサイズをパッと出してくれるSQLを、@serinuntiusが出す。

MariaDB [torb]> select
    ->     table_name, engine, table_rows as tbl_rows, avg_row_length as rlen,
    ->     floor((data_length+index_length)/1024/1024) as allMB, #総容量
    ->     floor((data_length)/1024/1024) as dMB, #データ容量
    ->     floor((index_length)/1024/1024) as iMB #インデックス容量
    ->     from information_schema.tables
    ->     where table_schema=database()
    ->     order by (data_length+index_length) desc;
+----------------+--------+----------+------+-------+------+------+
| table_name     | engine | tbl_rows | rlen | allMB | dMB  | iMB  |
+----------------+--------+----------+------+-------+------+------+
| reservations   | InnoDB |   192507 |   57 |    15 |   10 |    4 |
| users          | InnoDB |     5173 |  307 |     1 |    1 |    0 |
| sheets         | InnoDB |     1229 |   53 |     0 |    0 |    0 |
| administrators | InnoDB |      101 |  162 |     0 |    0 |    0 |
| events         | InnoDB |       21 |  780 |     0 |    0 |    0 |
+----------------+--------+----------+------+-------+------+------+
5 rows in set (0.01 sec)

11:00 ~ アプリを読んでみる

@kazasikiとわいわいしながら、「何これ糞すぎ」「なにこれヤバイ」といいながらアプリを読んでいると、いくつかこれは確実にボトルネックになるであろうヤバポイントがあった。

getEvent, getEventsの「N+1」

こんだけの箇所で、getEventが呼ばれていた↓。

f:id:serinuntius:20180917090542p:plain

これを直すだけでも、だいぶ良さそう。

SHA2 の計算をわざわざMySQLに問い合わせて計算してもらっている

それ自体はそんなに重くないかもだけど、回数が多くなるとレイテンシが乗るしかなり無駄。

@kazasiki がざっと読んで、こんなメモを残していた。(原文ママ

* [ループクエリ]func getEventsからfunc getEventを読んでいて、getEvent内でsheetsやreserveを引いてる

* 455行目totalPriceが毎回reserveをgroupbyしてsum()してるからまずい

* 385行目/509行目でpasswordのsha2変換をmysqlにやらせている

* 517行目でuserをもう一回引いてるけど無駄?

* 533行のsanitizeEventはオブジェクトコピーがいらない気がする

• 167行目のgetLoginUserが毎回ユーザ情報をdbから引いている

11:30〜

@dozenのNginxへの移行が終わり、やっとalpでの集計ができた。 ちなみにNginxへ移行してスコアが200点ほど落ちた。

こんな感じのコマンドを叩いてました。

[root@118-27-24-38 nginx]# cat access.log |alp --aggregates="/api/users/.*, /api/events/.*/sheets/.*/.*/reservation, /admin/api/events/.*/actions/edit"|less

f:id:serinuntius:20180917091955p:plain

/admin/api/users/:id/ が遅い。

予想通り、 getEvent & getEvents がネックぽいってなったので、@serinuntiusはそれを修正することにした。 @kazasikiはtotalPriceのSUMをどうにかすることになった。

12:30〜

N+1も酷いんだけど、SheetってUPDATEも走らないし、INSERTもDELETEも走らないので、cacheすれば良くない?と思って、 /initialize でGoのメモリにキャッシュすることにした。 *1

ただ、cacheするだけじゃだめで、ハマった。何回かFailしてやっと意味がわかった。 ポインタ型を渡してしまうと、いろいろな処理でゼロ埋めみたいな処理とかが走って駄目だったみたい。

ポインタじゃなくて、実態を渡すことで回避した。 @kazasikiにいろいろと助けてもらった。

ただ、これはスコアにほぼ影響せず、12:38に score: 963 でマージした。

初めてのアプリの修正が競技開始2時間半って、

「うわっ・・・俺らのチーム遅すぎ・・・?」

ほぼ同時刻ぐらいに、@kazasikiの修正も終わったので、ブランチ変えて試してたら、Index貼るスキーマ, がなかったりして、修正してマージした。

12:54 score:1125

この2つの修正後のalp。まだgetEvent修正してないので、そんなに変化はない。 f:id:serinuntius:20180917122831p:plain

13:00〜

@serinuntius が getEventの修正をする。

@dozenがSlowログ出す。

@kazasiki は レポート作成時の不要なソートをしないっていうのをやっていた。 report作成時にやってる不要なソートを消す by kazasiki · Pull Request #6 · dozen/isucon8 · GitHub

15:00~

書くのも辛いが、getEventの修正にめちゃくちゃ時間がかかってしまった。

マージできたのは15時になった。 全部の関数には適当しなかったので、スコアは 1608

いろいろ自分がポンコツ過ぎて、@kazasikiにめっちゃ助けてもらった。 今思うと、常にペアプロで正確にガシガシ修正して行ったほうがよかったかもしれないと思った。

15:40~

別の箇所でもgetEventsを適用した。

score: 2289

17:00~

@kazasikiが直近の予約の取得を僕が作った、N+1改善後の関数にしてくれて、ここで大きくはねた。

スコアは 12635

なんかめっちゃ時間かかってしまったな〜という感じ。

*1:Goのメモリっていう表現はなんか変だけど、Redisではないっていうこと。

builderscon 2018に行ってきたよ

builderscon.io

builderscon 2018 に 参加してきたので、レポート。

buildersconの良いところ

  • 知識欲を満たせる豊富なカテゴリのセッション!
  • その道に詳しい人によるハイレベルなセッション!
  • 「知らなかった!」を絶対聞ける!
  • 普段(使ってない|知らない)技術でも「ちょっと聞いてみよ」ができる
  • 開催してる場所が日吉駅で、個人的にそこそこアクセスが良い

buildersconのイマイチなところ

  • ステッカーいらない問題(後述します)
  • 人気のセッションが聞けなかったり、座れなかったりする(とはいえ、大体のセッションがYouTubeで公開されるはずなので、後で見れたりできるはず)
  • ゆえに、発表後のQ&Aを聞かずに待機列に並ぶ人も・・・

空間による制約のせいなので、全員VR上でカンファレンスすればいいのでは????(極端

自分のよかったところ

  • チケットの販売が始まった瞬間に、前売り券を買ったこと
  • 遅刻せずに(懇親会を覗く)全日程をこなした

自分の悪かったところ

  • スポンサーチケットを買わなかったところ(名札欲しいっていろいろなセッション聞いてめっちゃ思った・・・)
  • LTしたいな〜と思っていたら、いつの間にか登録終わってたみたい(というか、どこからどのタイミングでLT申し込みできたのかよくわからなかった。)
  • 懇親会に行ったりして、知らない人と話すみたいなムーブをしなかった

聞いたセッション

  • Envoy internals deep dive
  • ランチセッション (サイボウズ株式会社): Kubernetes で実現するインフラ自動構築パイプライン
  • Building and operating a service mesh at mid-size company
  • Webサービスにて200週連続で新機能をリリースする舞台裏
  • 実録!ある担当者がみた「謎ガジェット」開発1年史
  • JavaCardの世界
  • ブロックチェーン(DApp)で作る世界を変える分散型ゲームの世界
  • 次世代通信プロトコルにおけるセキュリティ・プライバシー保護・パフォーマンス (Security, privacy, performance of the upcoming transport protocols)

  • 高集積コンテナホスティングにおけるボトルネックとその解法

  • ブログサービスのHTTPS化を支えたAWSで作るピタゴラスイッチ

  • Webアプリケーションエンジニアが知るべきDNSの基本

  • なぜ私はキーボードを作るのか

私的ベストスピーカー

意見

完全に余談です。超個人的な意見ですが、主催者がフィードバックを求めているとおっしゃっていたので書きます。

企業ステッカーいらない問題

って書いたけど、よく考えたらスポンサー企業によって支えられてるから、受け取る義務があるのかな・・・。

各企業の方は、本当にステッカー需要あるか考えたほうがいいかも・・・。

少なくとも僕にとっては本当にいらないし、捨てるのもかわいそうだけど、全部捨てました・・・。

他のノベルティは大体嬉しいけど、ステッカー本当にいらない・・・。

まとめ

buildersconに関わるすべての皆様、ありがとうございました!

控えめにいって、これ以上最高のカンファレンスはないだろうっていうぐらい最高でした。

この記事を読んだ人で、buiidersconに参加したことない人は絶対1度参加してみることを強くオススメします!

Evernoteより100倍便利なメモサービス「Notion」を今すぐ使おう

こんばんは、今日*1は歴史的な台風ですが、皆様いかがおすごしでしょうか。

今朝、たまたまTwitterを見ていて発見したメモツール「Notion」が今までのメモツールの100倍は軽く超えてくるレベルで良いので紹介したい。

f:id:serinuntius:20180904230110p:plain

今までのメモツールの歴史を覆す「Notion」

今までのメモツールってどれも基本的には画一的で、メモ帳の粋を超えることが出来ていなかった

しかし、「Notion」 は違う。 メモ帳2.0 だと思う。明らかにバージョンが上がった。

何が今までのメモ帳と違うのかサクッと紹介したい。

従来型のメモ帳ツールとの違い

個人的に感じた違いを3つほど紹介する。

本当に全部入り

基本的にメモ帳、タスク管理系のツール、スプレッドシートWikiやカレンダーって

  • 得意な分野
  • 特定の機能

があったりするから、それぞれ別のツールを使っているはずだ。

しかし、基本的に他のツールの全機能がNotionにあるので、他のツールを使う必要はあんまりなくなるかもしれない。*2

情報の探しやすさ

知識を集約させる系のメモ帳ツールでは、情報の探しやすさはかなり大事だ。

Notionは情報に対するIndexの構築をユーザがかなり自由に設定できる。 特定の情報のIndexページを作るもよし、タグを付けるもよし、スプレッドシートで管理するもよし。

コンポーネントの分離の美しさ

各オブジェクトがキレイに分離されていて、直感的に使いやすい

情報共有の容易さ、権限を絞るの容易さ

全てのオブジェクトに対して、リンクを発行してハイパーリンクが出来る。

そのハイパーリンクには、1つ1つ権限を付けたり、付けなかったりが容易です。

全てがDBとして扱える

皆さん、無理やりスプレッドシートをDBのように使いますよね。

けど、それってかなり無理やり使っていてDB本来の旨味を享受できていないんですよね。

Notionはあらゆるデータに対するインターフェースとなり、DBを意識せずとも扱えるようになっています。

どういう用途に向いているか

  • 社内Wiki(個人的に一番向いているかなと)
  • Webクリップとして
  • タスク管理ツールとして(Trelloの代替)
  • UIの美しいスプレッドシートとしてw
  • 企画書として(スプレッドシートの企画書なんてどう考えても間違っている)
  • ブログとして
  • カレンダーとして
  • リマインダーとして

とりあえず、なんでも使える!

何がいいのか

ドキュメントに階層構造を持てる

階層構造にできるので、なんか書いてて膨らんできちゃったな〜と思ったら別ノートにすればいい。

全てがここにまとまる

よくあるのが、資料や企画書にリンクが貼ってあって、別のタブ、アプリケーションで開く羽目になるというのがあるが、それがなくなる。

画像も貼れるし、スプレッドシートも貼れるし、カンバンも貼れるのであっちゃこっちゃしない。

使用例

適当にいろいろなテストをしたノートを公開する。

www.notion.so

まとめ

便利なのでどんどん使っていこう。

まだ1日目なので、ロクな使用例がなくて申し訳ないが、1ヶ月ぐらい立ったらまたレポート書きたい。

*1:2018年9月4日

*2:流石に言いすぎかも

「Linuxのしくみ ~実験と図解で学ぶOSとハードウェアの基礎知識」を買った

最近、低レイヤーなことに興味を持ち始めたので買った。

技術書って、今読むか後で読むかの違いなので、迷ったら買うのが良いと思っている。

技術書読むの昔は大嫌いだったけど、 YAPCkindle oasisもらってからかなり読むようになった。

やっぱり、技術書って自分の知らないことがまとまって書いてあるので、良い。

一歩踏み込んだnginxのプロファイリングをする

ISHOCON2で惨敗して、悔しくてたまらなくてhttp2やnginxのことについてずっと調べたので、調査記録として残しておく。

serinuntius.hatenablog.jp

一番手軽で万能な「strace」

straceとはprocessに直接アタッチして、システムコールを調査するためのコマンドです。

インストールも簡単で、使うのも簡単です。 しかも、どんなツールにも使うことができます。

しかし、読み解くのは難しいです。(個人的な感想です。)

使い方

ざっくりと集計してボトルネックを探す

まず、調査対象のpidが必要なので、 ps aux|grep nginx とかで nginxのpidを調べます。

ubuntu@ip-172-31-21-29:~$ ps aux|grep nginx
root     20904  0.0  0.0  42976   852 ?        Ss   04:22   0:00 nginx: master process /usr/sbin/nginx -g daemon on; master_process on;
root     20905  0.0  0.1  48424  6848 ?        S    04:22   0:00 nginx: worker process
root     20906  0.0  0.0  47752  3664 ?        S    04:22   0:00 nginx: worker process
ubuntu   22510  0.0  0.0  13136   972 pts/0    S+   11:54   0:00 grep --color=auto nginx

masterプロセスではなく、worker processのpidをメモしておきます。 この例だと、20905か20906ですね。どちらでも良いです。

strace -c -S time -p 20905

オプションの意味は

-c で集計
-S で集計結果を何でソートするか(今回はtime)
-p pid

だと理解しています。

この状態で、ベンチマーカーを回します。*1

ベンチマーカーを回して、もう良いかな〜というタイミングで ctrl-c で止めます。すると、こんな感じで集計結果が見れます。 f:id:serinuntius:20180826210931p:plain

readを占める割合が一番多いですね。あと、エラーがめっちゃ出ているのも気になります。

集計結果を元にあたりをつけて調査する

先程の集計結果で、 read を占める割合が一番多かったので、 readシステムコールだけ追ってみます。

sudo strace -T -s 1024 -e read -p 22773 -k -o /tmp/strace.read.stack

オプションの意味は次のような感じだと理解しています。

-T 時間を出す
-s 1024 (デフォルトだと、1行の長さが省略されてしまうので、適当に長くする)
-e read (システムコールを絞り込む。)
-p pid
-k (スタックトレースを出す)
-o /tmp/strace.read.stack (ファイルに出力する)

このログを見ていると、

read(10, "\26\3\1\0\237\1\0\0\233\3\3\312\323\257.\224\3\2750C.\374os\302\343\16\310\7\214\2104\341\332\252\7\204\362\355#,v)\0\0 \300/\3000\300+\300,\314\250\314\251\300\23\300\
t\300\24\300\n\0\234\0\235\0/\0005\300\22\0\n\1\0\0R3t\0\0\0\5\0\5\1\0\0\0\0\0\n\0\n\0\10\0\35\0\27\0\30\0\31\0\v\0\2\1\0\0\r\0\22\0\20\4\1\4\3\5\1\5\3\6\1\6\3\2\1\2\3\377\1\0\1\
0\0\20\0\16\0\f\2h2\10http/1.1\0\22\0\0", 16709) = 164 <0.000035>
 > /lib/x86_64-linux-gnu/libpthread-2.27.so(read+0xe) [0x1134e]
 > /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1(BIO_sock_should_retry+0x5e) [0xa0a2e]
 > /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1(BIO_read+0x63) [0x9b613]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_rstate_string+0x148) [0x1c3e8]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_rstate_string+0x3e67) [0x20107]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_rstate_string+0x17d3) [0x1da73]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_in_before+0x850d) [0x3f40d]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_in_before+0x6aa) [0x375aa]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_do_handshake+0x41) [0x2f901]
 > /usr/sbin/nginx(ngx_ssl_handshake+0x3d) [0x5418d]
 > /usr/sbin/nginx(ngx_http_process_request+0x1364) [0x6a024]
 > /usr/sbin/nginx(ngx_os_specific_status+0x56c) [0x4f89c]
 > /usr/sbin/nginx(ngx_process_events_and_timers+0x54) [0x44934]
 > /usr/sbin/nginx(ngx_dlerror+0xe85) [0x4d7e5]
 > /usr/sbin/nginx(ngx_spawn_process+0x1a1) [0x4bc11]
 > /usr/sbin/nginx(ngx_dlerror+0x560) [0x4cec0]
 > /usr/sbin/nginx(ngx_master_process_cycle+0x1ce) [0x4e58e]
 > /usr/sbin/nginx(main+0xab6) [0x22506]
 > /lib/x86_64-linux-gnu/libc-2.27.so(__libc_start_main+0xe7) [0x21b97]
 > /usr/sbin/nginx(_start+0x2a) [0x226fa]
read(10, 0x56235cb4d0a3, 16709)         = -1 EAGAIN (Resource temporarily unavailable) <0.000029>
 > /lib/x86_64-linux-gnu/libpthread-2.27.so(read+0xe) [0x1134e]
 > /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1(BIO_sock_should_retry+0x5e) [0xa0a2e]
 > /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1(BIO_read+0x63) [0x9b613]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_rstate_string+0x148) [0x1c3e8]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_rstate_string+0x3e67) [0x20107]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_rstate_string+0x17d3) [0x1da73]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_in_before+0x850d) [0x3f40d]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_in_before+0x6aa) [0x375aa]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_do_handshake+0x41) [0x2f901]
 > /usr/sbin/nginx(ngx_ssl_handshake+0x3d) [0x5418d]
 > /usr/sbin/nginx(ngx_http_process_request+0x1364) [0x6a024]
 > /usr/sbin/nginx(ngx_os_specific_status+0x56c) [0x4f89c]
 > /usr/sbin/nginx(ngx_process_events_and_timers+0x54) [0x44934]
 > /usr/sbin/nginx(ngx_dlerror+0xe85) [0x4d7e5]
 > /usr/sbin/nginx(ngx_spawn_process+0x1a1) [0x4bc11]
 > /usr/sbin/nginx(ngx_dlerror+0x560) [0x4cec0]
 > /usr/sbin/nginx(ngx_master_process_cycle+0x1ce) [0x4e58e]
 > /usr/sbin/nginx(main+0xab6) [0x22506]
 > /lib/x86_64-linux-gnu/libc-2.27.so(__libc_start_main+0xe7) [0x21b97]
 > /usr/sbin/nginx(_start+0x2a) [0x226fa]

まぁ、本当はもっとあるんですが、だいたいこれが並んでいます。

これ見て気づくのは、libssl.so とか libcrypto.so とか、重そうなやつが並んでますね〜。

つまりこれは TLSのハンドシェイクが負荷となっているわけです。(たぶん)

なのでいい感じの対策を考えなければなりません。

対策は、後ろでまとめます。

出すのは面倒だけどわかりやすい「FlameGraph」

straceとは別のアプローチとして、FlameGraphを出してみるというのがある。

nginx profilingでググると、一番上にOpenRestyの記事がヒットする。

The most useful tools are

C-land on-CPU Flame Graph tool: https://github.com/openresty/nginx-systemtap-toolkit#sample-bt

C-land off-CPU Flame Graph tool: https://github.com/openresty/nginx-systemtap-toolkit#sample-bt-off-cpu

Lua-land on-CPU Flame Graph tool: https://github.com/openresty/stapxx#lj-lua-stacks

そこで紹介されているのが、 openresty/nginx-systemtap-toolkit というやつです。

今回はそれを使ってみます。

インストール方法

sudo apt-get install -y systemtap gcc
git clone https://github.com/openresty/nginx-systemtap-toolkit
git clone https://github.com/brendangregg/FlameGraph

使い方

まず、 .bt っていうのを生成するらしい

cd nginx-systemtap-toolkit
sudo ./sample-bt -p 17084 -t 10 -u > /tmp/a.bt

オプションの意味は、

-p nginxのpid
-t 10(時間、僕の環境だと長くするとエラーでちゃう)

次に、さっきの .bt から .cbt を生成する。 その、.cbt から .svg を生成する。

# cloneしたFlameGraphのリポジトリに移動する。
cd ../FlameGraph

# btからcbtを生成する
./stackcollapse-stap.pl /tmp/a.bt > /tmp/a.cbt

# cbtからsvgを生成する
./flamegraph.pl /tmp/a.cbt > /tmp/a.svg

あとは、これをscpとかでローカルに持ってくるなりして、ブラウザなりで開いてみるといい感じのFlameGraphが表示されるはずです。

読み解き方は、僕の雑な記事や、Deeeeetさんの神記事GolangでFlame Graphを描く を読むと良いかもしれません。

HTTP 1.1 のときのグラフ

sslで絞り込みして、紫になっているのですが、それがssl周りのスタックです。 結構な回数呼び出されてますね。 f:id:serinuntius:20180826110704p:plain

HTTP 2 のときのグラフ

劇的に、sslの呼び出し回数が減っています。 f:id:serinuntius:20180826110957p:plain

2つの調査結果から考えられる対策

http2にする。

    listen 443 ssl http2;

http2にすると、いい感じにコネクションを使いまわしてくれるみたい。(あんまりわかってないのでちゃんと勉強する。)

(そもそも、keep aliveの設定をちゃんとしていなかったので、それを設定しても効果あるのかな?ここもよくわかってないので、また今度調べる)

まとめ

  • 簡単にざっくり調べるには、 strace が便利
  • いい感じに負荷がかかっている理由等を調べるには FlameGraph が便利
  • コネクションの負荷、TLSの負荷を考えるの大事
  • http2

参考

strace の -k オプションでスタックトレースを出す - hibomaの日記

OpenResty - Profiling

https://wiki.ubuntu.com/Kernel/Systemtap

GitHub - openresty/openresty-systemtap-toolkit: Real-time analysis and diagnostics tools for OpenResty (including NGINX, LuaJIT, ngx_lua, and more) based on SystemTap

GitHub - brendangregg/FlameGraph: Stack trace visualizer

*1:今回はISUCON(ISHOCON)だったので、ベンチですが、実業務ではtmuxでしばらく放置でしょうか?

ISHOCON2というISUCONの個人大会で惨敗してきました【優勝スコアと同等の参考実装付き】

昨日(2018年8月25日)、ISHOCON2というISUCONの個人競技バージョンの大会に参加してきたのでレポートです。スコアが思うように伸びなかった方はぜひ読んでみてください。

ISHOCONとは

github.com

f:id:serinuntius:20180826113155p:plain

ISHOCON2

iikanjina showwin contest 2nd (like ISUCON)

ISHOCONとは Iikanjina SHOwwin CONtest の略で、ISUCONと同じように与えられたアプリケーションの高速化を競うコンテスト(?)です。

らしいです。

ISHOCONの特徴

ISHOCONの特徴は、個人的に3つあると思います。

問題がコンテスト開催前からオープンであること

これ、ISUCONでは絶対ありえないと思うのですが、開催する前からオープンです

なので、自分はgraqtのテスト、またISUCONの練習として、1週間ぐらい前に取り組みました!

おかげで、モチベがあがってgraqtの実装がだいぶ進みました!

個人参加であること

ISUCONはチームで参加を前提としていますが*1、ISHOCONはむしろ個人同士のコンテストです。

なので、どれだけ幅広い知識を持っているかが求められていると思います。

僕は、アプリやDB周りはなんとか出来ますが、インフラ系は経験が浅く苦手意識があります・・・。

ベンチマーカーもオープンであること

これもISUCONでは絶対ありえないのですが、なんとベンチマーカーまでオープンになっています。

ベンチマーカーの気持ちがわかれば、スコアが伸びるかも??

Go実装を選択してやったこと

本当に勘違いして欲しくないのですが、事前回答時にmysqlである程度高速化してこれ以上速くならないな〜と思ったので最初からRedisに載せるという攻略方針でやっています。

最初から全部cacheさせる、Redisに載せるは本番のISUCONでは通用しないと思います。

この記事を読んでくださった学生さんや、ISUCON初学者の方にそこは勘違いして欲しくないです。*2

事前回答時のmysqlを一部捨てて、redisに載せるぞというp-rを一応貼っておきます。

Feature/cache by serinuntius · Pull Request #4 · serinuntius/ISHOCON2 · GitHub

CSSをNginxで返す

Goで静的ファイルを返してたので、Nginxで返すようにしました。 プロファイリングツールの導入 & css => nginx by serinuntius · Pull Request #2 · serinuntius/ishocon2-2 · GitHub

プロファイリングツール入れる

graqtをサクッと入れて、見てみるとこんな感じでした。

https://user-images.githubusercontent.com/10571219/44613717-e3f3f200-a852-11e8-9379-5b1da0f49d17.png

普通のISUCONより、デフォルト状態で圧倒的に速いんですよね〜w Maxで0.43ってw

「別にチューニングするほど遅くないやん」 って内心思っちゃいました。

スコア「10:36:49 score: 6460, success: 5380, failure: 0」

templateを外に出す

GolangのWAFとしてginが使われているのですが*3、それのwarningが気になったので修正しました。

詳しくは覚えてないですが、「Handlerの中でSetHTMLTemplateするのマジやめろ」 みたいな内容だったと思います。

r.SetHTMLTemplate(template.Must(template.ParseFiles(layout, "templates/vote.tmpl")))

templateを外に出す & sessionなくす by serinuntius · Pull Request #3 · serinuntius/ishocon2-2 · GitHub

なので、mainの中で登録してあげました。

スコア「10:59:06 score: 6604, success: 5452, failure: 0」

mysqlとnginxのコンフィグをgit管理するように

適当に、いい感じにしました。(したつもり)

ガバガバチューニングなので、 innodb_log_file_size = 1G のせいでバカでかいログファイルが2つも出来て、あとでディスク容量で苦しみます。

スコア「11:09:19 score: 6714, success: 6082, failure: 0」

GETのレスポンスは全部cacheする

アクセスログ見てるとベンチマーカーがアクセスするパターンがわかるのですが、 ざっくりいうと大量の POST /vote が来て、その後に各GETが来るという感じになっていて、POSTが来たときにcacheを消すということをしておけばOKだった。

なので実質、「GETのロジックとかどうでもよくてcache返すのでそこがある程度重くても特に問題ない」 というのが今回のポイントです。*4

その対応がこちら。 Feature/response cache by serinuntius · Pull Request #5 · serinuntius/ishocon2-2 · GitHub

ここはginのおかげでデフォルトでcache機構があってかなり楽できた。 イマイチdocとか実装みても使い方のイメージが掴めなかったので、いろいろ調べているとherokuの公式記事が出てきた。これが参考になった。

devcenter.heroku.com

この記事は、メモリストアをmemcacheにしているけど、オンメモリ実装が普通にあって、それを利用した。

スコアworkload20で「11:28:44 score: 23474, success: 15962, failure: 0」

POST /vote のレスポンスもcacheする

エラーメッセージがいくつかあるのですが、そこもメッセージごとにcacheしてしまえば、テンプレートレンダリングが各種1回だけで済むのでいい感じです。

正常時のレスポンスもcacheできます。

ここは事前に準備してたときに、どうやったら1度呼び出したテンプレートのレスポンスボディが取得できるかいろいろ調べてたどり着いた答えは、 「gin.ResponseWriter の interfaceを実装した structを作って差し替える案」です。

Goはこういうのがサクッと効率良くできるので良いですね。

具体的にはこんな感じです。

type bodyCacheWriter struct {
    gin.ResponseWriter
        // cache用のbody
    body *bytes.Buffer
}

 func (w bodyCacheWriter) Write(b []byte) (int, error) {
    w.body.Write(b)
    return w.ResponseWriter.Write(b)
}

使い方はこんな感じ

bcw := &bodyCacheWriter{
    body:           &bytes.Buffer{},
    ResponseWriter: c.Writer,
}

// cはgin.Context
// 差し替える
c.Writer = bcw

// あとは普通に返す
c.HTML(http.StatusOK, "vote.tmpl", gin.H{
    "candidates": candidates,
    "message":    "投票に成功しました",
})

// このあとでbcw.bodyをメモリに載せれば OK

実際には、bcw.bodyからRedisに載せる作業がありますが、本質ではないので省略します。後で気づくのですが、別にRedisに載せなくても普通にmapにcacheした方が良いですね。

スコア workload20で「11:54:47 score: 24550, success: 16950, failure: 0」

はい、ここまで破壊的な変更は一切行っておりません。 かなり安全に書き換えるだけで、24550点になります。

投票をRedisに載せる

これはかなり破壊的な変更になります。

今までvoteテーブルに1レコードずつ、mysqlにInsertしていたのですが、それをやめてRedisのsorted setや普通の文字列型とかでいろいろ持つようにします。

ここのロジック本当に汚くて、自分でも嫌気がさすのですが、こうなってしまいました。もっと効率の良い持ち方があると思いますが、1度思いついてしまうと中々その考えが離れず、最後まで変えることが出来ませんでした。

// goroutineで並列にしてるけどあんまり意味ないかも
var eg errgroup.Group

eg.Go(func() error {
    _, err := rc.ZIncrBy(politicalParty, float64(voteCount), keyword).Result()
    if err != nil {
        return errors.Wrap(err, "")
    }
    return nil
})

eg.Go(func() error {
    _, err := rc.ZIncrBy(candidateZKey(candidateID), float64(voteCount), keyword).Result()
    if err != nil {
        return errors.Wrap(err, "")
    }
    return nil
})

eg.Go(func() error {
    _, err := rc.ZIncrBy(kojinKey(), float64(voteCount), candidateVotedCountKey(candidateID)).Result()
    if err != nil {
        return errors.Wrap(err, "")
    }
    return nil
})

eg.Go(func() error {
    _, err := rc.IncrBy(candidateKey(candidateID), int64(voteCount)).Result()
    if err != nil {
        return errors.Wrap(err, "")
    }
    return nil
})

eg.Go(func() error {
    _, err := rc.IncrBy(userKey(userID), int64(voteCount)).Result()
    if err != nil {
        return errors.Wrap(err, "")
    }
    return nil
})

eg.Go(func() error {
    sex := candidateIdMap[candidateID].Sex
    _, err := rc.IncrBy(sexKey(sex), int64(voteCount)).Result()
    if err != nil {
        return errors.Wrap(err, "")
    }
    return nil
})


if err := eg.Wait(); err != nil {
    return errors.Wrap(err, "Failed to wait")
}

Sorted Set

  • 政党に対する支持者の声ランキング(zincrby)
key: 政党名
member: 支持者の声
increment: 投票数
  • 候補者に対する支持者の声ランキング(zincrby)
key: 候補者のid
member: 支持者の声
increment: 投票数
  • 候補者の投票数ランキング(zincrby)
key: "候補者の投票数ランキング"
member: 候補者のid
increment: 投票数

文字列型

  • 候補者の投票数(incr)
key: 候補者のid
increment: 投票数

(あれ?これ、候補者の投票数ランキング(zincrby)使えば削れそう)

  • ユーザの投票数(incr)
key: ユーザのid
increment: 投票数
  • 性別別投票数
key: 性別("男"、"女")
increment: 投票数

なんか削れそうなやつも発見しましたが、createVoteはこういう感じになりました。こんだけの数incrするの遅いに決まってるけどmysqlにinsertしないってたぶんこういうことなんでしょうね・・・。厳しいw

けど、これのおかげで GET /がシンプル(大嘘)になるんですよね。

1~10位、それと最下位っていうの、SQLだとかなり厳しいですが、Redisのsorted setを使えば2発でサクッと(?)取ってこれますね。

ZREVRANGEBYSCOREとZRANGEBYSCOREを使います。

// 1 ~ 10 の取得
results, err := rc.ZRevRangeWithScores(kojinKey(), 0, 9).Result()
if err != nil {
    log.Println(err)
}

// 最下位
resultsWorst, err := rc.ZRangeWithScores(kojinKey(), 0, 0).Result()
if err != nil {
    log.Println(err)
}
// これで1〜10位と最下位のsliceの出来上がり
results = append(results, resultsWorst...)

Redisのsorted setあんまりちゃんと使ったことがなかったので、コマンド名が呪文みたいだな〜と思っていたのですが、ちゃんと意味を理解すると簡単ですね。

ベースのコマンドがzrange(昇順)で、startとendのmemberを取ってくるというコマンドになっています。それにスコアをつけてほしかったら、withscoresになる。

で逆順だと、zrevrange になる!それだけのシンプルな話でした。

あとは、ゴリゴリRedis実装に差し替えていくだけです。 詳しくはp-r見てください。特に変わったことはしてないつもりです。

Feature/fix vote by serinuntius · Pull Request #7 · serinuntius/ishocon2-2 · GitHub

スコア workload20で「13:05:49 score: 40228, success: 31964, failure: 0 」

このあたりで、完全にnginxがボトルネックに変わります。 topで見ているとNginxが70%ぐらいを占めています。

都度メモリのアロケーションが走ると重そうなので、 POST /vote を中心にsync.Pool計画

nginxでTLSのキャッシュとか入れてるし、静的ファイルもgzipで返してるし、ベンチマーカーはETAGとか、cache-control ヘッダは見てくれないし、nginxの負荷を落とすのは無理ゲーやろと思って、nginxがボトルネックになっているとはわかってはいつつもアプリを直します。

メモリのアロケーションって結構重い処理みたいで、structとか使い回すと良いみたいですね。その使い回しを楽にやってくれるパッケージが syncにあります。

その名も 「sync.Pool」!

こいつを使えばいい感じにオブジェクトをpoolしてくれるのでメモリのアロケーションが減ります。*5

雑に書いても他のLLと比べたらかなり速いのに、もっとちゃんと書いたら更に速くなるGoはやっぱり最高。

使い方はこんな感じです。

type User struct {
    ID       int
    Name     string
    Address  string
    MyNumber string
    Votes    int
}

// Poolを作る
var userPool = sync.Pool{
    New: func() interface{} {
        return &User{}
    },
}

func newUser() *User {
    return userPool.Get().(*User)
}

// 適当ですけどこんな感じの使用感
func hoge() {
  u := newUser()
  defer u.close()
  u.Name = "hoge"
  fmt.Println(u)
}

// なんとなくファイルみたいにcloseにしておいた
// ここでまっさらにしておかないと不都合がある場合はゼロ値で埋めるみたいな処理があったほうが良いかも
func (u *User) close() {
    userPool.Put(u)
}

実際の対応 Feature/user pool by serinuntius · Pull Request #8 · serinuntius/ishocon2-2 · GitHub

スコア workload 30「2018/08/25 06:21:42 {"score": 41714, "success": 32482, "failure": 0}」

ベンチマーカーとの戦い ~リアルISUCON~

このちょっと前ぐらいから、アプリケーションが高速化しすぎて、ベンチマーカーが荒ぶるという事件が起こりだしました。

運営さんのリアルISUCONです。

僕は、事前に問題を解いていたこともあり、ボトルネックがnginxにありこれ以上スコアを上げることは厳しそうなので、運営にコミットしてベンチマーカーを直すという選択肢を選びました💪*6

アプリへの接続のコネクションの使い回しをせずに、ガンガンリクエストしているとエフェメラルポートが枯渇するという問題だと勝手に思っていたのですが、どちらかというとベンチマーカーもmysqlを持っていてそれをベースにリクエストしているみたいなのですが、どうやらそこのmysqlの接続するところで Too many connections が出ているということがわかりました。

なんでだろうと思って、ベンチマーカーのコード読んだら、都度openしてるじゃないですか〜、ヤダ〜w

f:id:serinuntius:20180826153212p:plain

dbのクライアントを使い回すようなp-rを出しました。

https://github.com/showwin/ISHOCON2/pull/25github.com

最新のcontestブランチから切ったもつもりが、古いブランチでコンフリクト解消しようと思ったら変な差分出てしまって、手間取ったので、このp-rはcloseにして、showwinさんに変更だけ入れていただきました。

テンパって手間取っていたのを優しく待ってくれたshowwinさんは優しい方でした。僕のp-rが入らないのも「良いのか?」と聞いてくださいましたし。

僕としては、とりあえず速くベンチ直って走るようになればどうでも良かったので、速い方でお願いしました!

このとき、焦って、MaxIdleConnectionや、MaxOpenConnectionの設定を忘れました・・・😇

で、なんだかんだしてたら、終了です。 最後までベンチマーカーに嫌われ*7、top10入りさえ出来ませんでした。 手元のベンチマーカーインスタンスでベンチ回すとスコアは4万ぐらいは出ていたので、top10には入れるはずだったのですが。

ボトルネックを解消する意義

ISUCONって本当にボトルネックを改善しないとスコアは思うように伸びないようにできていて、ボトルネックを解消するのが大事です。

こんなツイートもしています。

かなり、ブーメランだ・・・。 nginxがボトルネックなのに、それの改善を出来なかった人が言うことじゃないw

ちなみに、競技終了後に優勝した方にnginxのconfigのについて聞きました。

細かい違いはあれど、大事なhttp2の設定がありました。

    listen 443 http2;

はい、これを書くだけでhttp2になるみたいです。

ちなみに自分はこの対応を入れるだけで、優勝スコアと同等の25万点に到達しました。

く、悔しい・・・。

アプリケーションの改善はほぼ完璧だったということでしょう。

自分のインフラ力のなさが露呈する結果となってしまいました。

ですが、自分のボトルネックがわかるのもISUCONの面白いところで、どういう知識を増やせばアプリケーションを高速化できるかっていうのがかなり客観的にわかります。

実際のISUCONはチームなので、得意な分野がそれぞれ違う3人が集まったほうが強いでしょうね。

なぜhttp2にするとnginxのボトルネックが解消するのか

これは別記事で書こうと思います。

2018年8月28日21時追記しました

serinuntius.hatenablog.jp

優勝スコア25万点に到達できる実装

ここにあります!!

github.com

優勝した方との差分

おそらくですが、優勝された方のコードは公開されていないので優勝インタビューから推測するしかないですが、差分は以下ぐらいだと思います。

  • レスポンスをcacheするんじゃなくて、静的なファイルとして書き出して、nginxで返す

っていうのは斬新でした。僕は思いつきもしなかったです。

謝辞

改めて、問題を作成されたshowwinさん、会場提供、最高の弁当提供、インスタンス提供してくださったscoutyさん ありがとうございました!

まとめ

  • やっぱりISUCONは楽しい
  • ISHOCONも楽しい
  • 得意不得意があるので、お互いをカバーできるチーム構成が良さそう

*1:今年からお一人様枠が出来ましたが

*2:といいつつ、自分もISUCONに参加したことのない初学者ですが・・・

*3:これ系のコンテストで、デファクトじゃない実装使われるのだいぶ厳しい・・・。GolangはうすいWAFが使われるイメージがある。

*4:1人で8時間のコンテストだから別に良いけど、本家ISUCONだとこうはいかないだろうな〜と・・・

*5:趣味Gopherなので、お目にかかる機会はあんまりありませんでした。便利ですね

*6:これができるのもオープンなベンチマーカーのおかげ

*7:まだ、Too many connectionsが出ていたようです

Goのボトルネック調査にgo-torchがめっちゃ良い

こんばんは〜。

ISUCONの練習に励んでいる @_serinuntiusです。

自作のWebアプリケーションのボトルネック調査アプリケーションgraqtを書いていますが、もっと便利(?)なツールがあることを僕は知ってしまいました。

それがgo-torchです。

f:id:serinuntius:20180821212032p:plain

go-torchとは

Tool for stochastically profiling Go programs. Collects stack traces and synthesizes them into a flame graph. Uses Go's built in pprof library.

とのことで、goの組み込みのpprofというツールを使って、スタックトレースをプロファイリングして、炎のグラフ(?)を作成してくれるツールです。

このグラフが慣れると超読みやすくてボトルネックが簡単にわかります!(たぶん)

go-torchの読み方をちゃんと日本語で説明してくれている記事はとても少なく、deeeetさんのGolangでFlame Graphを描く | SOTA という記事ぐらいでしかちゃんと解説されていません。

このグラフを雰囲気で読むと痛い目にあう(すごいxy軸が独特)ので、自分なりにグラフの読み方を書きたいと思います。

go-torchのすごいところ

go-torchの読み解き方

軸の解説をしておきますと、x軸(幅)は出現回数で、y軸はstackされている数です。

要注意なのは、各軸が長いからといって遅いとは限らないということです。

x軸が長い、つまり幅が長いということはその関数が、他の関数に比べて多く呼ばれているということを表しています。

y軸が長い、つまりたくさんの関数がスタックされているところは、関数が多いだけで遅いわけではありません。

そして、もう1つ注意なのが、 色は全く関係ありません。

大事なので、もう一度言います!

色は全く関係ありません。

これは図を読みやすくするための手段らしいです。

まとめ

正直自分の記事を読むより、deeetさんの記事を繰り返し読むほうが良いw

10回ぐらい読み直して、ちょっと理解できた。

参考

GitHub - uber/go-torch: Stochastic flame graph profiler for Go programs GolangでFlame Graphを描く | SOTA Profiling Go Applications with Flamegraphs