redisのパフォーマンス悪化により Connectionエラーになる

Question

実現したいこと

あるオープンWEB系のそれなりにアクセスがあるサイトを運営しております。
そのシステムのアクセス数をパス毎に計測したいのですが、
instantaneous_ops_per_sec:486
この値が400を超えるとエラーになります。
redisの設定が悪いのでしょうか？

発生している問題・分からないこと

アクセスする毎に、パスをキーにして、INCREMENT 処理をしています。
（現状他の処理に影響を受けさせたくないため、これ用のredisサーバーを用意し、他の処理は走っておりません。）

以下の値が400くらいまでならなんとか処理出来るのですが、400を超えるとConnectionエラーが発生してしまいます。
instantaneous_ops_per_sec:486

本来であれば、↑の値は1万くらいまで耐えられるのではないかと思うのですが・・・

エラーメッセージ

connection error

該当のソースコード

redis-cli info の結果を貼り付けておきます。
ubuntu@redis:~$ redis-cli info | grep instantaneous_ops_per_sec
instantaneous_ops_per_sec:486
ubuntu@redis:~$ redis-cli info | grep instantaneous_ops_per_sec
instantaneous_ops_per_sec:332
ubuntu@redis:~$ redis-cli info
# Server
redis_version:7.0.15
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:d81b8ff71cfb150e
redis_mode:standalone
os:Linux 6.8.0-1016-oracle x86_64
arch_bits:64
monotonic_clock:POSIX clock_gettime
multiplexing_api:epoll
atomicvar_api:c11-builtin
gcc_version:13.2.0
process_id:5149
process_supervised:systemd
run_id:a57c5db7fb2e42efa08aef56b6b006f1c1699d6d
tcp_port:6379
server_time_usec:1733485810631947
uptime_in_seconds:625981
uptime_in_days:7
hz:10
configured_hz:10
lru_clock:5432562
executable:/usr/bin/redis-server
config_file:/etc/redis/redis.conf
io_threads_active:0

# Clients
connected_clients:33
cluster_connections:0
maxclients:10000
client_recent_max_input_buffer:20480
client_recent_max_output_buffer:0
blocked_clients:0
tracking_clients:0
clients_in_timeout_table:0

# Memory
used_memory:1623405304
used_memory_human:1.51G
used_memory_rss:1874042880
used_memory_rss_human:1.75G
used_memory_peak:1625447648
used_memory_peak_human:1.51G
used_memory_peak_perc:99.87%
used_memory_overhead:1080335764
used_memory_startup:876120
used_memory_dataset:543069540
used_memory_dataset_perc:33.47%
allocator_allocated:1624028928
allocator_active:1839931392
allocator_resident:1866817536
total_system_memory:25194946560
total_system_memory_human:23.46G
used_memory_lua:31744
used_memory_vm_eval:31744
used_memory_lua_human:31.00K
used_memory_scripts_eval:0
number_of_cached_scripts:0
number_of_functions:0
number_of_libraries:0
used_memory_vm_functions:32768
used_memory_vm_total:64512
used_memory_vm_total_human:63.00K
used_memory_functions:200
used_memory_scripts:200
used_memory_scripts_human:200B
maxmemory:21474836480
maxmemory_human:20.00G
maxmemory_policy:allkeys-lru
allocator_frag_ratio:1.13
allocator_frag_bytes:215902464
allocator_rss_ratio:1.01
allocator_rss_bytes:26886144
rss_overhead_ratio:1.00
rss_overhead_bytes:7225344
mem_fragmentation_ratio:1.15
mem_fragmentation_bytes:250621936
mem_not_counted_for_evict:3072
mem_replication_backlog:1073755212
mem_total_replication_buffers:1077136632
mem_clients_slaves:3394808
mem_clients_normal:263424
mem_cluster_links:0
mem_aof_buffer:3072
mem_allocator:jemalloc-5.3.0
active_defrag_running:0
lazyfree_pending_objects:0
lazyfreed_objects:0

# Persistence
loading:0
async_loading:0
current_cow_peak:0
current_cow_size:0
current_cow_size_age:0
current_fork_perc:0.00
current_save_keys_processed:0
current_save_keys_total:0
rdb_changes_since_last_save:1040316
rdb_bgsave_in_progress:0
rdb_last_save_time:1733481964
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:12
rdb_current_bgsave_time_sec:-1
rdb_saves:5552
rdb_last_cow_size:3006464
rdb_last_load_keys_expired:0
rdb_last_load_keys_loaded:0
aof_enabled:1
aof_rewrite_in_progress:0
aof_rewrite_scheduled:0
aof_last_rewrite_time_sec:12
aof_current_rewrite_time_sec:-1
aof_last_bgrewrite_status:ok
aof_rewrites:77
aof_rewrites_consecutive_failures:0
aof_last_write_status:ok
aof_last_cow_size:3608576
module_fork_in_progress:0
module_fork_last_cow_size:0
aof_current_size:198087855
aof_base_size:192976921
aof_pending_rewrite:0
aof_buffer_length:0
aof_pending_bio_fsync:0
aof_delayed_fsync:0

