「Linuxのしくみ ~実験と図解で学ぶOSとハードウェアの基礎知識」を買った
最近、低レイヤーなことに興味を持ち始めたので買った。
技術書って、今読むか後で読むかの違いなので、迷ったら買うのが良いと思っている。
技術書読むの昔は大嫌いだったけど、 YAPCでkindle oasisもらってからかなり読むようになった。
やっぱり、技術書って自分の知らないことがまとまって書いてあるので、良い。
[試して理解]Linuxのしくみ ?実験と図解で学ぶOSとハードウェアの基礎知識
- 作者: 武内覚
- 出版社/メーカー: 技術評論社
- 発売日: 2018/02/23
- メディア: Kindle版
- この商品を含むブログを見る
一歩踏み込んだnginxのプロファイリングをする
ISHOCON2で惨敗して、悔しくてたまらなくてhttp2やnginxのことについてずっと調べたので、調査記録として残しておく。
一番手軽で万能な「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
で止めます。すると、こんな感じで集計結果が見れます。
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周りのスタックです。 結構な回数呼び出されてますね。
HTTP 2 のときのグラフ
劇的に、sslの呼び出し回数が減っています。
2つの調査結果から考えられる対策
http2にする。
listen 443 ssl http2;
http2にすると、いい感じにコネクションを使いまわしてくれるみたい。(あんまりわかってないのでちゃんと勉強する。)
(そもそも、keep aliveの設定をちゃんとしていなかったので、それを設定しても効果あるのかな?ここもよくわかってないので、また今度調べる)
まとめ
- 簡単にざっくり調べるには、
strace
が便利 - いい感じに負荷がかかっている理由等を調べるには
FlameGraph
が便利 - コネクションの負荷、TLSの負荷を考えるの大事
- http2
参考
strace の -k オプションでスタックトレースを出す - hibomaの日記
https://wiki.ubuntu.com/Kernel/Systemtap
GitHub - brendangregg/FlameGraph: Stack trace visualizer
*1:今回はISUCON(ISHOCON)だったので、ベンチですが、実業務ではtmuxでしばらく放置でしょうか?
ISHOCON2というISUCONの個人大会で惨敗してきました【優勝スコアと同等の参考実装付き】
昨日(2018年8月25日)、ISHOCON2というISUCONの個人競技バージョンの大会に参加してきたのでレポートです。スコアが思うように伸びなかった方はぜひ読んでみてください。
- ISHOCONとは
- ISHOCONの特徴
- Go実装を選択してやったこと
- ベンチマーカーとの戦い ~リアルISUCON~
- ボトルネックを解消する意義
- なぜhttp2にするとnginxのボトルネックが解消するのか
- 優勝スコア25万点に到達できる実装
- 優勝した方との差分
- 謝辞
- まとめ
ISHOCONとは
ISHOCON2
iikanjina showwin contest 2nd (like ISUCON)
ISHOCONとは Iikanjina SHOwwin CONtest の略で、ISUCONと同じように与えられたアプリケーションの高速化を競うコンテスト(?)です。
らしいです。
ISHOCONの特徴
ISHOCONの特徴は、個人的に3つあると思います。
問題がコンテスト開催前からオープンであること
これ、ISUCONでは絶対ありえないと思うのですが、開催する前からオープンですw
なので、自分は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をサクッと入れて、見てみるとこんな感じでした。
普通の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の公式記事が出てきた。これが参考になった。
この記事は、メモリストアを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
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って本当にボトルネックを改善しないとスコアは思うように伸びないようにできていて、ボトルネックを解消するのが大事です。
こんなツイートもしています。
ISUCONってボトルネック解消しないと本当にスコアあがりません。けど、ボトルネックを解消すると、事前に打っていた手が効いてきて点数が跳ね上がります。
— serinuntius@5時起き (@_serinuntius) 2018年8月24日
ボトルネックを読み間違えたらダメです。
かなり、ブーメランだ・・・。 nginxがボトルネックなのに、それの改善を出来なかった人が言うことじゃないw
ちなみに、競技終了後に優勝した方にnginxのconfigのについて聞きました。
細かい違いはあれど、大事なhttp2の設定がありました。
listen 443 http2;
はい、これを書くだけでhttp2になるみたいです。
ちなみに自分はこの対応を入れるだけで、優勝スコアと同等の25万点に到達しました。
く、悔しい・・・。
アプリケーションの改善はほぼ完璧だったということでしょう。
自分のインフラ力のなさが露呈する結果となってしまいました。
ですが、自分のボトルネックがわかるのもISUCONの面白いところで、どういう知識を増やせばアプリケーションを高速化できるかっていうのがかなり客観的にわかります。
実際のISUCONはチームなので、得意な分野がそれぞれ違う3人が集まったほうが強いでしょうね。
なぜhttp2にするとnginxのボトルネックが解消するのか
これは別記事で書こうと思います。
2018年8月28日21時追記しました
優勝スコア25万点に到達できる実装
ここにあります!!
優勝した方との差分
おそらくですが、優勝された方のコードは公開されていないので優勝インタビューから推測するしかないですが、差分は以下ぐらいだと思います。
- レスポンスをcacheするんじゃなくて、静的なファイルとして書き出して、nginxで返す
っていうのは斬新でした。僕は思いつきもしなかったです。
謝辞
改めて、問題を作成されたshowwinさん、会場提供、最高の弁当提供、インスタンス提供してくださったscoutyさん ありがとうございました!
まとめ
- やっぱりISUCONは楽しい
- ISHOCONも楽しい
- 得意不得意があるので、お互いをカバーできるチーム構成が良さそう
Goのボトルネック調査にgo-torchがめっちゃ良い
こんばんは〜。
ISUCONの練習に励んでいる @_serinuntiusです。
自作のWebアプリケーションのボトルネック調査アプリケーションgraqtを書いていますが、もっと便利(?)なツールがあることを僕は知ってしまいました。
それがgo-torchです。
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すごい! pic.twitter.com/DfunmE5suC
— serinuntius@5時起き (@_serinuntius) August 21, 2018
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
【3,4日目】graqt開発日誌 ~PercentileとStddev(標準偏差)~
「べ、別に土日早起き出来なかったからブログ書けなかったわけじゃないんだからね。。。」
冗談はさておき、土日はISHOCON2やgraqtの開発に力を入れてしまい、記事を書けませんでした。
いろいろ機能が追加されたので、紹介したいと思います。
新機能
Percentileが見れるようになりました
graqtはbetter than alpを標語として、作っているのですが、alpにあるPercentileを移植しました。
P1, P50, P99とかのことです。
なんで、これが必要なのか調べていると、レスポンスタイムの平均(Avg)だけ見てしまうと、スロークライアントの結果に引っ張られる可能性があるからです。
Nginxの$request_timeは、nginxがリクエストを受けてからレスポンスをクライアントに返しきるまでの時間なので、変に遅いクライアントが居ないとも限らない・・・。 平均値だと、極端な異常値が少しでもあったばあい、これに引きづられて数字が大きくなったりして、あまり信用できなくなったりします。 測定誤差をできるだけ減らしたいので、平均値ではなくてパーセンタイルを取ろうという考え方です。
ベンチマーカー相手だとあんまり考えなくてもいいかもですが(わざわざスロークライアントになるようなベンチマーカーって過去のISUCONでないよね?)、本番のアプリケーションでは重要ですね。
Stddev(標準偏差)が見れるようになりました
標準偏差も、かなりわかりにくい指標なのですが、こちらの記事にわかりやすく書いてありました。詳しく知りたい方はこちらの記事をお読みください。
この機能もalpについている機能で、そのままパクリましたリスペクトして実装しました。
Pathを集約して見れるようになりました
これもalpリスペクトの機能で、alpではAggregate機能として実装されています。
例えばですけど、
/diary/entry/1 /diary/entry/2 /diary/entry/3
こういう感じのリクエストがあると、集約しないとそのまま3行で表示されてしまいますが、設定ファイルに正規表現を書いておくと集約して1行でまとめて表示できます。
graqt.yamlに
aggregates: - /diary/entry/\d+
このように書いておくと、集約され表示されるようになります。
実際の例を見たほうがわかりやすいと思うので、貼っておきます。
これが、
こうなります!!!
けど、これ使うと「一部のページだけ異様に遅い!」みたいなのがあった場合わかりにくいので気をつけてください。
レスポンスボディのサイズが表示されるようになりました
今まで項目としてはちゃんと用意されていたのですが、ロガーの方で取得していなかったので、ちゃんとレスポンスボディのサイズを取得してロガーに載せるようにしました。
やったぜ!
ginというフレームワークに(一部)対応しました
ginというフレームワークは、http.Handlerを準拠して作られているわけではないので、それようのmiddlewareを作るしかありませんでした。(たぶん)
個人的には、http.Handlerに準拠しないフレームワークはgo wayじゃないと思っていて、いろいろな制約がつきまとって非常に面倒くさいことになります。
会社の先輩方が、「Go書くときは薄いフレームワークしか使わなくて良い」とおっしゃっていた理由が今回とても身にしみました。
具体的には、Ginのmiddlewareのシグネチャーにあわせて書いてあげるという感じです。めっちゃ処理が増えるとかではないですが、わざわざ1つのフレームワークのためにどんどんを作るのは非常に面倒です・・・。
func RequestIdForGin() gin.HandlerFunc { return func(c *gin.Context) { t1 := time.Now() id := newRequestID() c.Set(string(RequestIDKey), id) c.Next() RLogger.Info("", zap.Duration("time", time.Since(t1)), zap.String("request_id", id), zap.String("path", c.Request.RequestURI), zap.String("method", c.Request.Method), zap.Uint64("content_length", uint64(c.Writer.Size())), ) } }
https://github.com/serinuntius/graqt/blob/master/middleware.go#L38-L57
今回は、ISHOCON2でGinが利用されていたので、実装せざるおえませんでした。
一部対応と書いたのは、クエリのロガーの方で、contextに仕込んでいるはずのrequest id(uuid)が取れてないので、クエリのログは出ているのですが、紐付けることができていません 。たぶん、改善できるはずなので、いずれ改善いたします。
まとめ
やっぱり、実際のISUCON(ISHOCON2)を解きながら、graqtの開発をすると、
「うおぉぉぉぉ〜、この情報知りたいんだけどぉ!!!!」
とか
「ginに対応してないやん!!!対応せねば!!」
みたいな気持ちがわいてきて、モチベーションになりやすいです。
どんどん開発して、素晴らしいソフトウェアにするので、今後共よろしくお願いいたします。
【2日目】graqt開発日誌 ~GolangでスクロールできるCLIを作る~
今日から、朝5時に起きて、筋トレして7時に出勤して、始業の9時半までgraqtを書くことにした。夜は22時に寝る(つもり)。
1日3時間半程開発時間を取れるため、結構捗る。
進捗
午前中
- ヘッダーを残したままスクロールする(結構考える必要があった)
今日のgraqtの進捗です。
— serinuntius@5時起き (@_serinuntius) August 17, 2018
スクロールできるようになりました。ちゃんとheaderを残しつつ、スクロールを実装したのがポイントです。https://t.co/6JZQyklKlP#golang #isucon #朝活 pic.twitter.com/lfubBmWUMt
帰宅後
- スクロールの実装
- リファクタ
- query widgetの閉じる処理
graqt夜の部の進捗。
— serinuntius@5時起き (@_serinuntius) August 17, 2018
今日はGIFにしてみた。
query windowを表示したり、閉じたりできるようになった!
リファクタして各windowごとのファイルにわけた。https://t.co/6JZQyklKlP#golang #isucon #graqt pic.twitter.com/xkkubqmeBi
コード
implement scroll by serinuntius · Pull Request #1 · serinuntius/go-cui-sandbox · GitHub
きれいなGIFを作る方法
まとめ
5時起き開発、やってくぞ!!!!
【1日目】graqt開発日誌 ~GolangでリッチなCLIを作る~
最近ブログ書いてないので、graqtの進捗を1mmでも進んだら書くことにする。
graqtについては、以下の記事を参考にされたし。 一言で言うと、バカでも使えるGolang用のWebアプリのボトルネックを調査するソフトウェアです。主にISUCONをターゲットにしています。
serinuntius.hatenablog.jp github.com
進捗
現在、CLI部分を作っていて、見た目だけ少し動くようになった。 まだ、ログ部分とつなぎこみはしていない。
別日だけど、sketchでワイヤー作ったりもした。
めっちゃ雑に今作ってるISUCON用の解析ツールのCLIのデザインをsketchで書いてみた!
— serinuntius (@_serinuntius) August 7, 2018
CLIツールでもGUIの場合ワイヤー引いとかないと、いろいろ要件漏れちゃいそうだからな〜。 pic.twitter.com/d79CjFq5DO
graqtの進捗 #golang #isucon pic.twitter.com/F35efDpx9w
— serinuntius (@_serinuntius) August 16, 2018
golangでリッチなCLIを作るには
jroimartin/gocuiというOSSがすごく便利です。
_exampleに参考になるコードが結構ある。 github.com
今日のコードを貼っておきます。 汚いのは自覚してるし、graqtに持っていくときは清書しますw
package main import ( "log" "github.com/jroimartin/gocui" "fmt" "text/tabwriter" "github.com/pkg/errors" ) type RequestWidget struct { name string x, y int w, h int counter int v *gocui.View tw *tabwriter.Writer } func NewRequestWidget(name string, x, y, w, h int) *RequestWidget { // add initialize return &RequestWidget{name: name, x: x, y: y, w: w, h: h, counter: 0} } func (w *RequestWidget) Layout(g *gocui.Gui) error { // _ => vgit v, err := g.SetView(w.name, w.x, w.y, w.x+w.w, w.y+w.h) if err != nil { if err != gocui.ErrUnknownView { return err } v.Title = "Request Index" v.Highlight = true v.SelBgColor = gocui.ColorGreen v.SelFgColor = gocui.ColorBlack v.SetCursor(0, 1) if err := w.KeyBindings(g); err != nil { return errors.Wrap(err, "Failed to Set KeyBindings") } if _, err := g.SetCurrentView("request"); err != nil { log.Panicln(err) } w.InitTabWriter(v) if _, err := w.PrintHeader(); err != nil { return err } // TODO テスト用 for i := 0; i < 10; i++ { fmt.Fprintln(w.tw, "\t300\tGET\t/hoge\t10\t0.3\t5\t3000\t3\t8\t9\t8\t300mb\t50mb\t30mb\t30000mb") } w.tw.Flush() fmt.Fprintln(w.v) } return nil } func (w *RequestWidget) InitTabWriter(v *gocui.View) error { w.v = v w.tw = tabwriter.NewWriter(v, 0, 8, 2, ' ', 0) return nil } func (w *RequestWidget) PrintHeader() (int, error) { return fmt.Fprintln(w.tw, "\tCount\tMethod\tPath\tMax\tMin\tAvg\tSum\tP1\tP50\tP99\tStddev\tMaxBody\tMinBody\tAvgBody\tSumBody") } func (w *RequestWidget) enter(g *gocui.Gui, v *gocui.View) error { w.v.Clear() w.PrintHeader() w.counter++ for i := 0; i < w.counter; i++ { fmt.Fprintln(w.tw, "\taaaaaaaaaa\tbbb") } w.tw.Flush() fmt.Fprintln(w.v) return nil } func (w *RequestWidget) cursorUp(g *gocui.Gui, v *gocui.View) error { if v != nil { ox, oy := v.Origin() cx, cy := v.Cursor() // cy == 0 is header if cy == 1 { return nil } if err := v.SetCursor(cx, cy-1); err != nil && oy > 0 { if err := v.SetOrigin(ox, oy-1); err != nil { return err } } } return nil } func (w *RequestWidget) cursorDown(g *gocui.Gui, v *gocui.View) error { if v != nil { cx, cy := v.Cursor() if err := v.SetCursor(cx, cy+1); err != nil { ox, oy := v.Origin() if err := v.SetOrigin(ox, oy+1); err != nil { return err } } } return nil } func (w *RequestWidget) Printf(format string, a ...interface{}) { fmt.Fprintf(w.tw, format, a) w.tw.Flush() fmt.Fprintln(w.v) } type HelpWidget struct { name string x, y int w, h int body string } func NewHelpWidget(name string, x, y, w, h int) *HelpWidget { // add initialize return &HelpWidget{name: name, x: x, y: y, w: w, h: h} } func (w *HelpWidget) Layout(g *gocui.Gui) error { // _ => v v, err := g.SetView(w.name, w.x, w.y, w.x+w.w, w.y+w.h) if err != nil { if err != gocui.ErrUnknownView { return err } v.Title = "Help" fmt.Fprintf(v, "%d:%d:%d:%d", w.x, w.y, w.x+w.w, w.y+w.h) } return nil } type QueryWidget struct { name string x, y int w, h int } func NewQueryWidget(name string, x, y, w, h int) *QueryWidget { // add initialize return &QueryWidget{name: name, x: x, y: y, w: w, h: h} } func (w *QueryWidget) Layout(g *gocui.Gui) error { // _ => v v, err := g.SetView(w.name, w.x, w.y, w.x+w.w, w.y+w.h) if err != nil { if err != gocui.ErrUnknownView { return err } v.Title = "Query Index" } return nil } type ParameterWidget struct { name string x, y int w, h int } func NewParameterWidget(name string, x, y, w, h int) *ParameterWidget { // add initialize return &ParameterWidget{name: name, x: x, y: y, w: w, h: h} } func (w *ParameterWidget) Layout(g *gocui.Gui) error { // _ => v v, err := g.SetView(w.name, w.x, w.y, w.x+w.w, w.y+w.h) if err != nil { if err != gocui.ErrUnknownView { return err } v.Title = "Query Parameter" } return nil } func quit(g *gocui.Gui, v *gocui.View) error { return gocui.ErrQuit } func (w *RequestWidget) KeyBindings(g *gocui.Gui) error { if err := g.SetKeybinding("request", gocui.KeyEnter, gocui.ModNone, w.enter); err != nil { return err } if err := g.SetKeybinding("request", gocui.KeyArrowDown, gocui.ModNone, w.cursorDown); err != nil { return err } if err := g.SetKeybinding("request", gocui.KeyArrowUp, gocui.ModNone, w.cursorUp); err != nil { return err } if err := g.SetKeybinding("request", gocui.KeyCtrlN, gocui.ModNone, w.cursorDown); err != nil { return err } if err := g.SetKeybinding("request", gocui.KeyCtrlP, gocui.ModNone, w.cursorUp); err != nil { return err } return nil } func main() { g, err := gocui.NewGui(gocui.OutputNormal) if err != nil { log.Panicln(err) } defer g.Close() g.Highlight = true g.SelFgColor = gocui.ColorBlue winX, winY := g.Size() fmt.Println(winX, winY) request := NewRequestWidget("request", 0, 0, winX-1, winY-3) help := NewHelpWidget("help", 0, winY-3, winX-1, 2) //query := NewQueryWidget("query", winX/2, 0, winX/2-1, winY-3) //parameter := NewParameterWidget("parameter", winX/2, winY/2, winX/2-1, winY/2-2) g.SetManager(help, request) //, query, parameter) if err := g.SetKeybinding("", gocui.KeyCtrlC, gocui.ModNone, quit); err != nil { log.Panicln(err) } if err := g.MainLoop(); err != nil && err != gocui.ErrQuit { log.Panicln(err) } }