客户端连接数问题

[wenbin1989]

您好： 目前使用pika中发现了一个问题。正常情况下一个pika节点的客户端连接数在270-300之间，但连接数有时候会有波动，到一个350-400连接数的峰值，监控如图。

在这些峰值的时间点，都会出现检查节点状态时ping无响应，读取错误等故障。查看日志未发现明显问题，请问有没有什么解决思路，以及pika本身时候有什么限制，谢谢。

当前服务状态：

127.0.0.1:6379> info

Server

pika_version:2.1.0 os:Linux 2.6.32-431.el6.centos.plus.x86_64 x86_64 arch_bits:64 process_id:3150 tcp_port:6379 thread_num:8 sync_thread_num:4 uptime_in_seconds:23350 uptime_in_days:1 config_file:/data/pika/conf/pika.conf

Data

db_size:30618M compression:snappy used_memory:32105758360 db_memtable_usage:404912908Bytes db_tablereader_usage:338472679Bytes

Log

log_size:9536M safety_purge:write2file3122 expire_logs_days:7 expire_logs_nums:10 write2file:3132

Clients

connected_clients:285

Stats

total_connections_received:27792 instantaneous_ops_per_sec:2280 total_commands_processed:58205799 is_bgsaving:No, , 0 is_scaning_keyspace:No is_compact:No

Replication(MASTER)

role:master connected_slaves:0

Keyspace

Time:2016-08-18 13:01:52

kv keys:1934565 hash keys:0 list keys:0 zset keys:2253399 set keys:0

[KernelMaker]

多谢反馈，pika这里除了连接数上限之外没有其他限制，你可以先排查一下：

1. 出错时段客户端报什么错，超时？
2. 如果是超时错误，看下无响应时段pika的慢日志，猜测那个时候可能是你们有在集中执行耗时比较多的请求，导致其他请求无法响应

另外，你们用的pika的版本是多少呢？

[wenbin1989]

您好，多谢回复。 是用v2.1.0 release页面下载的版本。

1. 超时无响应，读取和ping都有失败，写入失败记录几乎没有
2. 对应时间段的慢日志如下： E0818 13:12:28.273990 3163 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525948, duration(us): 88793 E0818 13:12:28.529270 3158 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525948, duration(us): 106312 E0818 13:12:28.547597 3162 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525948, duration(us): 91680 E0818 13:12:28.848769 3158 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525948, duration(us): 99824 E0818 13:12:29.079372 3163 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525949, duration(us): 22972 E0818 13:12:29.096505 3160 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525948, duration(us): 99720 E0818 13:12:29.239689 3161 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525949, duration(us): 66341 E0818 13:12:29.270689 3163 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525949, duration(us): 13290 E0818 13:12:29.357663 3158 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525949, duration(us): 38935 E0818 13:12:29.479305 3158 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525949, duration(us): 33931 E0818 13:12:29.751195 3160 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525949, duration(us): 28785 E0818 13:12:29.777120 3158 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525949, duration(us): 90224 E0818 13:12:29.831889 3163 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525949, duration(us): 64940 E0818 13:12:30.040900 3161 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525949, duration(us): 73030 E0818 13:12:30.095551 3158 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525950, duration(us): 34525 E0818 13:12:30.132876 3163 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525950, duration(us): 77279 E0818 13:12:30.188822 3157 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525950, duration(us): 26481 E0818 13:12:30.237318 3163 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525950, duration(us): 76070 E0818 13:12:30.285257 3157 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525950, duration(us): 46266 E0818 13:12:30.331856 3161 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525950, duration(us): 146982 E0818 13:12:30.475834 3161 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525950, duration(us): 10140 E0818 13:12:30.582893 3163 pika_client_conn.cc:121] command:zrange, start_time(s): 1471525950, duration(us): 128008

与正常时间段比较没有明显区别。

故障时间点与连接数增长点均完全吻合，感觉连接数也并不是很多，基本都在500一下。排查一些大批量的请求，均与故障时间点不一致。