# Stats
total_connections_received:118407872
total_commands_processed:147168592
instantaneous_ops_per_sec:380
total_net_input_bytes:9532839370
total_net_output_bytes:6654711911
total_net_repl_input_bytes:0
total_net_repl_output_bytes:5716577785
instantaneous_input_kbps:22.54
instantaneous_output_kbps:24.35
instantaneous_input_repl_kbps:0.00
instantaneous_output_repl_kbps:22.49
rejected_connections:0
sync_full:1
sync_partial_ok:0
sync_partial_err:0
expired_keys:0
expired_stale_perc:0.00
expired_time_cap_reached_count:0
expire_cycle_cpu_milliseconds:4865
evicted_keys:0
evicted_clients:0
total_eviction_exceeded_time:0
current_eviction_exceeded_time:0
keyspace_hits:54495
keyspace_misses:2
pubsub_channels:0
pubsub_patterns:0
pubsubshard_channels:0
latest_fork_usec:34791
total_forks:5630
migrate_cached_sockets:0
slave_expires_tracked_keys:0
active_defrag_hits:0
active_defrag_misses:0
active_defrag_key_hits:0
active_defrag_key_misses:0
total_active_defrag_time:0
current_active_defrag_time:0
tracking_total_keys:0
tracking_total_items:0
tracking_total_prefixes:0
unexpected_error_replies:0
total_error_replies:1
dump_payload_sanitizations:0
total_reads_processed:265576431
total_writes_processed:242647978
io_threaded_reads_processed:0
io_threaded_writes_processed:0
reply_buffer_shrinks:577784
reply_buffer_expands:1

# Replication
role:master
connected_slaves:1
slave0:ip=10.0.1.249,port=6379,state=online,offset=5716563710,lag=0
master_failover_state:no-failover
master_replid:031645b0bae484072a5738f0f6328e4612baf329
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:5716577525
second_repl_offset:-1
repl_backlog_active:1
repl_backlog_size:1073741824
repl_backlog_first_byte_offset:4642823361
repl_backlog_histlen:1073754165

# CPU
used_cpu_sys:8715.896671
used_cpu_user:2438.235513
used_cpu_sys_children:1414.177144
used_cpu_user_children:27977.623618
used_cpu_sys_main_thread:8639.726319
used_cpu_user_main_thread:2429.331752

# Modules

# Errorstats
errorstat_WRONGTYPE:count=1

# Cluster
cluster_enabled:0

# Keyspace
db0:keys=37966,expires=0,avg_ttl=0

試したこと・調べたこと

• teratailやGoogle等で検索した
• ソースコードを自分なりに変更した
• 知人に聞いた
• その他

上記の詳細・結果

パスがキーとなるので、同じキーに対してのINCREMENTになり、同じキーの処理で渋滞を起こしているのかと思い、パス + ランダム数字(0～99)の数字を追加して分散してみましたが、変わらず400以上でエラーとなってしまいました。
（全部が全部エラーになるわけではなく、アクセス数が多いので一部のユーザーがConnect error になっているかと思います。また他のユーザーは、レスポンスが悪い状態になっております）

補足

ubuntu@redis:~$ cat /etc/os-release
PRETTY_NAME="Ubuntu 24.04.1 LTS"
NAME="Ubuntu"
VERSION_ID="24.04"
VERSION="24.04.1 LTS (Noble Numbat)"

ubuntu@redis:~$ redis-cli -v
redis-cli 7.0.15

Comments

[maisumakun]

> 本来であれば、↑の値は1万くらいまで耐えられるのではないかと思うのですが・・・

それは、どのような根拠を持って推測したものでしょうか。

[akasatanaha]

公式のベンチマークでは10万/sec出ております。

そこが根拠となっている訳ではありませんが、
redisはCPUは1CPUでも問題ありませんし
（が、念の為2CPU積んでおります）
メモリは24Gでサーバーの負荷状況を見てみても
CPU、メモリ、ロードアベレージなど、どの数値もすっかすかの状態です。

あと今までの経験やセミナーでの話を聞いて
当該システムのスペックでは1万/secくらいは出せるのではないかと。
redis-benchmarkなどやって、確証を得たわけではありませんが・・・

あとはchat-gpt さんも1万は出るよ！と。。。

[tmp]

そのような状態になったときに、netstat などで状態を確認できますか？
素人が失礼ですが、アクセスする毎にredisサーバーに接続してますか？

[akasatanaha]

>素人が失礼ですが、アクセスする毎にredisサーバーに接続してますか？
アクセスする毎に接続しています。

