1章チューニングの基礎知識

理論の話なので要約

Web サービスが高速であることは現代では必須要件と言える

Web サービスを高速化することで得られるメリット

ユーザーの離脱率を下げることができる
Core Web Vitals のスコアが上がり、SEOに有利になる
業務システムの場合、業務効率が向上する
システムリソースの消費を抑え、コストと地球に優しい
かっこいい(重要)

高速の定義

本書では ISUCON における以下の定義に基づき、 Webサービス利用者(クライアント)のリクエスト送信開始からレスポンス受信完了までの所要時間(レイテンシ)が短いこと を高速であると定義する。つまり、レイテンシが低い Webサービスが高速であると言える。

ただし、実際の Webサービスは特定のリクエストだけでなく、様々な種類のリクエスト俯瞰していずれも高速の処理することや、同時並行で行われる大量のリクエストを少ないシステムリソースで処理することも求められる。

速さとキャパシティ

Webサービスの負荷は、システムリソース(CPU,メモリ,ネットワークIO...) の利用率が高い状態を指す。

一種類のリクエストのレイテンシが低い場合、リクエストごとのシステムリソースの消費も減るため、システムリソースのキャパシティを他のリクエストに割り当てられるようになることから、スループットを向上することが出来る。

必要十分なキャパシティ

ここでいうキャパシティは、システムリソースの性能×個数を指す。

必要十分なキャパシティとは、リクエスト量(需要) に対する供給(キャパシティ) が適切であることを指し、需要があふれる場合はシステムが過負荷状態になり障害に繋がってしまう一方。供給過多になると不要なコストを支払っている状態になってしまう。

需要過多に対してキャパシティを必要十分にするためには、二通りのアプローチがある。

需要を減らす
- リクエストのキューイングなど、処理の実行を分散する
- 単位時間あたりのリクエスト上限を制限する
- 先着順を抽選に変えるなど、サービスの仕様側で調整する
供給を増やす
- システムリソースの性能をあげる (垂直スケーリング or スケールアップ)
- システムリソースの数を増やす (水平スケーリング or スケールアウト)

たいていの場合は需要側の調整が難しいことから、供給側が調整される。

クラウドサービスを利用している場合はオートスケーリング機能によって水平スケーリングが自動で行われる(リアクティブ) が、スケーリングまでに時間を要すること、よきせぬキャパシティ切れがあることから、事前にキャパシティを見積もってスケーリングしておく(プロアクティブ) 手法と組みわせる必要がある。

キャパシティの正確な見積もりは不可能なので、負荷試験を通じて現実的なキャパシティを検討するための土台となるデータを獲得してく。

推測するな計測せよ

パフォーマンスチューニングは感で行ってはならず、計測に基づいて行うべきであり、計測についても以下を守る必要がある。

2つのデータを比較するときは前提条件を揃える
複数の施策を同時に比較せず、一つずつ効果を確認する

ボトルネックにだけアプローチする

全体のスループットはボトルネックのスループットに律速するという考えがあり、ボトルネック以外の要素を高速化してもシステム全体のパフォーマンスは改善されづらい。

ボトルネックは概ね以下の流れで見つける

システム全体をマクロ視点で俯瞰し、データの流れを把握する
データの流れに沿って各要素の入り口と出口での所要時間及びリソース利用状況を計測する
所要時間が長いまたはリソース利用率が高い箇所を特定する

ボトルネックを特定したら、マクロからミクロの視点に切り替えて、APMやプロファイリングを活用した原因特定を行う。原因に対する対応として以下の3パターンが考えられる。

解決: 処理方法の変更、書き直しなど、事象の根本原因を解決する
回避: 処理そのものを不要にしたり、キャッシュを用いて処理を減らすなど
緩和: スケールアウトや設定変更などを通じてボトルネックの程度を緩和する

当然望ましいのは「解決」ではあるが、必ずしもすぐに解決できるわけではないことと、特定のボトルネックを対処しても、他の箇所にボトルネックが移動するだけで消滅することはないため、一箇所に固執することが良いとは限らない。

shingo.sasaki

2章モニタリング

モニタリングはアプリケーションの状態を常時監視することから、継続的なテストでもあるといえる。

モニタリングで何を監視するかはアプリケーションの要件などによって決まるため、その目的を定めて、一貫した変わらない視点で継続的に監視することが重要。

モニタリングには以下の2種類がある

外形監視
- アプリケーションを外側の視点からモニタリングする
- エンドポイントに対して HTTP リクエストを行い、レスポンスが意図通りかを監視するなど
- よりユーザー体験に近い操作を行うシナリオテストもある
内部監視
- ユーザーからは見えないアプリケーションの内側をモニタリングする
- 主に WebアプリケーションやOS、ミドルウェアのメトリクスを取得する

モニタリングにおけるメトリクスの取得には top や free などの Linux コマンドが使え、手動でのモニタリングも可能ではあるが、モニタリングツールを用いることでこれを効率的にできる。

モニタリングツールとは概ね以下のような機能を有する

メトリクスの自動収集、保存
保存したメトリクスの表示、集計
メトリクスのしきい値に基づく通知

モニタリングツールには Pull 型と Push 型がある

