AWS for Games Advent Calendar 2023 1日目の記事です。
はじめに
ゲーム開発にとどまらず、データのキャッシュ用途や柔軟なデータ型を利用することでリーダーボードやPub/Subなど幅広い用途で利用されるRedisと、RedisのマネージドサービスであるElastiCache for Redis。用途によっては重要な役割を持ち、コネクション数やコマンドの実行数も大量になりがちなため、Redis (ElastiCache) の負荷が高くなることはしばしばあると思います。
AWS re:Invent 2023ではElastiCache ServerlessがGAされ、大変興味深い発表でした。ElastiCache Serverlessではトラフィックパターンに基づいてキャパシティが自動スケールするため、高負荷な環境でもスケールしやすくなるメリットがあります。
一方で、キャパシティに合わせて料金もスケールするので、意図しないアプリケーションのバグや非効率な実装による高負荷は適切に対処する必要があります。高負荷の原因を正しく特定し、アプリケーション側の改善を図ることで、コストとパフォーマンスのバランスを取ることが重要だと思います。
その高負荷の原因(アプリケーションが正しく利用していない可能性)や傾向を調査する際のTipsを紹介します。私の経験上、ゲーム開発の現場では、アプリケーションとインフラの担当部隊が分かれている場合があり、このような課題の調査責任が曖昧になりがちだったことを多く経験しました。楽に調査ができて問題解決がスムーズになれば嬉しいです!
CloudWatch のメトリクスを見る
まずは、標準で備わっているElastiCacheのメトリクスを確認することから始めるのが一般的です。以下のようなガイドも用意されているため、どのメトリクスを注視すべきかの参考になります。
メトリクスを確認して負荷の傾向を把握し、対策を立てる際には、以下のようなre:PostのQ&Aも参考になります。
対策としては、より大きいインスタンスタイプに変更することや、クラスターモードで運用しているクラスターに対してノードを追加することなどが考えられます。
具体的にボトルネックになっているコマンドを特定するには、以下に記載するような手段を取る必要があります。
CloudWatch Logsにスローログを出力する
スローログは、エンジンバージョン6.0以降を使用するRedisクラスターでサポートされており、明示的に有効にすることでログを出力できます。ログの転送先として、CloudWatch LogsかKinesis Data Firehoseを選択できます。
パラメータグループの“slowlog-log-slower-than”で閾値(μs)を設定することで、何μs以上かかったコマンドをスローログとして出力することができます。調査目的でとにかく全て出力するならば、「0」を設定して全コマンドを出力するのが良いでしょう。
出力結果はCloudWatch Logsに出力した際の例です。
インサイトで絞り込みやソートが可能なので、調査がしやすくなりそうです。
ただし、上記のようにコマンドの引数は丸められ、key/valueを特定できません。また、CLIENT SETNAMEコマンドで任意の名前をクライアント名として付与できるものの、"ClientName"の文字列が途中で丸められているため、スタックトレースのようにファイル名や行番号を含めた長い文字列を登録することは難しそうです。redis-cliからSHOWLOGコマンドを使用すれば、より詳細なスローログが確認できるので、こちらも併用すると良いでしょう。
SLOWLOG GET 1
1) 1) (integer) 62054744
2) (integer) 1701266759
3) (integer) 0
4) 1) "SET"
2) "key"
3) "value"
5) "172.31.12.235:59914"
6) "my-app#Error_at_file:///home/ec2-user/environment/adv2023/test.mjs:7:37_at_file:///home/ec2-user/environment/adv2023/test.mjs:7:92_at_runMicrotasks_(<anonymous>)_at_processTicksAndRejections_(node:internal/process/task_queues:96:5)"
Redis MONITOR
Redis MONITORは、Redisサーバーによって処理されるすべてのコマンドをストリームで返すデバッグコマンドです。データベース内で何が起きているかを理解するのに役立ちます。このコマンドはredis-cliに実装されており、ElastiCacheでも利用できます。
どのようなコマンドが流れているかを確認するのであれば、CloudWatch Logsにスローログとして出力する方が後から検索しやすいですが、手軽さではRedis MONITORの方が便利でしょう。
ただし、MONITORは全コマンドをストリームするため負荷が高く、ドキュメントによると1つのMONITORクライアントを実行するだけでスループットが50%以上低下する場合があるそうです。したがって、本番環境で実行する際はこの点に注意が必要です。
MONITOR
1701267313.987149 [0 172.31.12.235:45766] "CLIENT" "SETNAME" "my-app#Error_at_file:///home/ec2-user/environment/adv2023/test.mjs:7:37_at_file:///home/ec2-user/environment/adv2023/test.mjs:7:92_at_runMicrotasks_(<anonymous>)_at_processTicksAndRejections_(node:internal/process/task_queues:96:5)"
1701267313.987625 [0 172.31.12.235:45766] "SET" "key" "value"
1701267313.987981 [0 172.31.12.235:45766] "GET" "key"
1701267313.990282 [0 172.31.12.235:45784] "CLIENT" "SETNAME" "my-app#Error_at_file:///home/ec2-user/environment/adv2023/test.mjs:7:37_at_file:///home/ec2-user/environment/adv2023/test.mjs:7:92_at_runMicrotasks_(<anonymous>)_at_processTicksAndRejections_(node:internal/process/task_queues:96:5)"
1701267313.990723 [0 172.31.12.235:45784] "SET" "key" "value"
1701267313.991091 [0 172.31.12.235:45784] "GET" "key"
....
redis-faina
Facebook製のツール (現在アーカイブ済み)
Redis MONITORコマンドの結果を解析して、統計情報を表示してくれるため、頻繁に実行されているコマンドやキーを特定したい場合に役立ちます。Pythonの標準パッケージのみで実装されているため導入が簡単な点が良いでしょう。ただし、Redis MONITORを使用するツールであることに留意が必要です。
以下は実行例
redis-cli -h エンドポイント MONITOR | head -n 10000 | ./redis-faina.py
Overall Stats
========================================
Lines Processed 10000
Commands/Sec 1029.13
Top Prefixes
========================================
key 1700 (17.00%)
counter 600 (6.00%)
myset 500 (5.00%)
Top Keys
========================================
mylist 4900 (49.00%)
key:__rand_int__ 1700 (17.00%)
myset 1099 (10.99%)
counter:__rand_int__ 600 (6.00%)
myset:__rand_int__ 500 (5.00%)
Top Commands
========================================
LRANGE 2000 (20.00%)
PING 1200 (12.00%)
LPUSH 1100 (11.00%)
INCR 600 (6.00%)
SET 600 (6.00%)
GET 600 (6.00%)
LPOP 600 (6.00%)
RPOP 600 (6.00%)
Command Time (microsecs)
========================================
Median 29.25
75% 44.25
90% 74.0
99% 9279.0
Heaviest Commands (microsecs)
========================================
MSET 5253914.25
LRANGE 924210.25
PING 559702.75
LPUSH 513888.25
INCR 324686.0
SET 324561.25
LPOP 320195.0
GET 308743.0
Slowest Calls
========================================
1057570.0 "MSET" "key:__rand_int__" "xxx" "key:__rand_int__" "xxx" "key:__rand_int__" "xxx" ...
1040329.0 "MSET" "key:__rand_int__" "xxx" "key:__rand_int__" "xxx" "key:__rand_int__" "xxx" ...
1040218.0 "MSET" "key:__rand_int__" "xxx" "key:__rand_int__" "xxx" "key:__rand_int__" "xxx" ...
1032906.0 "MSET" "key:__rand_int__" "xxx" "key:__rand_int__" "xxx" "key:__rand_int__" "xxx" ...
1030291.0 "MSET" "key:__rand_int__" "xxx" "key:__rand_int__" "xxx" "key:__rand_int__" "xxx" ...
86542.0 "LPOP" "mylist"
80689.0 "LPUSH" "mylist" "xxx"
78757.0 "RPOP" "mylist"
redis-traffic-stats
tcpdumpのpcapデータを解析してレポートを作成するため、Redis MONITORと比べてクラスターへの負荷がかからない点や、コマンドの転送バイト数の統計も出力できる点が優れています。
ただし、ビルド済みの配布ファイルが404になっており、ソースからビルドする場合はPerl依存パッケージなどのインストールが必要なため、導入は少しハードルが高いです。
# cpanm install
$ curl -L https://cpanmin.us | perl - --sudo App::cpanminus
$ cpanm --local-lib=~/perl5 local::lib && eval $(perl -I ~/perl5/lib/perl5/ -Mlocal::lib)
# redis-traffic-stats install
$ git clone https://github.com/hirose31/redis-traffic-stats.git
$ cd redis-traffic-stats/
# Net::Pcap のインストールでエラーが出たので、libpcap-develをインストール: sudo yum install libpcap-devel
$ cpanm --installdeps .
$ perl Build.PL
$ ./Build
$ ./Build test
$ ./Build install
使用例
$ tcpdump -s 65535 tcp port 6379 -w redis.pcap -i eth0 $ redis-traffic-stats -r redis.pcap
pcapfile: redis.pcap
read pcap data and rebuild TCP stream ......................................... done (41057 pkt)
process Redis protocol ............ done
# redis-traffic-stats
## Summary
* Duration:
* 2023-11-29 15:16:10 - 2023-11-29 15:16:16 (6s)
* Total Traffic:
* 1607003 bytes (267833.83 bytes/sec)
* Total Requests:
* 6486 requests (Avg 1081.00 req/sec, Peak 1621.00 req/sec)
## Top Commands
### By count
Command | Count | Pct | Req/sec
-----------------|-------:|-------:|---------:
LRANGE | 1445 | 22.28 | 240.83
LPUSH | 733 | 11.30 | 122.17
PING | 690 | 10.64 | 115.00
HSET | 396 | 6.11 | 66.00
LPOP | 393 | 6.06 | 65.50
GET | 377 | 5.81 | 62.83
SET | 371 | 5.72 | 61.83
SADD | 371 | 5.72 | 61.83
MSET | 371 | 5.72 | 61.83
INCR | 343 | 5.29 | 57.17
### By traffic
Command | Bytes | Byte/sec
-----------------|----------:|-------------:
LRANGE | 1588650 | 264775.00
LPUSH | 5131 | 855.17
PING | 2760 | 460.00
INCR | 2401 | 400.17
RPUSH | 2394 | 399.00
LPOP | 1179 | 196.50
GET | 1131 | 188.50
RPOP | 1026 | 171.00
SET | 742 | 123.67
MSET | 742 | 123.67
## Command Detail
### LRANGE
Key | Bytes | Byte/sec | Count | Pct | Req/sec
---------------------|----------:|-------------:|-------:|-------:|---------:
mylist | 1588650 | 264775.00 | 1445 | 100.00 | 240.83
### LPUSH
Key | Bytes | Byte/sec | Count | Pct | Req/sec
---------------------|----------:|-------------:|-------:|-------:|---------:
mylist | 5131 | 855.17 | 733 | 100.00 | 122.17
### PING
Key | Bytes | Byte/sec | Count | Pct | Req/sec
---------------------|----------:|-------------:|-------:|-------:|---------:
### INCR
Key | Bytes | Byte/sec | Count | Pct | Req/sec
---------------------|----------:|-------------:|-------:|-------:|---------:
counter:__rand_int__ | 2401 | 400.17 | 343 | 100.00 | 57.17
### RPUSH
Key | Bytes | Byte/sec | Count | Pct | Req/sec
---------------------|----------:|-------------:|-------:|-------:|---------:
mylist | 2394 | 399.00 | 342 | 100.00 | 57.00
### LPOP
Key | Bytes | Byte/sec | Count | Pct | Req/sec
---------------------|----------:|-------------:|-------:|-------:|---------:
mylist | 1179 | 196.50 | 393 | 100.00 | 65.50
### GET
Key | Bytes | Byte/sec | Count | Pct | Req/sec
---------------------|----------:|-------------:|-------:|-------:|---------:
key:__rand_int__ | 1131 | 188.50 | 377 | 100.00 | 62.83
### RPOP
Key | Bytes | Byte/sec | Count | Pct | Req/sec
---------------------|----------:|-------------:|-------:|-------:|---------:
mylist | 1026 | 171.00 | 342 | 100.00 | 57.00
### SET
Key | Bytes | Byte/sec | Count | Pct | Req/sec
---------------------|----------:|-------------:|-------:|-------:|---------:
key:__rand_int__ | 742 | 123.67 | 371 | 100.00 | 61.83
### MSET
Key | Bytes | Byte/sec | Count | Pct | Req/sec
---------------------|----------:|-------------:|-------:|-------:|---------:
key:__rand_int__ | 742 | 123.67 | 371 | 100.00 | 61.83
### HSET
Key | Bytes | Byte/sec | Count | Pct | Req/sec
---------------------|----------:|-------------:|-------:|-------:|---------:
myset:__rand_int__ | 396 | 66.00 | 396 | 100.00 | 66.00
### SADD
Key | Bytes | Byte/sec | Count | Pct | Req/sec
---------------------|----------:|-------------:|-------:|-------:|---------:
myset | 371 | 61.83 | 371 | 100.00 | 61.83
### SPOP
Key | Bytes | Byte/sec | Count | Pct | Req/sec
---------------------|----------:|-------------:|-------:|-------:|---------:
myset | 80 | 13.33 | 312 | 100.00 | 52.00
## Slow Commands
Time | Command
------:|------------------------------------------------------------------------
0.044 | LRANGE mylist 0 599
0.044 | LRANGE mylist 0 599
0.043 | LRANGE mylist 0 599
0.043 | SADD myset element:__rand_int__
0.043 | LRANGE mylist 0 599
0.043 | LRANGE mylist 0 599
0.043 | LRANGE mylist 0 599
0.042 | SADD myset element:__rand_int__
0.042 | LRANGE mylist 0 599
0.042 | LRANGE mylist 0 599
さいごに
以上、ElastiCache for Redis の高負荷の原因を特定するに役立つ情報でした。
他にも有用な情報などございましたら、コメントや編集リクエスト歓迎しています！
(免責) 本記事の内容はあくまでも個人の意見であり、所属する企業や団体は関係ございません。