>そのような状態になったときに、netstat などで状態を確認できますか？
すみません。今は本番で試せないんで出せないですが
netstat で分かることは、redis-cli info でも少し出るので、その値を載せます。
chat-gptに聞いた結果です。

1. 接続数の確認
Redisで確認:

connected_clients:33
blocked_clients:0
client_recent_max_input_buffer:20480
client_recent_max_output_buffer:20504

connected_clients: 現在接続中のクライアント数。
blocked_clients: ブロック中のクライアント数（BRPOPなどで待機中）。
これにより、接続が多すぎる（connected_clientsが高い）場合を特定できます。
netstatでの確認: Redisのポート（例: 6379）でESTABLISHEDの接続数を確認します。

netstat -an | grep 6379 | grep ESTABLISHED | wc -l
どちらも接続数の観点では類似情報を提供しますが、infoのほうがRedisに特化した情報（ブロック中クライアント数など）も得られます。

2. TIME_WAIT/CLOSE_WAITの確認
Redisのinfoコマンドでは、直接的なTIME_WAITやCLOSE_WAIT状態は確認できません。ただし、間接的なヒントとして以下を確認できます。

instantaneous_ops_per_sec:380
total_connections_received:118407872
rejected_connections:0
instantaneous_ops_per_sec: 毎秒のコマンド処理数。負荷の兆候を監視可能。
total_connections_received: 接続数の累計値。
rejected_connections: 接続拒否された回数。ポート枯渇やmaxclients設定を超えた場合に増加します。
接続数が多すぎる場合: 接続がTIME_WAITやCLOSE_WAITで大量発生している場合、rejected_connectionsが増加する可能性があります。

3. ブロッキング状態の確認
Redisで確認: blocked_clientsで、ブロック中のクライアントを確認できます。

blocked_clients:0
ブロック中のクライアントが多い場合、BRPOPやBLPOPで待機中のクライアントが多いことを示します。

4. 接続元クライアントの特定
id=3 addr=10.0.0.1:6379 fd=6 name= age=300 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 tot-mem=9743 events=r cmd=get

addr: クライアントのIPアドレス。
cmd: 最後に実行されたコマンド（例: GET、SET）。
idle: クライアントがアイドル状態になっている時間。
特定のIPアドレスやクライアントが多すぎる場合、それがボトルネックの原因になっている可能性を探れます。

5. スナップショット/バックグラウンド操作の影響
rdb_last_bgsave_status:ok
latest_fork_usec:34791

latest_fork_usec: バックグラウンドタスク（RDB/AOF書き込み）のフォーク時間。値が大きい場合、Redisのパフォーマンスに影響を与える可能性があります。
Redis-cli infoでの確認が優れる点
Redisに特化した情報:
connected_clientsやblocked_clientsなど、Redis専用の指標を簡単に確認可能。
原因の絞り込み:
rejected_connectionsやclient listで、クライアントの問題を直接特定可能。
コマンド処理状況のリアルタイム把握:
instantaneous_ops_per_secで現在の負荷を確認可能。

Redis-cli infoの限界
TCP状態（TIME_WAIT/CLOSE_WAIT）の直接確認は不可:
TCP接続状態（TIME_WAITなど）はnetstatやssでしか確認できません。
ネットワークの詳細な分析には不向き:
特定のクライアントのパケット遅延や、帯域の使用状況までは取得できません。

[tmp]

Webサーバー側からredisに接続して、切断するのですね？
切断したほう(Active Close)がTIME_WAITの状態で60秒そのポートが使えません。ダイナミックポートがいくつあるか、わかりませんが、多分、足りなくなると思うのですが、redis側でなく、Webサーバー側が足りなくなってるのではないでしょうか？Webサーバー側の状態は確認できませんか？

[akasatanaha]

なるほど。WEBサーバー側ですか。
Redis側はすっかすかなので、そうかもしれない。

取り急ぎ以下に変更しました。
（念の為、WEBサーバー側とRedis側両方変更）
net.ipv4.tcp_fin_timeout = 15
net.ipv4.tcp_tw_reuse = 1
net.ipv4.ip_local_port_range = 1024 65535
net.core.somaxconn = 65535
net.ipv4.tcp_max_syn_backlog = 8192
net.ipv4.tcp_keepalive_time = 600
net.core.netdev_max_backlog = 5000
net.ipv4.tcp_rmem = 8192 262144 8388608
net.ipv4.tcp_wmem = 8192 262144 8388608
vm.swappiness = 10
vm.dirty_ratio = 10
vm.dirty_background_ratio = 5

また apache fmp は以下に変更しました

Apache

StartServers 2
MinSpareThreads 25
MaxSpareThreads 75
ThreadLimit 64
ThreadsPerChild 25
MaxRequestWorkers 150
ServerLimit 150
MaxConnectionsPerChild 1000

PHP-FPM
pm.max_children = 150

この変更で450くらいまでは耐えられるようになった気がするけど、
あまり状況変わらずでした。。。