Pull 型
- モニタリング対象環境内にエージェントを設置し、モニタリングツールがエージェントに対してメトリクス取得をリクエストする
Push 型
- モニタリング対象環境内にエージェントを設置し、エージェントがモニタリングツールに対してメトリクスを送信する

Pull 型はエージェントがシンプルな Web サーバーに済むというメリットはあるが、各環境にエージェントのためのポートを開放する必要があったり、エージェントの追加削除をツール側で一元管理しなきゃならなかったりするなどのデメリットがある。

本書で使用する Prometheus は Pull 型ではあるものの、上記デメリットを緩和するための仕組みも多く備えている。

モニタリングツール及びそのエージェントは様々な種類があるが、重要なのは何を対象としてモニタリングするかで、何を用いてモニタリングするかはそこまで重要ではない。

グラフの読み方にご注意

グラフ上は数値が跳ね上がっていたとしても、縦軸の設定が不適切で実際は軽微な変化に過ぎないというおことがあるので、縦軸横軸の設定に注意しよう。

複数のグラフを比較する場合は、比較対象以外の条件を合わせることでミスリードを避けよう。

shingo.sasaki

3章基礎的な負荷試験

本書では負荷試験を行うソフトウェアのことをベンチマーカーと呼び、実際にベンチマーカー及び題材用のWebサービスを用いて、実際に負荷試験とチューニングを繰り返す流れを確認する。

private-isu

ピクシブ社が社内ISUCONを実施するために開発したインスタグラム風のWebサービス。
本書ではそのうち Go と Ruby の実装を使用する。

https://github.com/catatsuy/private-isu

AWSを用いた環境構築と、ローカルでの Docker を用いた構築の二種類があるが、ローカルの場合は端末で動いている他のアプリケーションなどの影響を受けてノイズが目立つため、本書ではAWSを使用するし、自身もそれにあわせていくことにする。(ので Docker でのセットアップは省略)

環境構築は以下の流れで行った

AWSコンソールにログイン後、リージョンを東京に切り替え
AMI(ami-06c39e451ff9930db) を c5a.large で起動 (sasaki-private-isu)
セキュリティグループ (sasaki-private-isu-app) を作成し、80番ポートへのパブリックアクセスを許可
キーペアは適当に作成して鍵を持っておく (SSMが推奨されてるけどSSH使いたいので)
パブリックアクセスは自身のグローバルIPアドレスからのみにセキュリティルールを追加
パブリックIPアドレス経由でブラウザでアクセスできることを確認

一通りの操作やページ遷移をしてみてアプリケーションの雰囲気は確認。
既に重さを感じているけど、体感でしか無いので負荷試験で数値化していく。

負荷試験の準備

本来はベンチマーカーはアプリケーションとは別ホストで動かすようにしないと、ベンチマーカー自体の負荷がノイズになってしまうが、本書の範囲内では影響は軽微であるため、アプリケーションと同インスタンス内で localhost に対して負荷検証を行う。

今回は nginx のアクセスログを使用する。アクセスログは /var/log/nginx/access.log に以下のように記録されている。

xx.xx.xx.xx - - [12/Nov/2022:21:31:37 +0900] "GET / HTTP/1.1" 200 5795 "http://xxx.xxx.xxx.xxx/@sasaki" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/106.0.0.0 Safari/537.36"

アクセスログからは以下が確認できる

リクエスト元IPアドレス
リクエスト処理完了時刻
リクエストメソッド、パス、バージョン
レスポンスステータスコード
レスポンスサイズ
リファラーヘッダー
ユーザーエージェント

が、この形式だとフォーマット的に機械的に抜き出すのが面倒なのと、リクエストの処理にかかった時間が特定できないため、 nginx の設定を変えて以下のようにした。(/etc/nginx/nginx.conf)

log_format json escape=json '{"time": "$time_iso8601",'
                                '"host": "$remote_addr",'
                                '"port": "$remote_port",'
                                '"method": "$request_method",'
                                '"uri": "$request_uri",'
                                '"status": "$status",'
                                '"body_bytes": "$body_bytes_sent",'
                                '"referer": "$http_referer",'
                                '"ua": "$http_user_agent",'
                                '"request_time": "$request_time",'
                                '"response_time": "$upstream_response_time"}';
access_log /var/log/nginx/access.log json;

詳細ドキュメント

こんなログが取れるように