谢谢。

[KernelMaker]

你们的连接数及QPS都不大，不应该出现这样的问题，我看图里的高峰时段是在13:20到13:25之间，这段时间的慢日志也正常吗？如果确认排除慢请求造成的阻塞，那请再确认一下：

1. 服务器在问题时段的负载信息：CPU，内存及磁盘占用，磁盘及网络io
2. 平时状态下客户端都有什么请求？高峰状态下多出来的100多客户端在做什么请求？你们有zset的删除或过期操作吗，是否频繁？
3. 问题时段出错的客户端是连接超时还是读写超时？
4. 问题时段的持续时间大概多久呢？如果稳定复现，你可以在出问题时通过htop或strace来看下当时pika的线程状况，是否有卡在什么调用上之类的

辛苦啦^^

[wenbin1989]

您好，感谢回复。

问题已确定，是由于用ZRANG读取一个成员数特别大的key（10w+）时，pika实例假死，造成其他其他请求不断的在连接池中新建客户端连接导致连接数上升，而不是连接数上升导致故障T-T。出错的客户端都是读写超时，问题操作也都没有写到binlog以及慢日志中。

问题时段服务器负载正常，CPU idle大概还有30 - 50，io也正常。该服务器上还在另一个硬盘有另一个pika实例，在问题时段也运行正常。

有zset的删除或者过期操作，每小时一次，不过确实有一些异常导致的zset成员数过多。

还想麻烦请教下，pika的ZRANGE和HKEYS（或HGETALL）操作的时间复杂度分别是什么？我看redis分别是O(log(N)+M)与O(N)，不知道pika中依赖nemo与rocksdb的实现具体有什么区别，谢谢。

[KernelMaker]

嗯，应该是zrange请求过大导致线程卡死；

1. 每条命令执行完如果满足刷慢日志的条件应该是会写到慢日志文件中的，你说的慢日志中没有有两个原因：1) 那条特别慢的命令直到关闭服务时始终没有执行完；2) 可能刷到文件中了你没有找到。另外像zrange这种读命令是不会写到binlog中，只有写命令才会写binlog
2. 如果zset有较频繁并且大量的过期操作（已过期），这样的情况会稍微影响zrange的执行效率，如果你们的过期操作很多并且已经有大量的元素已经过期，推荐在负载低峰时手动执行compact命令，这样可以提高zrange的执行速度
3. pika是基于kv的接口来实现的zset和hash结构，所以zrange，hkeys和hgetall的复杂度均为O(N)，不过不同于redis的内存操作，pikaO(N)的每次操作是对磁盘进行读写（当然由于cache，也不是全部进行磁读写磁盘），这三个操作的性能均低于redis
4. 在数据量较大的情况下不推荐直接使用keys，hkeys，hgetall等获取全量数据的接口，可以使用scan，hscan加count来替代，将一次请求切分为多次来执行

[wenbin1989]

多谢答复！

还有个问题想请教下，麻烦了。

我看nemo代码中对于zset的实现，在zadd，zrange等中均没有看到排序逻辑。不知道排序是在什么时候进行的？多谢。

[KernelMaker]

这个是由rocksdb支持的，通过iterator可以按照字典序将key从小到大遍历出来，所以nemo只需要将存在rocksdb的key按一定方式拼接组织（看这里），就可以完成相关排序了

[wenbin1989]

所以即使一个很大的zset，如果用zrange只读m个的话，复杂度也只是O(m)？

[KernelMaker]

在nemo层面是O(m)，不过真正在rocksdb的层面还是O(N)，具体的原因你可以看下nemo和rocksdb的实现

[AngoSong]

E0429 22:32:15.672225 573 pika_client_conn.cc:158] ip_port: 124.222.69.130:41104, table: db0, command: "INFO", command_size: 4, arguments: 1, start_time(s): 1682807535, duration(us): 161834

使用docker pika:v3.3.6 ，里面的日志一直是上面这个，导致CPU和内存一直占用很多，请问这是什么原因