ISUCONで学ぶObservability入門
限られた時間（業務時間）のなかでシステムのパフォーマンスを改善するときには メトリクスを見ながら効果のある修正を行っていきたいです。
具体的には Web のパフォーマンスチューニングを行う上で以下のような指標を計測したいです。
- cpu, load, ram, network, i/o といったサーバーの概要を捉える指標
- DB のクエリ別のリソース使用状況 (slow-query-log)
- API のエンドポイント別のパフォーマンス
- アプリケーションの関数ごとのリソース使用状況
Web パフォーマンスチューニングの業界では、LINE\Yahoo 社が主催している「ISUCON」と呼ばれるパフォーマンスチューニングコンテストが年に一度開かれています。 今年は 11/25 に ISUCON13 が開催され私も参加してきました。
ISUCON は競技である以上、 デプロイと計測には定石が共有されています。
本記事では、ISUCON に参加するにあたって勉強したプロファイル(計測)手法についてまとめます。
(導入とカスタマイズができるだけ簡単なもの&無料なものが好まれるため、長期的な計測をする際にはもっといい方法が沢山あると思います。)
netdata
サーバーのモニタリングツールです。 アプリケーションごとの CPU 使用率やディスク IO、ネットワークなどの確認に使っています。
pt-query-digester
PECONA 社が公開している MySQL のスロークエリの統計を取るコマンドツールです。 以下のようなサマリーとそれぞれの詳細を知れます。 Response time は総時間, Calls はコール数, R/Call はクエリ一回あたりの時間です。 詳細を見ると Exec time, Lock time などの分布を確認できます。 今回の計測では全体の 23%の時間を占めているこのクエリが悪さをしていそうです。
SELECT IFNULL(SUM(l2.tip), 0) FROM users u
INNER JOIN livestreams l ON l.user_id = u.id
INNER JOIN livecomments l2 ON l2.livestream_id = l.id
WHERE u.id = 618\G
pt-query-digester サマリ
# 11.4s user time, 10ms system time, 30.62M rss, 36.66M vsz
# Current date: Sat Nov 25 06:41:12 2023
# Hostname: ip-192-168-0-13
# Files: /tmp/slow_query_20231025063929.log
# Overall: 171.00k total, 66 unique, 2.59k QPS, 5.16x concurrency ________
# Time range: 2023-11-25T06:39:37 to 2023-11-25T06:40:43
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 341s 1us 350ms 2ms 6ms 8ms 194us
# Lock time 978ms 0 38ms 5us 1us 200us 1us
# Rows sent 640.81k 0 7.40k 3.84 0.99 70.59 0.99
# Rows examine 37.03M 0 14.12k 227.08 49.17 1.42k 0.99
# Query size 10.12M 5 435 62.04 158.58 50.64 40.45
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ============================= ============= ===== ====== ===== ====
# 1 0xF1B8EF06D6CA63B24BFF433E... 78.7247 23.1% 10412 0.0076 0.02 SELECT users livestreams livecomments
# 2 0x64CC8A4E8E4B390203375597... 66.6257 19.6% 1003 0.0664 0.01 SELECT ng_words
# 3 0x59F1B6DD8D9FEC059E55B3BF... 25.8362 7.6% 779 0.0332 0.01 SELECT reservation_slots
# 4 0xEDE18C1523658A19E07525EA... 20.7467 6.1% 297 0.0699 0.01 SELECT ng_words
# 5 0xFFFCA4D67EA0A788813031B8... 16.0878 4.7% 6484 0.0025 0.01 COMMIT
# 6 0xD6032FE08E1FE706A928B8B7... 15.9029 4.7% 28505 0.0006 0.00 SELECT livestreams
# 7 0xDB74D52D39A7090F224C4DEE... 14.8011 4.3% 10414 0.0014 0.00 SELECT users livestreams reactions
# 8 0xEA1E6309EEEFF9A6831AD2FB... 13.4922 4.0% 26138 0.0005 0.00 SELECT users
# 9 0xB08B7B7486D2DFE2F2FE9CE7... 8.6992 2.6% 115 0.0756 0.01 SELECT ng_words
# 10 0xFD38427AE3D09E3883A680F7... 7.3614 2.2% 8188 0.0009 0.00 SELECT livestreams livecomments
# 11 0xC499D81D570D361DB61FC43A... 7.1177 2.1% 8190 0.0009 0.00 SELECT livestreams reactions
# 12 0x859BBB7E9D760686137A9444... 7.0589 2.1% 261 0.0270 0.01 DELETE records
# 13 0xA3401CA3ABCC04C3AB221DB8... 6.1253 1.8% 70 0.0875 0.02 UPDATE reservation_slots
# 14 0x7F9C0C0BA9473953B723EE16... 5.8574 1.7% 71 0.0825 0.01 SELECT reservation_slots
# 15 0x50445823239A29D3A1BF75B2... 5.7238 1.7% 8845 0.0006 0.00 SELECT icons
# 16 0xF5C7940F264BAB49FBD63A1F... 5.5437 1.6% 9506 0.0006 0.00 SELECT icons
# 17 0x3F155F5E71EFF856F0CF7B84... 5.2305 1.5% 9111 0.0006 0.02 SELECT users
# 18 0x41F805E95754958A974F41AE... 3.8622 1.1% 288 0.0134 0.01 SELECT livecomments
# 19 0x9AC623FA477E73A44D191D29... 3.6877 1.1% 522 0.0071 0.01 SELECT records
# 20 0x9E2DA589A20EC24C34E11DDE... 2.1351 0.6% 15127 0.0001 0.00 START
# 21 0x42EF7D7D98FBCC9723BF896E... 2.0447 0.6% 261 0.0078 0.01 SELECT records
# 22 0xFFF66E9B3D962FA319C8068B... 2.0285 0.6% 8891 0.0002 0.00 ROLLBACK
# 23 0xF3A502CCF34F7DA288CC1B75... 1.7494 0.5% 1003 0.0017 0.01 INSERT livecomments
# 24 0x4B6FA79E206C6CED71D433A2... 1.6588 0.5% 1492 0.0011 0.00 SELECT
# 25 0x38BC86A45F31C6B1EE324671... 1.4736 0.4% 672 0.0022 0.00 SELECT themes
# 26 0xDA556F9115773A1A99AA0165... 1.2149 0.4% 1566 0.0008 0.17 ADMIN PREPARE
# 27 0xB78E63D0D9C72DDDAB7A3E53... 0.8256 0.2% 696 0.0012 0.00 SELECT livecomments
# 28 0xAD0C28443E1E5CFAFF1569DB... 0.6944 0.2% 692 0.0010 0.00 SELECT reactions
# 29 0x9EAD6C0CE525E3693EE27FFC... 0.6860 0.2% 759 0.0009 0.11 SELECT livestreams
# 30 0xF7144185D9A142A426A36DC5... 0.6688 0.2% 1108 0.0006 0.00 SELECT livestream_tags
# 31 0x24C44C3518CE12293EF12410... 0.6642 0.2% 310 0.0021 0.00 SELECT livestreams
# 32 0x3D83BC87F3B3A00D571FFC81... 0.6585 0.2% 261 0.0025 0.00 SELECT records
# 33 0x5AEB6E4A781A3854CF642125... 0.5565 0.2% 691 0.0008 0.00 INSERT reactions
# 34 0x0B69134CEB7DC9D7EACFAF38... 0.5083 0.1% 288 0.0018 0.01 DELETE livecomments
# 35 0x651E3772B8767A368CB47EE7... 0.4191 0.1% 12 0.0349 0.01 SELECT livestream_tags
# 36 0x77FB9E134D073862D1E78FEE... 0.4129 0.1% 261 0.0016 0.00 INSERT records
# 37 0xD2A0864774622BA36F655749... 0.4016 0.1% 250 0.0016 0.01 INSERT themes
# 38 0x050F7D44808F43E5D33D0B90... 0.3931 0.1% 3 0.1310 0.00 SELECT livestreams
# 39 0x8F7679D452333ED3C7D60D22... 0.3753 0.1% 1816 0.0002 0.01 ADMIN RESET STMT
# 40 0x544239977D2094F805A7B062... 0.2831 0.1% 82 0.0035 0.12 SELECT tags
# MISC 0xMISC 2.2199 0.7% 5556 0.0004 0.0 <26 ITEMS>
pt-query-digester 詳細 (Query 1)
# Query 1: 200.23 QPS, 1.51x concurrency, ID 0xF1B8EF06D6CA63B24BFF433E06CCEB22 at byte 13967751
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.02
# Time range: 2023-11-25T06:39:46 to 2023-11-25T06:40:38
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 6 10412
# Exec time 23 79s 128us 92ms 8ms 33ms 12ms 2ms
# Lock time 10 100ms 0 8ms 9us 1us 153us 1us
# Rows sent 1 10.17k 1 1 1 1 0 1
# Rows examine 17 6.62M 0 2.82k 666.52 2.16k 966.25 8.91
# Query size 16 1.64M 163 166 164.99 158.58 0 158.58
# String:
# Databases isupipe
# Hosts localhost
# Users isucon
# Query_time distribution
# 1us
# 10us
# 100us ################################################################
# 1ms ###################################################
# 10ms ######################################
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isupipe` LIKE 'users'\G
# SHOW CREATE TABLE `isupipe`.`users`\G
# SHOW TABLE STATUS FROM `isupipe` LIKE 'livestreams'\G
# SHOW CREATE TABLE `isupipe`.`livestreams`\G
# SHOW TABLE STATUS FROM `isupipe` LIKE 'livecomments'\G
# SHOW CREATE TABLE `isupipe`.`livecomments`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT IFNULL(SUM(l2.tip), 0) FROM users u
INNER JOIN livestreams l ON l.user_id = u.id
INNER JOIN livecomments l2 ON l2.livestream_id = l.id
WHERE u.id = 618\G
alp
リバースプロキシのアクセスログの集計ツールです。 以下のようなメトリクスを収集できます。 エンドポイントは正規表現でグループ化できます。 /api/user/[a-zA-Z0-9]+/icon, /api/user/[a-zA-Z0-9]+/statistics が重いです。
+-------+-----+-----+------+--------+---------------------------------------+-------+--------+---------+--------+--------+
| COUNT | 5XX | 4XX | 2XX | METHOD | URI | MIN | MAX | SUM | AVG | P90 |
+-------+-----+-----+------+--------+---------------------------------------+-------+--------+---------+--------+--------+
| 8851 | 0 | 2 | 8849 | GET | /api/user/[a-zA-Z0-9]+/icon | 0.004 | 0.424 | 156.472 | 0.018 | 0.040 |
| 13 | 0 | 5 | 8 | GET | /api/user/[a-zA-Z0-9]+/statistics | 2.540 | 20.004 | 149.436 | 11.495 | 20.004 |
| 1066 | 0 | 6 | 1060 | POST | /api/livestream/[0-9]+/livecomment | 0.004 | 0.316 | 113.868 | 0.107 | 0.156 |
| 771 | 0 | 1 | 770 | GET | /api/livestream/[0-9]+/livecomment | 0.004 | 0.392 | 56.888 | 0.074 | 0.160 |
| 806 | 0 | 2 | 804 | GET | /api/livestream/[0-9]+/reaction | 0.004 | 0.336 | 49.800 | 0.062 | 0.140 |
| 263 | 1 | 3 | 259 | POST | /api/register | 0.004 | 0.684 | 49.304 | 0.187 | 0.268 |
| 100 | 0 | 4 | 96 | POST | /api/livestream/reservation | 0.004 | 1.304 | 46.956 | 0.470 | 0.944 |
| 5 | 0 | 3 | 2 | GET | /api/livestream/[0-9]+/statistics | 2.564 | 13.684 | 42.768 | 8.554 | 13.684 |
| 298 | 0 | 0 | 298 | GET | /api/livestream/[0-9]+/ngwords | 0.004 | 0.296 | 28.224 | 0.095 | 0.148 |
| 116 | 0 | 0 | 116 | POST | /api/livestream/[0-9]+/moderate | 0.008 | 0.424 | 20.108 | 0.173 | 0.272 |
| 333 | 0 | 1 | 332 | GET | /api/livestream/search? | 0.008 | 0.832 | 18.784 | 0.056 | 0.080 |
| 715 | 0 | 0 | 715 | POST | /api/livestream/[0-9]+/reaction | 0.004 | 0.172 | 18.128 | 0.025 | 0.056 |
| 857 | 0 | 0 | 857 | GET | /api/livestream | 0.004 | 0.344 | 15.024 | 0.018 | 0.044 |
| 456 | 34 | 0 | 422 | GET | /api/livestream/[0-9]+/report | 0.004 | 0.180 | 9.704 | 0.021 | 0.052 |
| 260 | 0 | 0 | 260 | POST | /api/icon | 0.004 | 0.184 | 9.152 | 0.035 | 0.076 |
| 1 | 0 | 0 | 1 | POST | /api/initialize | 8.472 | 8.472 | 8.472 | 8.472 | 8.472 |
| 267 | 0 | 2 | 265 | POST | /api/login | 0.004 | 0.148 | 4.972 | 0.019 | 0.044 |
| 86 | 0 | 0 | 86 | GET | /api/tag | 0.004 | 0.204 | 2.088 | 0.024 | 0.056 |
| 73 | 0 | 0 | 73 | POST | /api/livestream/[0-9]+/enter | 0.004 | 0.084 | 1.532 | 0.021 | 0.048 |
| 64 | 0 | 0 | 64 | DELETE | /api/livestream/[0-9]+/exit | 0.004 | 0.124 | 1.228 | 0.019 | 0.044 |
| 12 | 0 | 0 | 12 | GET | /api/user/[a-zA-Z0-9]+/theme | 0.004 | 0.032 | 0.116 | 0.010 | 0.020 |
| 1 | 0 | 0 | 1 | GET | /api/user/yasuhiro280/livestream | 0.024 | 0.024 | 0.024 | 0.024 | 0.024 |
| 1 | 0 | 0 | 1 | GET | /api/user/mtanaka1/livestream | 0.012 | 0.012 | 0.012 | 0.012 | 0.012 |
| 1 | 0 | 0 | 1 | GET | /api/user/kanasasaki0/livestream | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 |
| 1 | 0 | 0 | 1 | GET | /api/user/csasaki0/livestream | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 |
| 1 | 0 | 0 | 1 | GET | /api/user/yukitanaka0/livestream | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 |
| 1 | 0 | 0 | 1 | GET | /api/user/yamazakikyosuke0/livestream | 0.004 | 0.004 | 0.004 | 0.004 | 0.004 |
| 1 | 0 | 0 | 1 | GET | /api/user/test | 0.004 | 0.004 | 0.004 | 0.004 | 0.004 |
| 1 | 0 | 0 | 1 | GET | /api/livestream/7497 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
| 1 | 0 | 0 | 1 | GET | /api/payment | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
| 3 | 0 | 0 | 3 | GET | /api/user/me | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
+-------+-----+-----+------+--------+---------------------------------------+-------+--------+---------+--------+--------+
pprof
Go のプロファイリングツールで CPU 負荷や処理時間、メモリ使用量を計測して表示してくれます。 以下のように CPU の実行時間をフレームグラフにすると見やすいです。 上から下に関数がよびだされています。
まとめ
モニタリングは継続的なテストとも言われています。 STG, PROD 環境問わず、こうした指標を常に持っておくことで安心してデプロイすることができるのではないかと思います。