ElastiCache for Redis の高負荷の原因を特定するに役立つ情報

[AWS for Games Advent Calendar 2023](https://qiita.com/advent-calendar/2023/aws-for-games) 1日目の記事です。

## はじめに

ゲーム開発にとどまらず、データのキャッシュ用途や柔軟なデータ型を利用することでリーダーボードやPub/Subなど幅広い用途で利用されるRedisと、RedisのマネージドサービスであるElastiCache for Redis。用途によっては重要な役割を持ち、コネクション数やコマンドの実行数も大量になりがちなため、Redis (ElastiCache) の負荷が高くなることはしばしばあると思います。

AWS re:Invent 2023ではElastiCache ServerlessがGAされ、大変興味深い発表でした。ElastiCache Serverlessではトラフィックパターンに基づいてキャパシティが自動スケールするため、高負荷な環境でもスケールしやすくなるメリットがあります。
一方で、キャパシティに合わせて料金もスケールするので、意図しないアプリケーションのバグや非効率な実装による高負荷は適切に対処する必要があります。高負荷の原因を正しく特定し、アプリケーション側の改善を図ることで、コストとパフォーマンスのバランスを取ることが重要だと思います。

https://aws.amazon.com/jp/blogs/aws/amazon-elasticache-serverless-for-redis-and-memcached-now-generally-available/

その高負荷の原因(アプリケーションが正しく利用していない可能性)や傾向を調査する際のTipsを紹介します。私の経験上、ゲーム開発の現場では、アプリケーションとインフラの担当部隊が分かれている場合があり、このような課題の調査責任が曖昧になりがちだったことを多く経験しました。楽に調査ができて問題解決がスムーズになれば嬉しいです!

## CloudWatch のメトリクスを見る

![Screenshot 2023-11-29 at 20.26.53.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/19855/6c796bba-5213-6429-d482-3551738e14b5.png)

まずは、標準で備わっているElastiCacheのメトリクスを確認することから始めるのが一般的です。以下のようなガイドも用意されているため、どのメトリクスを注視すべきかの参考になります。

https://docs.aws.amazon.com/ja_jp/AmazonElastiCache/latest/red-ug/CacheMetrics.WhichShouldIMonitor.html


メトリクスを確認して負荷の傾向を把握し、対策を立てる際には、以下のようなre:PostのQ&Aも参考になります。


https://repost.aws/ja/knowledge-center/elasticache-redis-high-cpu-usage

https://repost.aws/ja/knowledge-center/elasticache-redis-correct-high-latency

対策としては、より大きいインスタンスタイプに変更することや、クラスターモードで運用しているクラスターに対してノードを追加することなどが考えられます。

具体的にボトルネックになっているコマンドを特定するには、以下に記載するような手段を取る必要があります。



## CloudWatch Logsにスローログを出力する

スローログは、エンジンバージョン6.0以降を使用するRedisクラスターでサポートされており、明示的に有効にすることでログを出力できます。ログの転送先として、CloudWatch LogsかKinesis Data Firehoseを選択できます。

パラメータグループの“slowlog-log-slower-than”で閾値(μs)を設定することで、何μs以上かかったコマンドをスローログとして出力することができます。調査目的でとにかく全て出力するならば、「0」を設定して全コマンドを出力するのが良いでしょう。



https://repost.aws/knowledge-center/elasticache-turn-on-slow-log

![Screenshot 2023-11-29 at 23.09.02.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/19855/097526cb-8250-2e0f-3440-5015016d6654.png)


出力結果は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

http://mogile.web.fc2.com/redis/redis500/commands/monitor.html

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製のツール (現在アーカイブ済み)

https://github.com/facebookarchive/redis-faina

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

https://github.com/hirose31/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 の高負荷の原因を特定するに役立つ情報でした。
他にも有用な情報などございましたら、コメントや編集リクエスト歓迎しています！

(免責) 本記事の内容はあくまでも個人の意見であり、所属する企業や団体は関係ございません。