REQLY開発ブログ

プロの料理レシピ専門検索エンジンREQLY(レクリー)の開発ブログです。

ISUCON8 本戦参加記

10/20(土)に行われたISUCON8(Iikanjini Speed Up CONtest)というWebサービスの高速化を図るコンテストに、REQLYチームで本戦初参加してきました。ありがたいことにREQLYチームとしては初めてオンサイトのコンテストに参加させて頂き、そして30チーム20位(学生では16チーム中10位)という順位で清々しく惨敗しました! そこで、本戦当日にどんなことをしたのか、あるいはどんなことをすれば点数が伸びたと考えられるかを振り返ってみました。

メンバー

予選と同様、プログラミング言語として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時の時点でインフラを整える中で考えていたのは以下の改良であった。

  1. dockerをはがす(dockerがあると通信のボトルネックになるという例が、過去のisuconであった)
  2. mysqlを別サーバーに逃がして、pythonサーバ3台とmysql1台としたときにどうなるか? -> 14:00に改善
  3. nginxで静的ファイルをキャッシュする(あまりスコアには貢献しないかもしれなさそう)-> 13:30に改善
  4. /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マイナー志向 を参考にした。結果は下図である。

f:id:reqly-tokyo:20181021172045p:plain

このグラフからも、/order が実行時間の大宗を占めていることが明らかになったが、これよりもさらに細かい、関数ごとの所要時間をみてみることにしたい。 /tmp/profile に出力されるprofileファイルには、そのファイル名でそのリクエストの処理にかかった時間がミリ秒単位で記載されていることから、スローリクエストのプロファイルを対象として、SnakeViz を利用することで、取得したプロファイルを階層構造で表現することができる*2

10秒近くかかっている /order のクエリのうち、isuloggerへのrequestが数秒占めていることが明らかになった。そこで、そのコードを読んでみたところ、isuloggerにログを送りつける処理は、同期処理でPOSTのリクエストを吐いていることが明らかになった。ロガーがつまっているときにこのリクエストが遅延するのではないかと考え、非同期処理でisuloggerへのpost処理を行うようにした*3

その後、プロファイルは以下のようになった。まだスロークエリではisubankへのAPIリクエストに時間がかかっていたが、この問題については本戦期間中に有効な解決策を見いだすことはできなかった。

f:id:reqly-tokyo:20181021093856p:plain

時系列データの取得に向けて

またここで、alpベンチマークの結果をみてみると、1分の負荷走行のうち45秒ぐらい経過すると、アクセスが捌ききれなくなって、/info/orders/signup などアプリケーションサーバに対するリクエストが軒並みタイムアウトにするようになった。しかしこのタイムアウトの連鎖は、最初に何かタイムアウトを引き起こす原因となるリクエストがあり、それによって他のリクエストも巻き添えを食ってタイムアウトしたのではないかと考えられる*4。つまり、どのリクエストが原因で詰まり始めたのかや、最大でどのぐらいの同時接続数があったのかを検証することが、タイムアウトの原因究明につながったと考えられる*5

こうしたときに、 alp やプロファイラの出力だけでは、リクエストのスナップショットや、全リクエストの合計・平均は分かるかもしれないが、経時的な変化を観測することはできない。ngxtopngreptcpdump などでシェル上でログを眺めることはできるが、ログが流れてしまうという問題点がのこる。反省会では可視化して解釈するため、 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点)

スコアの変遷は以下の通り。

f:id:reqly-tokyo:20181022112829p:plain

f:id:reqly-tokyo:20181022125426p:plain

反省

仮想通貨の取引や、APIサーバを内部で叩く実装は、REQLYチームの誰もなじみのないコードであったため、アプリケーションの全貌を理解するのに時間を費やしてしまったことが、まず反省としてあげられる。その後のプロファイリング・ドリブンによる計測によって、ボトルネック箇所の同定はできたが、それに対する有効な手立てが思いつかず、実装が進まぬまま時間が過ぎてしまったことが悔やまれる。

以下の点に改善を加えることができれば、点数を伸ばすことができたと考えられる。

  • isuloggerやisubankなどの外部API/venderソースコードは、深追いする必要は無いと判断してしまったが、マニュアルをよく読めば、バルクでisuloggerに投げる実装がTODOになっており、それによって点数の改善が見込めた。
  • /info を雑にキャッシュすることは、改善方法として考えていたものの、実装まで至らなかった。
  • これはアルゴリズムの改善というより気づきの問題であるが、SNSシェアの仕様について、「SNSシェアを全ての場合で許可する/許可しない」の二択だと思い込んでいたが、実際にはSNSシェアするかどうかはリクエストごとのものであるという点に発想が至れば、エラーが頻発しない程度に確率的にシェアさせることが可能になったはずである。

おわりに

運営の皆さんありがとうございました!これからもREQLYチームは精進を続けます!

*1:ロードバランシングの仕組みが再起動試験した際にうまく動かないことが分かったので、結局最終的にはSERVER1およびSERVER2しか利用しなかった

*2:この図はあたかも生物のタクソノミのヒエラルキーであるかのように見える

*3:しかしこれは、実際にはバルクでisuloggerに流す実装をしたほうがよかった

*4:大量のリクエストのうち、どれかが"ドライバー"となってタイムアウトを引き起こし、残りが"パッセンジャー"として巻き添えになってしまった、という言い方もできるだろう

*5:例えば、もしかしたらgunicornのワーカー数等の設定を変更することで、タイムアウトを抑制できたかもしれない