ISUCON8 本戦参加記
10/20(土)に行われたISUCON8(Iikanjini Speed Up CONtest)というWebサービスの高速化を図るコンテストに、REQLYチームで本戦初参加してきました。ありがたいことにREQLYチームとしては初めてオンサイトのコンテストに参加させて頂き、そして30チーム20位(学生では16チーム中10位)という順位で清々しく惨敗しました! そこで、本戦当日にどんなことをしたのか、あるいはどんなことをすれば点数が伸びたと考えられるかを振り返ってみました。
メンバー
- yoco: インフラ担当。発起人兼筆者。
- m2ku: SQL兼アプリケーションサーバ担当。
- kenbo: アプリケーションサーバ担当。
予選と同様、プログラミング言語としてpythonを選択した。
本戦参加記
10:00〜11:00 環境構築
- git, htop, vim, dstatなどをインストールする。
- gitで、webappのコードをトラッキング。自動でデプロイしてslack通知してくれるシェルスクリプトを導入。
- alpでnginxのログを見る。
- ベンチマークを走らせながら、ログなどを瞥見する。
- コードリーディングを行う。
11:00〜12:00 開始1時間で確認したこと
dstat
で現状の分析
----system---- -------cpu0-usage--------------cpu1-usage------ ---load-avg--- ------memory-usage----- -dsk/total- --io/total- -net/total- ----swap--- time |usr sys idl wai hiq siq:usr sys idl wai hiq siq| 1m 5m 15m | used buff cach free| read writ| read writ| recv send| used free 20-10 11:04:12| 3 0 97 0 0 0: 3 0 97 0 0 0|0.46 0.51 0.75| 562M 10.1M 268M 152M| 88k 25k|2.34 0.88 | 0 0 | 98M 1950M 20-10 11:04:22| 18 1 81 0 0 0: 27 1 71 0 0 0|0.39 0.49 0.74| 571M 10.2M 268M 143M| 0 18k| 0 0.60 |4160k 4160k| 98M 1950M 20-10 11:04:32| 70 3 26 0 0 1: 59 3 35 3 0 1|0.79 0.57 0.77| 593M 5276k 220M 174M|7468k 368k| 227 23.1 |7777k 7652k| 99M 1949M 20-10 11:04:42| 76 2 21 0 0 1: 73 2 24 0 0 0|1.29 0.69 0.80| 629M 3276k 176M 184M| 423k 328k|14.0 22.5 | 11M 11M| 100M 1948M 20-10 11:04:52| 98 2 0 0 0 0: 98 2 0 0 0 0|1.93 0.85 0.85| 704M 3724k 179M 106M| 225k 283k|4.30 22.6 | 11M 11M| 100M 1948M 20-10 11:05:02| 97 2 0 0 0 0: 97 2 0 0 0 0|2.85 1.08 0.93| 656M 3692k 129M 204M| 60k 405k|5.10 32.4 | 14M 14M| 100M 1948M 20-10 11:05:07| 97 3 0 0 0 0: 98 2 0 0 0 0|3.18 1.18 0.96| 766M 4012k 131M 92.0M| 266k 366k|7.20 28.8 | 16M 16M| 100M 1948M 20-10 11:05:08| 97 3 0 0 0 0: 98 2 0 0 0 0|3.18 1.18 0.96| 683M 4068k 131M 175M| 234k 361k|6.67 28.2 | 18M 18M| 100M 1948M 20-10 11:05:09| 97 3 0 0 0 0: 98 2 0 0 0 0|3.18 1.18 0.96| 664M 4076k 131M 193M| 201k 321k|5.71 24.7 | 17M 17M| 100M 1948M
server1の2台のCPUが最大のボトルネックになっている。メモリは1GBのなかで800MB近くまで使っているが、swapは特に起きていない。このことから、
isucon実装改変アイディア
11時の時点でインフラを整える中で考えていたのは以下の改良であった。
- dockerをはがす(dockerがあると通信のボトルネックになるという例が、過去のisuconであった)
- mysqlを別サーバーに逃がして、pythonサーバ3台とmysql1台としたときにどうなるか? -> 14:00に改善
- nginxで静的ファイルをキャッシュする(あまりスコアには貢献しないかもしれなさそう)-> 13:30に改善
/orders
が重いのをなんとかできないだろうか?- ベンチマーカのログで、error: POST /orders request failed: this user give up browsing because response time is too long. [10.01874 s] となって落ちている。
2,3の改善を行い、最終的には4台のサーバーは以下のような構成とした*1。
13:00〜 プロファイリング
alpによる計測
+-------+-------+--------+----------+-------+-------+-------+--------+--------+------------+------------+--------------+------------+--------+-------------------------------+ | COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | METHOD | URI | +-------+-------+--------+----------+-------+-------+-------+--------+--------+------------+------------+--------------+------------+--------+-------------------------------+ | 218 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 51679.000 | 51679.000 | 8216961.000 | 37692.482 | GET | /js/moment.min.js | | 218 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 886.000 | 886.000 | 140874.000 | 646.211 | GET | / | | 218 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 11992.000 | 11992.000 | 1906728.000 | 8746.459 | GET | /css/app.033eaee3.css | | 218 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 894.000 | 894.000 | 142146.000 | 652.046 | GET | /favicon.ico | | 218 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 8988.000 | 8988.000 | 1429092.000 | 6555.468 | GET | /img/isucoin_logo.png | | 218 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 14403.000 | 14403.000 | 2290077.000 | 10504.940 | GET | /js/Chart.Financial.js | | 218 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 19425.000 | 19425.000 | 3088575.000 | 14167.775 | GET | /js/app.2be81752.js | | 218 | 0.000 | 0.002 | 0.091 | 0.000 | 0.000 | 0.000 | 0.001 | 0.001 | 139427.000 | 139427.000 | 22168893.000 | 101692.170 | GET | /js/chunk-vendors.3f054da5.js | | 218 | 0.001 | 0.003 | 0.173 | 0.001 | 0.000 | 0.001 | 0.003 | 0.001 | 159638.000 | 159638.000 | 25382442.000 | 116433.220 | GET | /js/Chart.min.js | | 1 | 0.052 | 0.052 | 0.052 | 0.052 | 0.052 | 0.052 | 0.052 | 0.000 | 2.000 | 2.000 | 2.000 | 2.000 | POST | /initialize | | 1 | 0.138 | 0.138 | 0.138 | 0.138 | 0.138 | 0.138 | 0.138 | 0.000 | 13.000 | 13.000 | 13.000 | 13.000 | DELETE | /order/719388 | | 170 | 0.025 | 10.295 | 685.267 | 4.031 | 0.025 | 3.725 | 9.900 | 2.806 | 0.000 | 59.000 | 6374.000 | 37.494 | POST | /signin | | 249 | 0.007 | 10.535 | 989.574 | 3.974 | 0.008 | 3.971 | 10.052 | 2.750 | 0.000 | 141746.000 | 227333.000 | 912.984 | GET | /orders | | 122 | 0.195 | 10.569 | 510.996 | 4.188 | 0.195 | 4.369 | 9.471 | 2.587 | 0.000 | 40.000 | 287.000 | 2.352 | POST | /signup | | 637 | 0.019 | 10.845 | 2860.303 | 4.490 | 0.025 | 4.367 | 10.457 | 2.645 | 0.000 | 183587.000 | 9204806.000 | 14450.245 | GET | /info | | 159 | 0.142 | 12.329 | 833.227 | 5.240 | 0.142 | 5.192 | 11.633 | 3.053 | 0.000 | 87.000 | 1855.000 | 11.667 | POST | /orders | +-------+-------+--------+----------+-------+-------+-------+--------+--------+------------+------------+--------------+------------+--------+-------------------------------+
ISUCOINのコード中に、SNS シェアを有効にしてユーザーの流入を増やすことのできるboolean optionがあり、これをTrueにするかどうかでアクセス数がかなり変化し、ベンチマークに影響を与えていた。SNS shareをTrueにした場合のalp
によるログは上記であった。このことから、応答に10秒以上かかるスローリクエストが発生していることが分かった。実際にこれは、ベンチマーカーのログをみるとタイムアウトが発生してエラーとしてカウントされており、ベンチマークを完動させるにはこのようなスローリクエストの原因を潰すことが必要になると考えた。
いかにしてpython-flask serverの計測をしたか
alp
を利用することで、どのリクエストが負荷の原因となっているかを調査することはできる。しかし、そのリクエストの中で、具体的にどのコードが律速となっているかを判断することは、実際のアプリケーションサーバのプロファイルをとらない限り、困難である。pythonで軽量サーバを利用するとなると選択肢が限られていることから、flaskをはじめとするWSGI互換の軽量サーバーが登場することを予想していた。予選における反省を踏まえ、直前対策ではどのようにしてpythonによるアプリケーションサーバのプロファイリングするか、ということを重点的に調査した。
まずはプロファイルを出力するため、 GitHub - pallets/werkzeug: The comprehensive WSGI web application library. をflaskに仕掛けた。
from werkzeug.contrib.profiler import ProfilerMiddleware app.wsgi_app = ProfilerMiddleware(app.wsgi_app, profile_dir="/tmp/profile")
docker-compose.ymlで /tmp/profile
をホストのprofileディレクトリでマウントするようにすれば、ホストからプロファイルファイルをみることができるようになる。リクエスト毎にバイナリファイルが1個ずつ出力されていることが見て取れるだろう。
プロファイリングの結果から
まず、1回のベンチマークに対して、その時の全てのリクエストにおける所要時間の占める割合を可視化した。
gprof2dot -f pstats --colour-nodes-by-selftime --show-samples profile/* > profile.dot dot -Tpng profile.dot > profile.png
上記の処理は、 ISUCON7予選1日目にチーム「ババウ」で参加して最終スコアは205148でした - Dマイナー志向 を参考にした。結果は下図である。
このグラフからも、/order
が実行時間の大宗を占めていることが明らかになったが、これよりもさらに細かい、関数ごとの所要時間をみてみることにしたい。 /tmp/profile
に出力されるprofileファイルには、そのファイル名でそのリクエストの処理にかかった時間がミリ秒単位で記載されていることから、スローリクエストのプロファイルを対象として、SnakeViz を利用することで、取得したプロファイルを階層構造で表現することができる*2。
10秒近くかかっている /order
のクエリのうち、isuloggerへのrequestが数秒占めていることが明らかになった。そこで、そのコードを読んでみたところ、isuloggerにログを送りつける処理は、同期処理でPOSTのリクエストを吐いていることが明らかになった。ロガーがつまっているときにこのリクエストが遅延するのではないかと考え、非同期処理でisuloggerへのpost処理を行うようにした*3。
その後、プロファイルは以下のようになった。まだスロークエリではisubankへのAPIリクエストに時間がかかっていたが、この問題については本戦期間中に有効な解決策を見いだすことはできなかった。
時系列データの取得に向けて
またここで、alp
やベンチマークの結果をみてみると、1分の負荷走行のうち45秒ぐらい経過すると、アクセスが捌ききれなくなって、/info
、 /orders
、/signup
などアプリケーションサーバに対するリクエストが軒並みタイムアウトにするようになった。しかしこのタイムアウトの連鎖は、最初に何かタイムアウトを引き起こす原因となるリクエストがあり、それによって他のリクエストも巻き添えを食ってタイムアウトしたのではないかと考えられる*4。つまり、どのリクエストが原因で詰まり始めたのかや、最大でどのぐらいの同時接続数があったのかを検証することが、タイムアウトの原因究明につながったと考えられる*5。
こうしたときに、 alp
やプロファイラの出力だけでは、リクエストのスナップショットや、全リクエストの合計・平均は分かるかもしれないが、経時的な変化を観測することはできない。ngxtop
や ngrep
、 tcpdump
などでシェル上でログを眺めることはできるが、ログが流れてしまうという問題点がのこる。反省会では可視化して解釈するため、 GitHub - netdata/netdata: Get control of your servers. Simple. Effective. Awesome! https://my-netdata.io/ を導入しておけばよかったのではないか、というコメントが出たので付記しておく。
〜18:00 実装
今回取り組むことのできた実装は、大別すると以下であった。
- LIMIT 1の追加・MySQLサーバの分離(スコア2,000点〜3,000点)
- isuloggerへのpost処理を非同期化(スコアが4,000点〜5,000点)
- アプリケーションサーバを3台に負荷分散(スコア最大で6,000点)
スコアの変遷は以下の通り。
反省
仮想通貨の取引や、APIサーバを内部で叩く実装は、REQLYチームの誰もなじみのないコードであったため、アプリケーションの全貌を理解するのに時間を費やしてしまったことが、まず反省としてあげられる。その後のプロファイリング・ドリブンによる計測によって、ボトルネック箇所の同定はできたが、それに対する有効な手立てが思いつかず、実装が進まぬまま時間が過ぎてしまったことが悔やまれる。
以下の点に改善を加えることができれば、点数を伸ばすことができたと考えられる。
- isuloggerやisubankなどの外部APIの
/vender
のソースコードは、深追いする必要は無いと判断してしまったが、マニュアルをよく読めば、バルクでisuloggerに投げる実装がTODOになっており、それによって点数の改善が見込めた。 /info
を雑にキャッシュすることは、改善方法として考えていたものの、実装まで至らなかった。- これはアルゴリズムの改善というより気づきの問題であるが、SNSシェアの仕様について、「SNSシェアを全ての場合で許可する/許可しない」の二択だと思い込んでいたが、実際にはSNSシェアするかどうかはリクエストごとのものであるという点に発想が至れば、エラーが頻発しない程度に確率的にシェアさせることが可能になったはずである。
おわりに
運営の皆さんありがとうございました!これからもREQLYチームは精進を続けます!