{"time": "2022-11-12T21:52:59+09:00","host": "xxx.xxx.xxx.xxx","port": "60955","method": "GET","uri": "/posts/10001","status": "200","body_bytes": "846","referer": "http://13.231.184.123/","ua": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/106.0.0.0 Safari/537.36","request_time": "0.072","response_time": "0.072"}

$request_time は nginx がクライアントにレスポンスを返すまでの時間で、$upstream_response_time は App サーバーが nginx にレスポンスを返すまでの時間になる。

アクセスログを JSON 形式で出力できるようになったので、 alp を用いてこれを分析する。

https://github.com/tkuchiki/alp

今回は ec2 インスタンス側にこれをインストールする

$ wget https://github.com/tkuchiki/alp/releases/download/v1.0.12/alp_linux_amd64.zip
$ unzip alp_linux_arm64.zip
$ sudo install alp_linux_amd64.zip /usr/local/bin/alp

一旦 JSON 以外のフォーマットのログが混ざってる /var/log/nginx/access.json を削除してから適当に操作してログを貯める。

sudo rm /var/log/nginx/access.log
sudo systemctl reload nginx

ログが溜まったところで alp を使ってみる。
エンドポイントごとの集計結果が出た。楽しい。

$ cat /var/log/nginx/access.log | alp json
+-------+-----+-----+-----+-----+-----+--------+------------------+-------+-------+-------+-------+-------+-------+-------+--------+-------------+-------------+-------------+-------------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX | METHOD |       URI        |  MIN  |  MAX  |  SUM  |  AVG  |  P90  |  P95  |  P99  | STDDEV |  MIN(BODY)  |  MAX(BODY)  |  SUM(BODY)  |  AVG(BODY)  |
+-------+-----+-----+-----+-----+-----+--------+------------------+-------+-------+-------+-------+-------+-------+-------+--------+-------------+-------------+-------------+-------------+
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /@sasaki2        | 0.108 | 0.108 | 0.108 | 0.108 | 0.108 | 0.108 | 0.108 | 0.000  | 888.000     | 888.000     | 888.000     | 888.000     |
| 1     | 0   | 0   | 1   | 0   | 0   | POST   | /comment         | 0.004 | 0.004 | 0.004 | 0.004 | 0.004 | 0.004 | 0.004 | 0.000  | 0.000       | 0.000       | 0.000       | 0.000       |
| 1     | 0   | 0   | 1   | 0   | 0   | POST   | /                | 0.044 | 0.044 | 0.044 | 0.044 | 0.044 | 0.044 | 0.044 | 0.000  | 0.000       | 0.000       | 0.000       | 0.000       |
| 1     | 0   | 0   | 1   | 0   | 0   | POST   | /register        | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 | 0.000  | 0.000       | 0.000       | 0.000       | 0.000       |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /register        | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000  | 519.000     | 519.000     | 519.000     | 519.000     |
| 1     | 0   | 0   | 1   | 0   | 0   | POST   | /login           | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000  | 0.000       | 0.000       | 0.000       | 0.000       |
| 2     | 0   | 2   | 0   | 0   | 0   | GET    | /posts/10003     | 0.068 | 0.072 | 0.140 | 0.070 | 0.072 | 0.072 | 0.072 | 0.002  | 730.000     | 778.000     | 1508.000    | 754.000     |
| 2     | 0   | 2   | 0   | 0   | 0   | GET    | /login           | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000  | 540.000     | 607.000     | 1147.000    | 573.500     |
| 2     | 0   | 0   | 2   | 0   | 0   | GET    | /logout          | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000  | 0.000       | 0.000       | 0.000       | 0.000       |
| 3     | 0   | 3   | 0   | 0   | 0   | GET    | /image/9981.jpg  | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000  | 81386.000   | 81386.000   | 244158.000  | 81386.000   |
| 4     | 0   | 4   | 0   | 0   | 0   | GET    | /image/9986.jpg  | 0.000 | 0.004 | 0.004 | 0.001 | 0.004 | 0.004 | 0.004 | 0.002  | 86624.000   | 86624.000   | 346496.000  | 86624.000   |
| 4     | 0   | 4   | 0   | 0   | 0   | GET    | /image/9990.jpg  | 0.000 | 0.004 | 0.004 | 0.001 | 0.004 | 0.004 | 0.004 | 0.002  | 102371.000  | 102371.000  | 409484.000  | 102371.000  |
| 4     | 0   | 4   | 0   | 0   | 0   | GET    | /image/9989.jpg  | 0.000 | 0.004 | 0.008 | 0.002 | 0.004 | 0.004 | 0.004 | 0.002  | 107460.000  | 107460.000  | 429840.000  | 107460.000  |
| 4     | 0   | 4   | 0   | 0   | 0   | GET    | /image/9988.jpg  | 0.000 | 0.004 | 0.008 | 0.002 | 0.004 | 0.004 | 0.004 | 0.002  | 111515.000  | 111515.000  | 446060.000  | 111515.000  |
| 4     | 0   | 4   | 0   | 0   | 0   | GET    | /image/9987.jpg  | 0.000 | 0.004 | 0.004 | 0.001 | 0.004 | 0.004 | 0.004 | 0.002  | 367388.000  | 367388.000  | 1469552.000 | 367388.000  |
| 4     | 0   | 4   | 0   | 0   | 0   | GET    | /image/9991.jpg  | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000  | 153465.000  | 153465.000  | 613860.000  | 153465.000  |
| 4     | 0   | 4   | 0   | 0   | 0   | GET    | /image/9985.jpg  | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000  | 83264.000   | 83264.000   | 333056.000  | 83264.000   |
| 4     | 0   | 4   | 0   | 0   | 0   | GET    | /image/9983.jpg  | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000  | 98082.000   | 98082.000   | 392328.000  | 98082.000   |
| 4     | 0   | 4   | 0   | 0   | 0   | GET    | /image/9982.jpg  | 0.000 | 0.004 | 0.008 | 0.002 | 0.004 | 0.004 | 0.004 | 0.002  | 149874.000  | 149874.000  | 599496.000  | 149874.000  |
| 4     | 0   | 4   | 0   | 0   | 0   | GET    | /image/9993.jpg  | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000  | 85546.000   | 85546.000   | 342184.000  | 85546.000   |
| 4     | 0   | 4   | 0   | 0   | 0   | GET    | /image/10001.jpg | 0.004 | 0.004 | 0.008 | 0.002 | 0.004 | 0.004 | 0.004 | 0.002  | 2272300.000 | 2272300.000 | 9089200.000 | 2272300.000 |
| 4     | 0   | 4   | 0   | 0   | 0   | GET    | /image/9995.jpg  | 0.000 | 0.004 | 0.004 | 0.001 | 0.004 | 0.004 | 0.004 | 0.002  | 123364.000  | 123364.000  | 493456.000  | 123364.000  |
| 4     | 0   | 4   | 0   | 0   | 0   | GET    | /image/9994.jpg  | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000  | 105154.000  | 105154.000  | 420616.000  | 105154.000  |
| 4     | 0   | 4   | 0   | 0   | 0   | GET    | /image/10000.png | 0.004 | 0.008 | 0.016 | 0.004 | 0.008 | 0.008 | 0.008 | 0.003  | 1056749.000 | 1056749.000 | 4226996.000 | 1056749.000 |
| 4     | 0   | 4   | 0   | 0   | 0   | GET    | /image/9996.jpg  | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000  | 374805.000  | 374805.000  | 1499220.000 | 374805.000  |
| 4     | 0   | 4   | 0   | 0   | 0   | GET    | /image/9997.jpg  | 0.004 | 0.004 | 0.016 | 0.004 | 0.004 | 0.004 | 0.004 | 0.000  | 176404.000  | 176404.000  | 705616.000  | 176404.000  |
| 4     | 0   | 4   | 0   | 0   | 0   | GET    | /image/9999.jpg  | 0.004 | 0.004 | 0.008 | 0.002 | 0.004 | 0.004 | 0.004 | 0.002  | 89928.000   | 89928.000   | 359712.000  | 89928.000   |
| 4     | 0   | 4   | 0   | 0   | 0   | GET    | /image/9998.jpg  | 0.008 | 0.008 | 0.012 | 0.003 | 0.008 | 0.008 | 0.008 | 0.003  | 61656.000   | 61656.000   | 246624.000  | 61656.000   |
| 4     | 0   | 4   | 0   | 0   | 0   | GET    | /image/10003.jpg | 0.000 | 0.004 | 0.004 | 0.001 | 0.004 | 0.004 | 0.004 | 0.002  | 1255843.000 | 1255843.000 | 5023372.000 | 1255843.000 |
| 4     | 0   | 4   | 0   | 0   | 0   | GET    | /image/10002.jpg | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000  | 135866.000  | 135866.000  | 543464.000  | 135866.000  |
| 4     | 0   | 4   | 0   | 0   | 0   | GET    | /                | 1.508 | 1.516 | 6.048 | 1.512 | 1.516 | 1.516 | 1.516 | 0.003  | 5470.000    | 5694.000    | 22475.000   | 5618.750    |
+-------+-----+-----+-----+-----+-----+--------+------------------+-------+-------+-------+-------+-------+-------+-------+--------+-------------+-------------+-------------+-------------+

ベンチマーカーによる負荷試験の実行

まずは試しに Apache HTTP Server にも付属されているベンチマーカーである ab コマンドを使用する。

$ sudo apt update
$ sudo apt install apache2-utils

ベンチマーカーはアプリケーションと同じインスタンスで動かすのでローカルホストに対して実行する。

以下は１並列で10回リクエストするだけのシンプルなパターン

$ ab -c 1 -n 10 http://localhost/

実行結果

Server Software:        nginx/1.18.0
Server Hostname:        localhost
Server Port:            80

Document Path:          /
Document Length:        34415 bytes

Concurrency Level:      1
Time taken for tests:   14.936 seconds
Complete requests:      10
Failed requests:        0
Total transferred:      347870 bytes
HTML transferred:       344150 bytes
Requests per second:    0.67 [#/sec] (mean)
Time per request:       1493.582 [ms] (mean)
Time per request:       1493.582 [ms] (mean, across all concurrent requests)
Transfer rate:          22.75 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:  1490 1494   2.6   1493    1499
Waiting:     1490 1493   2.6   1493    1499
Total:       1490 1494   2.6   1493    1499

Percentage of the requests served within a certain time (ms)
  50%   1493
  66%   1494
  75%   1494
  80%   1497
  90%   1499
  95%   1499
  98%   1499
  99%   1499
 100%   1499 (longest request)

1リクエスト辺り1493ms、1秒あたり0.67リクエスト捌けたことがわかる。

さらに、 ab コマンドが10回リクエストを投げたので直近10回分のアクセスログを alp コマンドにかけることで結果の詳細がわかる。

$ tail -n 10 /var/log/nginx/access.log | alp json -o count,method,uri,min,avg,max
+-------+--------+-----+-------+-------+-------+
| COUNT | METHOD | URI |  MIN  |  AVG  |  MAX  |
+-------+--------+-----+-------+-------+-------+
| 10    | GET    | /   | 1.488 | 1.493 | 1.500 |
+-------+--------+-----+-------+-------+-------+

平均最大最小がいずれも同じような数値なので、リクエストごとのブレはなかったことがわかる。

今回はログの末尾10行を取り出したが、実際は確実に負荷試験でのログだけを集計対象にするように、ログのローテートなどの仕組みを心がける必要がある。

パフォーマンスチューニング最初の一歩

ab コマンドを用いて負荷試験を行いながら top コマンドでリソースの状態を確認すると、mysql プロセスによって CPU がほぼ使い切られていることがわかった。また、CPUは2個あるにも関わらず片方は全然使われていないこともわかる。

top - 21:03:22 up 37 min,  3 users,  load average: 0.45, 0.24, 0.10
Tasks: 114 total,   1 running, 113 sleeping,   0 stopped,   0 zombie
%Cpu0  : 12.0 us,  0.3 sy,  0.0 ni, 87.6 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu1  : 87.1 us,  0.7 sy,  0.0 ni, 12.3 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
MiB Mem :   3865.6 total,   2369.6 free,    727.0 used,    769.0 buff/cache
MiB Swap:      0.0 total,      0.0 free,      0.0 used.   2914.4 avail Mem 

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                           
    640 mysql     20   0 1781020 434868  35376 S  96.3  11.0   2:28.23 mysqld

このことから、アプリケーションは MySQL の中にボトルネックがあることが考えられる。

MySQL のうち、どのクエリに問題があるのかを特定するために、MySQL のスロークエリ出力の機能を有効化する。

/etc/mysql/mysql.conf.d/mysqld.cnf

slow_query_log          = 1
slow_query_log_file     = /var/log/mysql/mysql-slow.log
long_query_time = 0

重要なのは long_query_time を0にし、実行時間に関わらずすべてのログを取得すること。1回あたりの実行時間が小さくても、それが大量に実行されている場合はボトルネックとなり得るので、それを見逃さないようにするのが大事。

再起動

$ sudo systemctl restart mysql

こんなログが /var/log/mysql/mysql-slow.log に出力される

# administrator command: Prepare;
# Time: 2022-11-14T12:11:16.237757Z
# User@Host: isuconp[isuconp] @ localhost []  Id:     8
# Query_time: 0.000141  Lock_time: 0.000001 Rows_sent: 1  Rows_examined: 1
SET timestamp=1668427876;
SELECT * FROM `posts` WHERE `id` = 9982;

が、目視では普通にわかりづらいので大抵はツールを使う。今回は MySQL に付属する mysqldumpslow コ
マンドを利用する。

以下のように合計実行時間が長いものが順に表示される。

$ sudo mysqldumpslow /var/log/mysql/mysql-slow.log 

Reading mysql slow query log from /var/log/mysql/mysql-slow.log
Count: 44  Time=0.05s (2s)  Lock=0.00s (0s)  Rows=2.8 (124), isuconp[isuconp]@localhost
  SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N

どうやらコメント一覧を読みこむクエリが44回実行されている。1回あたりの実行時間も50msとまずまずなので、これをどうにかすることでパフォーマンスが良くなりそうだ。

調べていくと、コメントが10万件存在するのに、 post_id にインデックスが付与されていないことから、全件検索しているようだ。

mysql> select count(*) from comments;
+----------+
| count(*) |
+----------+
|   100007 |
+----------+
1 row in set (0.01 sec)

mysql> show create table comments\G
*************************** 1. row ***************************
       Table: comments
Create Table: CREATE TABLE `comments` (
  `id` int NOT NULL AUTO_INCREMENT,
  `post_id` int NOT NULL,
  `user_id` int NOT NULL,
  `comment` text NOT NULL,
  `created_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=100008 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
1 row in set (0.01 sec)

explain を使って実行計画を観てみると、およそ全ての行へのアクセスが発生している。

mysql> explain select * from comments where post_id = 9995\G;
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: comments
   partitions: NULL
         type: ALL
possible_keys: NULL
          key: NULL
      key_len: NULL
          ref: NULL
         rows: 97209
     filtered: 10.00
        Extra: Using where
1 row in set, 1 warning (0.00 sec)

なので post_id に対するインデックスを追加してみる。

mysql> alter table comments add index post_id_idx(post_id);
Query OK, 0 rows affected (0.53 sec)
Records: 0  Duplicates: 0  Warnings: 0

explain 結果が変わる

mysql> explain select * from comments where post_id = 9995\G;
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: comments
   partitions: NULL
         type: ref
possible_keys: post_id_idx
          key: post_id_idx
      key_len: 4
          ref: const
         rows: 6
     filtered: 100.00
        Extra: NULL
1 row in set, 1 warning (0.01 sec)

同様の負荷試験を再実施するとめちゃくちゃ早くなってる。

ubuntu@ip-172-31-18-233:~$ tail -n 10 /var/log/nginx/access.log | alp json -o count,method,uri,min,avg,max
+-------+--------+-----+-------+-------+-------+
| COUNT | METHOD | URI |  MIN  |  AVG  |  MAX  |
+-------+--------+-----+-------+-------+-------+
| 10    | GET    | /   | 0.092 | 0.095 | 0.108 |
+-------+--------+-----+-------+-------+-------+

MySQL のパフォーマンスを改善できたが、CPUが2個あるのに1個しか使われていないという問題が残っている。

これはアプリケーションサーバとして使用している unicorn が、1プロセスで1リクエストしか同時に処理できないというアーキテクチャにも関わらず、unicorn ワーカーを一つしか立ち上げていないことに起因する。

なので unicorn の設定を変更して、複数プロセス起動するようにする。

worker_processes 4
preload_app true
listen "0.0.0.0:8080"

bundle プロセスが4個立ち上がり、CPUも活用されていることがわかる。

top - 13:23:18 up 34 min,  4 users,  load average: 1.18, 0.26, 0.09
Tasks: 123 total,   4 running, 119 sleeping,   0 stopped,   0 zombie
%Cpu(s): 87.0 us, 12.1 sy,  0.0 ni,  0.7 id,  0.0 wa,  0.0 hi,  0.2 si,  0.0 st
MiB Mem :   3864.0 total,   2358.2 free,    741.7 used,    764.0 buff/cache
MiB Swap:      0.0 total,      0.0 free,      0.0 used.   2890.7 avail Mem 

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                     
    672 mysql     20   0 1794932 441316  35676 S  88.0  11.2   1:20.24 mysqld                                      
   1767 isucon    20   0  192512  57656   9768 R  28.6   1.5   0:03.62 bundle                                      
   1769 isucon    20   0  188384  53488   9768 S  27.9   1.4   0:03.57 bundle                                      
   1768 isucon    20   0  187680  52640   9768 R  26.6   1.3   0:03.42 bundle                                      
   1770 isucon    20   0  188584  53608   9768 R  26.6   1.4   0:03.36 bundle

shingo.sasaki

4章シナリオを持った負荷試験

前章では単一のURLに対して負荷試験を行ったが、それはそのエンドポイントの調査にしかならず、アプリケーション全体でどこが重いのかは特定できない。

本章では、k6 を用いて実際のユーザーのユースケースに基づいて複数の画面を横断して操作するようなシナリオを同時多発的に行って重い箇所を特定していく。

https://github.com/grafana/k6

k6 は Mac 側にインストールして、シナリオの負荷試験も Mac 側から AWS に対して行うことにする。

$ brew install k6
$ k6 version
k6 v0.41.0 ((devel), go1.19.3, darwin/arm64)

トップページにアクセスするだけのシンプルなシナリオ

import http from "k6/http";

const BASE_URL = "http://54.250.181.67";

export default function () {
  http.get(`${BASE_URL}/`);
}

1並列で30秒間実行する

$ k6 run --vus 1 --duration 30s 01.js 

          /\      |‾‾| /‾‾/   /‾‾/   
     /\  /  \     |  |/  /   /  /    
    /  \/    \    |     (   /   ‾‾\  
   /          \   |  |\  \ |  (‾)  | 
  / __________ \  |__| \__\ \_____/ .io

  execution: local
     script: 01.js
     output: -

  scenarios: (100.00%) 1 scenario, 1 max VUs, 1m0s max duration (incl. graceful stop):
           * default: 1 looping VUs for 30s (gracefulStop: 30s)


running (0m30.1s), 0/1 VUs, 273 complete and 0 interrupted iterations
default ✓ [======================================] 1 VUs  30s

     data_received..................: 9.5 MB 315 kB/s
     data_sent......................: 22 kB  716 B/s
     http_req_blocked...............: avg=282.13µs min=1µs     med=4µs      max=28.72ms  p(90)=7µs      p(95)=9µs     
     http_req_connecting............: avg=276.59µs min=0s      med=0s       max=28.61ms  p(90)=0s       p(95)=0s      
     http_req_duration..............: avg=109.79ms min=99.35ms med=108.34ms max=179.52ms p(90)=117.33ms p(95)=122.59ms
       { expected_response:true }...: avg=109.79ms min=99.35ms med=108.34ms max=179.52ms p(90)=117.33ms p(95)=122.59ms
     http_req_failed................: 0.00%  ✓ 0        ✗ 273
     http_req_receiving.............: avg=5.53ms   min=140µs   med=4.52ms   max=34.94ms  p(90)=8.68ms   p(95)=10.79ms 
     http_req_sending...............: avg=24.42µs  min=7µs     med=20µs     max=184µs    p(90)=38µs     p(95)=48µs    
     http_req_tls_handshaking.......: avg=0s       min=0s      med=0s       max=0s       p(90)=0s       p(95)=0s      
     http_req_waiting...............: avg=104.23ms min=95.26ms med=102.88ms max=176.6ms  p(90)=111.13ms p(95)=115.41ms
     http_reqs......................: 273    9.066669/s
     iteration_duration.............: avg=110.26ms min=99.55ms med=108.51ms max=179.65ms p(90)=117.59ms p(95)=123.09ms
     iterations.....................: 273    9.066669/s
     vus............................: 1      min=1      max=1
     vus_max........................: 1      min=1      max=1

http_reqs から、毎秒9リクエスト処理できていたことが、http_req_duration から1リクエスト辺り平均107ms かかっていることがわかった。

もう少しシナリオテストらしいコードを書いていく。

URL 取得は共通処理なので切り出しておく。

config.js

const BASE_URL = "http://54.250.181.67";

export function url(path) {
  return `${BASE_URL}${path}`;
}

ログインしてユーザーページに移動してコメントを投稿するシナリオを書く

comments.js

import http from "k6/http";
import { check } from "k6";
import { parseHTML } from "k6/html";
import { url } from "./config.js";

export default function () {
  // ログイン
  const login_res = http.post(url("/login"), {
    account_name: "k6_user",
    password: "password",
  });
  check(login_res, {
    "is status 200": (r) => r.status === 200,
  });

  // ユーザーページへ移動
  const user_res = http.get(url("/@terra"));
  const user_doc = parseHTML(user_res.body);

  // csrf_token, post_id を取得
  const csrf_token = user_doc
    .find("input[name=csrf_token]")
    .first()
    .attr("value");
  const post_id = user_doc.find("input[name=post_id]").first().attr("value");

  // コメントを投稿する
  const comment_res = http.post(url("/comment"), {
    csrf_token: csrf_token,
    post_id: post_id,
    comment: "Hello k6!",
  });
  check(comment_res, {
    "is status 200": (r) => r.status === 200,
  });
}

フォームから画像をアップロードするシナリオも書く

postimage.js

import http from "k6/http";
import { check } from "k6";
import { parseHTML } from "k6/html";
import { url } from "./config.js";

// アップロードする画像を開く
const testImage = open("./image.jpeg", "b");

export default function () {
  // ログイン
  const login_res = http.post(url("/login"), {
    account_name: "terra",
    password: "terraterra",
  });
  const doc = parseHTML(login_res.body);

  // csrf_token, post_id を取得
  const csrf_token = doc.find("input[name=csrf_token]").first().attr("value");
  const post_id = doc.find("input[name=post_id]").first().attr("value");

  // 画像をアップロード
  http.post(url("/"), {
    csrf_token: csrf_token,
    body: "Posted by k6",
    file: http.file(testImage, "image.jpeg", "image/jpeg"),
  });
}

それぞれ実行する

$ k6 run --vus 1 comments.js

$ k6 run --vus 1 postimage.js

コメント投稿と画像アップロードができてる。

ユーザー情報をシナリオにハードコードしてると、シナリオを並列実行する際にアカウントがバッティングしてしまうため、マスターデータを用意してそれぞれで使い分けられるようにする。

accounts.json

[
  {
    "account_name": "terra",
    "password": "terraterra"
  },
  {
    "account_name": "sheri",
    "password": "sherisheri"
  },
  {
    "account_name": "janelle",
    "password": "janellejanelle"
  },
  {
    "account_name": "chasity",
    "password": "chasitychasity"
  }
]

マスターデータからランダムに1件抜き出すためのモジュールも用意

accounts.js

import { SharedArray } from "k6/data";

const accounts = new SharedArray("accounts", function () {
  return JSON.parse(open("./accounts.json"));
});

// accounts からランダムで1件取り出す
export function getAccount() {
  return accounts[Math.floor(Math.random() * accounts.length)];
}

使い方

common.js

  const account = getAccount();
  const login_res = http.post(url("/login"), {
    account_name: account.account_name,
    password: account.password,
  });

こんな感じにしてシナリオを再実行すると、実行のたび異なるユーザーでコメント投稿、画像アップロードが行われる。

あと負荷試験を開始する際に叩くことを想定してると思われる /initialize エンドポイントを呼ぶシナリオも用意しておく。

initialize.js

import { sleep } from "k6";
import http from "k6/http";
import { url } from "./config.js";

export default function () {
  http.get(url("/initialize"), {
    timeout: "10s",
  });
  sleep(1);
}

ここまでで

initialize
comments
postimage

の3種類のシナリオが用意できたので、これらを組み合わせた統合シナリオを実行する。

統合シナリオは options というオブジェクトを export すればOK

integrated.js

import initialize from "./initialize.js";
import comment from "./comment.js";
import postimage from "./postimage.js";

// k6 が各関数を実行できるように
export { initialize, comment, postimage };

// 統合シナリオの定義
export const options = {
  scenarios: {
    // 初期化シナリオは1回のみ1並列で実行
    initialize: {
      executor: "shared-iterations",
      vus: 1,
      iterations: 1,
      maxDuration: "10s",
      exec: "initialize",
    },
    // コメントシナリオは4並列で実行30秒実行
    comment: {
      executor: "constant-vus",
      vus: 4,
      duration: "30s",
      exec: "comment",
      startTime: "12s", // initialize が終わってから
    },
    // 画像投稿シナリオは2並列で実行30秒実行
    postimage: {
      executor: "constant-vus",
      vus: 2,
      duration: "30s",
      exec: "postimage",
      startTime: "12s", // initialize が終わってから
    },
  },
};

// default export は空でOK
export default function () {}

各シナリオの実行オプションはコードで定義しているので、実行コマンドは run だけで良い。

$ k6 run integrated.js

結果

$ k6 run integrated.js 

          /\      |‾‾| /‾‾/   /‾‾/   
     /\  /  \     |  |/  /   /  /    
    /  \/    \    |     (   /   ‾‾\  
   /          \   |  |\  \ |  (‾)  | 
  / __________ \  |__| \__\ \_____/ .io

  execution: local
     script: integrated.js
     output: -

  scenarios: (100.00%) 3 scenarios, 7 max VUs, 1m12s max duration (incl. graceful stop):
           * initialize: 1 iterations shared among 1 VUs (maxDuration: 10s, exec: initialize, gracefulStop: 30s)
           * comment: 4 looping VUs for 30s (exec: comment, startTime: 12s, gracefulStop: 30s)
           * postimage: 2 looping VUs for 30s (exec: postimage, startTime: 12s, gracefulStop: 30s)


running (0m42.4s), 0/7 VUs, 390 complete and 0 interrupted iterations
initialize ✓ [======================================] 1 VUs  01.1s/10s  1/1 shared iters
comment    ✓ [======================================] 4 VUs  30s       
postimage  ✓ [======================================] 2 VUs  30s       

     ✓ is status 200

     checks.........................: 100.00% ✓ 456       ✗ 0   
     data_received..................: 18 MB   431 kB/s
     data_sent......................: 3.8 MB  90 kB/s
     http_req_blocked...............: avg=322µs    min=0s      med=4µs      max=46.65ms  p(90)=6µs      p(95)=7µs     
     http_req_connecting............: avg=315.89µs min=0s      med=0s       max=46.6ms   p(90)=0s       p(95)=0s      
     http_req_duration..............: avg=100.75ms min=19.86ms med=69.35ms  max=361.7ms  p(90)=202.14ms p(95)=219.65ms
       { expected_response:true }...: avg=100.75ms min=19.86ms med=69.35ms  max=361.7ms  p(90)=202.14ms p(95)=219.65ms
     http_req_failed................: 0.00%   ✓ 0         ✗ 1785
     http_req_receiving.............: avg=2.26ms   min=15µs    med=294µs    max=38.14ms  p(90)=5.84ms   p(95)=7.74ms  
     http_req_sending...............: avg=44.23µs  min=3µs     med=21µs     max=1.81ms   p(90)=82.6µs   p(95)=232.99µs
     http_req_tls_handshaking.......: avg=0s       min=0s      med=0s       max=0s       p(90)=0s       p(95)=0s      
     http_req_waiting...............: avg=98.44ms  min=19.3ms  med=69.05ms  max=328.62ms p(90)=196.74ms p(95)=214.95ms
     http_reqs......................: 1785    42.138486/s
     iteration_duration.............: avg=467.49ms min=265.8ms med=478.74ms max=1.08s    p(90)=576.4ms  p(95)=604.56ms
     iterations.....................: 390     9.206728/s
     vus............................: 6       min=0       max=6 
     vus_max........................: 7       min=7       max=7

k6 の出力は全てのリクエストをあわせた結果なので、ここからURL別の集計結果を得たい場合は、再度 alp コマンドを使うとよい。

nginx のログを一度削除してから負荷試験を再実施。生成された /var/log/nginx/access.log.json を alp にかける。

$ cat /var/log/nginx/access.log | alp json -m "/posts/[0-9]+,@\w+" --sort sum -r -o count,method,uri,min,avg,max,sum
+-------+--------+---------------+-------+-------+-------+--------+
| COUNT | METHOD |      URI      |  MIN  |  AVG  |  MAX  |  SUM   |
+-------+--------+---------------+-------+-------+-------+--------+
| 387   | GET    | /             | 0.096 | 0.165 | 0.340 | 63.736 |
| 225   | GET    | @\w+          | 0.076 | 0.142 | 0.272 | 31.932 |
| 387   | POST   | /login        | 0.008 | 0.045 | 0.156 | 17.280 |
| 387   | GET    | /posts/[0-9]+ | 0.000 | 0.019 | 0.108 | 7.208  |
| 225   | POST   | /comment      | 0.004 | 0.023 | 0.136 | 5.084  |
| 162   | POST   | /             | 0.004 | 0.023 | 0.124 | 3.692  |
| 1     | GET    | /initialize   | 0.040 | 0.040 | 0.040 | 0.040  |
+-------+--------+---------------+-------+-------+-------+--------+

この結果から、トップページやユーザーページが大量に呼ばれる割には遅いため、ボトルネックとなっていると考えることができる。

このように、ユーザーのアクセスパターンに応じたシナリオを用いて負荷試験を行うことで、頻繁に呼び出されている箇所や、相対的に重い部分が特定でき、アプリケーションのボトルネックの特定に役立つ。

shingo.sasaki

積読

このスクラップは2023/09/12にクローズされました

1章 チューニングの基礎知識

Web サービスが高速であることは現代では必須要件と言える

高速の定義

速さとキャパシティ

必要十分なキャパシティ

推測するな計測せよ

ボトルネックにだけアプローチする

2章 モニタリング

モニタリングには以下の2種類がある

モニタリングツールには Pull 型と Push 型がある

グラフの読み方にご注意

3章 基礎的な負荷試験

private-isu

負荷試験の準備

ベンチマーカーによる負荷試験の実行

パフォーマンスチューニング最初の一歩

4章 シナリオを持った負荷試験

1章チューニングの基礎知識

2章モニタリング

3章基礎的な負荷試験

4章シナリオを持った負荷試験