PHP教程
记一次PHP偶现获取不到Redis数据排查过程
李乐
问题描述
3月25号早晨8点左右线上回归时，发现getTestInfos接口部分请求返回空数据。kibana查询异常请求日志，输入参数正常；梳理接口业务逻辑，是根据输入参数从Redis查询数据返回空导致。
进一步确认：1）Redis查询数据时未抛异常；2）Redis中确实存在该数据；3）只有偶尔部分请求无法从Redis获取数据。
10点25左右，重启业务进程与confd，恢复正常。
两个疑问：1）为什么部分请求会获取不到Redis的数据；2）为什么重启服务可以恢复
现状梳理
已知：服务并不是直连Redis，中间经过代理Twemproxy转发（简称tw），tw后端存在多个Redis实例，tw通过key-hash将请求分发到具体的Redis实例。架构如下：
etcd作为注册中心，tw将自身信息ip:port:weight注册到etcd；业务机器都部署有confd进程，从etcd拉取tw配置，并同步配置到业务进程。
进一步了解：24号晚11点14分，一台tw实例曾出现"故障"，并在2分钟左右恢复。kibana查询日志验证，晚11点14分访问Redis出现短暂的异常"read error on connection"，后续再没有捕获到任何异常。
查看confd日志，晚11点14分（剔除一台tw），晚11点16分（tw恢复），早10点25分（confd重启），拉取tw配置正确，切同步配置到业务进程配置文件正确，如下：
DEBUG Got the following map from store xxxx DEBUG Target config /home/www/xxxx/conf/redis.php in sync
等等，上面说重启业务进程与confd恢复正常，业务进程为什么需要重启？原来，业务服务并不是运行在php-fpm模式下，是基于Swoole的，常驻进程。那么业务进程是如何感知到配置文件的变化并重新加载的。查看confd模板配置：
[template]
src="xxxx/config.tmpl"
dest="/home/www/xxxx/conf/redis.php"
keys=[
"xxxx",
]
check_cmd="/usr/local/php7/bin/php -l {{.src}}"
reload_com="/usr/local/php7/bin/php /home/www/xxxx/daemon/baseserver/start.php kill && /usr/local/php7/bin/php /home/www/xxxx/daemon/baseserver/start.php start"
原来业务进程是想通过confd提供的"reload_cmd"实现的（配置改变时，重启命令），只是书写错误导致业务进程没有重启。
另外，业务代码中与tw是通过长连接通信的。
有点眉目了，tw故障以及恢复时，业务进程没有重启，从而没有成功更新配置以及重新连接tw，导致业务进程与这台tw的连接是异常的，因此无法获取数据。
进一步思考，如果tw是挂掉并重启，那业务进程之前与tw建立的连接全部异常（如果没有重连机制）；而我们只有2个tw实例，并且请求是平均分摊到2个tw实例，那么理论上应该有大概50%的请求无法无法获取数据。kibana统计异常请求与正常请求比例，只有2%左右。
经咨询，原来晚11点14分，tw是由于所在机器网络线路故障，才导致的短暂失联，tw进程并没有重启。
猜测：在tw失联期间，业务进程执行查询请求，phpredis扩展由于连接异常导致读写数据错误，并抛出异常"read error on connection"；而如果此时同时标记该连接异常，且后续没有重连机制的话，那么这些那么这些连接上的请求将全部失败。
上面说过，业务服务是基于Swoole构建的，master-manager-work进程模式，work进程真正的负责处理请求，每个work进程与每个tw进程建立一个长连接。业务服务work进程数目配置为256，业务机器申数目为19，即总连接数接近5000；另外统计晚11点14分异常"read error on connection"数目大约为100；可以计算出"异常"连接比例大概为2%。与异常请求比例接近。
分析验证
事实是否就是我们猜测的呢？这里还要验证两个问题：1）抛出异常"read error on connection"时，phpredis扩展是怎么处理该连接的？2）短暂失联后tw恢复了，phpredis扩展没有重新发起连接吗？
查看业务机器redis扩展版本为3.1.2，下载对应源码：https://github.com/phpredis/p...
/usr/local/php7/bin/php --ri redis redis Redis Support => enabled Redis Version => 3.1.2 Available serializers => php
全局搜索"read error on connection"关键字，可以发现是在请求数据发送之后，等待接收数据时出现的：
if(php_stream_gets(redis_sock->stream, inbuf, 1024) == NULL) {
REDIS_STREAM_CLOSE_MARK_FAILED(redis_sock);
zend_throw_exception(redis_exception_ce, "read error on connection",
0 TSRMLS_CC);
return NULL;
}
在什么情况下php_stream_gets返回null呢？1）读数据超时；2）读数据出错。phpredis没有设置超时时间时，默认是按照PHP配置default_socket_timeout=60s；而kibana查询日志可以发现，出现异常时，请求处理时间都是3.2s，因此不可能是读取数据超时导致。
timestamp: March 24th 2020, 23:14:10.367
x_response:{ "stat":0,"msg":"read error on connection","data":[]}
x_duration: 3.225
我们通过下面程序模拟线上问题：
<?php
$redis = new Redis();
$redis -> connect('127.0.0.1', 4379);
$redis->set('phpredis', 'phpredis');
sleep(30); //-----strace跟踪-----
var_dump($redis->get('phpredis'));
sleep(30);//-----断开网络-----
try{
var_dump($redis->get('phpredis'));
}catch (\Exception $e){
var_dump($e->getMessage());
}
sleep(5);
try{
var_dump($redis->get('phpredis'));
}catch (\Exception $e){
var_dump($e->getMessage());
}
输出结果为：
# /php7/php-7.1.0/output/bin/php test.php string(8) "phpredis" string(24) "read error on connection" bool(false)
可以看到，在抛出异常"read error on connection"后，最后以此获取数据时，phpredis直接返回false。
通过strace跟踪进程系统调用；
注意：测试环境与线上环境配置相同，这里的断开网络，是通过iptables -A INPUT -s $ip -j DROP模拟的；
- 第一次GET：正常接收redis返回结果
sendto(4, "*2\r\n$3\r\nGET\r\n$8\r\nphpredis\r\n", 27, MSG_DONTWAIT, NULL, 0) = 27
poll([{fd=4, events=POLLIN|POLLERR|POLLHUP}], 1, 60000) = 1 ([{fd=4, revents=POLLIN|POLLERR|POLLHUP}])
recvfrom(4, "$8\r\nphpredis\r\n", 8192, MSG_DONTWAIT, NULL, NULL) = 14
- 第二次GET：recvfrom直接返回错误ETIMEDOUT；
sendto(4, "*2\r\n$3\r\nGET\r\n$8\r\nphpredis\r\n", 27, MSG_DONTWAIT, NULL, 0) = 27
poll([{fd=4, events=POLLIN|POLLERR|POLLHUP}], 1, 60000) = 1 ([{fd=4, revents=POLLIN|POLLERR|POLLHUP}])
recvfrom(4, 0x7fe562477000, 8192, MSG_DONTWAIT, NULL, NULL) = -1 ETIMEDOUT (Connection timed out)
可以清楚的看到，poll方法返回，recvfrom尝试读取数据但是出现错误ETIMEDOUT；原因就在于网络断开，TCP发送数据出错导致底层连接异常。
- 第三次GET：phpredis并没有调用sendto发起请求（因为上一步的错误导致TCP连接异常关闭）；write是向标准输出打印结果；
nanosleep({5, 0}, 0x7ffc97f85a10) = 0
write(1, "bool(false)\n", 12) = 12
另外，我们也可以通过阻塞redis（利用gdb调试阻塞），模拟读取数据超时情况；可以看到这里poll方法超时，而超时时间为60秒，下一步直接close该连接；
sendto(4, "*2\r\n$3\r\nGET\r\n$8\r\nphpredis\r\n", 27, MSG_DONTWAIT, NULL, 0) = 27
poll([{fd=4, events=POLLIN|POLLERR|POLLHUP}], 1, 60000) = 0 (Timeout)
close(4)
phpredis补充
另一个问题，phpredis在抛出异常"read error on connection"时会关闭连接，后续处理命令时为什么没有重试机制呢？这种问题其实只在低版本出现，高版本是有重试措施的。我们可以看看5.2.0版本代码：
phpredis出现异常时，关闭socket，并设置状态为REDIS_SOCK_STATUS_DISCONNECTED；每次执行命令时，会调用redis_sock_get—>redis_sock_server_open；该函数判断状态如果为REDIS_SOCK_STATUS_DISCONNECTED，则发起重连；
PHP_REDIS_API RedisSock *
redis_sock_get(zval *id, int no_throw)
{
if ((redis_sock = redis_sock_get_instance(id, no_throw)) == NULL) {
return NULL;
}
if (redis_sock_server_open(redis_sock) < 0) {
spprintf(&errmsg, 0, "Redis server %s:%d went away", ZSTR_VAL(redis_sock->host),
REDIS_THROW_EXCEPTION(errmsg, 0);
return NULL;
}
return redis_sock;
}
PHP_REDIS_API int
redis_sock_server_open(RedisSock *redis_sock)
{
if (redis_sock) {
switch (redis_sock->status) {
case REDIS_SOCK_STATUS_FAILED:
return FAILURE;
case REDIS_SOCK_STATUS_DISCONNECTED:
return redis_sock_connect(redis_sock);
default:
return SUCCESS;
}
}
return FAILURE;
}
最后说下我们常见的phpredis异常：
- Connection lost：正常连接时，假如kill掉redis进程；会尝试重连10次，如果还失败则抛该异常；并置redis_sock状态为REDIS_SOCK_STATUS_FAILED；
- read error on connection：底层socket读数据超时（默认60秒）或者读socket出错时，抛该异常，同时置redis_sock状态为REDIS_SOCK_STATUS_DISCONNECTED；
- Redis server went away：$redis->connect()连接失败时返回false，后续执行命令时，直接抛该异常；
- Connection closed：手动调用close关闭redis后，再执行命令时抛该异常；
为什么是3.2秒？
最后还有一个问题需要研究验证，为什么异常时所有请求的响应时间都是3.2秒？这是由什么决定的？
我们知道线上出现异常"read error on connection"，是由于tw机器网络线路故障，那此时发送命令请求时，TCP层理论上会经过重传，而最终发送失败。是TCP层重传引发的3.2秒吗？
基于上面的实验，我们tcpdump抓包分析：
11:35:48.316384 IP xxxx.18587 > xxxx.4379: Flags [P.], seq 990267312:990267339 重传1 => 11:35:48.517231 IP xxxx.18587 > xxxx.4379: Flags [P.], seq 990267312:990267339 重传2 => 11:35:48.718245 IP xxxx.18587 > xxxx.4379: Flags [P.], seq 990267312:990267339 重传3 => 11:35:49.121243 IP xxxx.18587 > xxxx.4379: Flags [P.], seq 990267312:990267339 重传4 => 11:35:49.927245 IP xxxx.18587 > xxxx.4379: Flags [P.], seq 990267312:990267339
- 48.3秒第一次发送数据，初始超时时间大约200ms；
- 48.5秒超时定时器触发，第一次重传，并且设定超时定时器200ms；
- 48.7秒超时定时器触发，第二次重传，并且设定超时定时器400ms；
- 49.1秒超时定时器触发，第三次重传，并且设定超时定时器800ms；
- 49.9秒超时定时器触发，第四次重传，并且设定超时定时器1600ms；
- 第四次重传超时后，没有了下次重试，总时间为49.9-48.3+1.6=3.2秒
- 另外可以很明显的看到，重传超时时间是指数递增的；
通过tcpdump抓包分析，网络原因导致TCP重传，可以看到TCP重传总的花费时间为3.2秒；正好接近异常请求的处理时间；
又有问题了：TCP重传时间为什么有3.2秒限制呢？是通过系统配置确定的：
$ sysctl -a | grep tcp_retries net.ipv4.tcp_retries1 = 3 net.ipv4.tcp_retries2 = 2
tcp_retries1tcp_retries2与配置限制的是TCP包的最大重传时间（计算得到）；超过tcp_retries1主要会更新路由缓存；超过tcp_retries2，内核直接销毁该socket，并返回ETIMEDOUT；
注意：
网上也有资料说tcp_retries1tcp_retries2限制的是重传次数；读者可以查看linux2.6.5版本源码，其确实限制的是重传次数，逻辑如下：
static int tcp_write_timeout(struct sock *sk)
{
retry_until = sysctl_tcp_retries2;
if (icsk->icsk_retransmits >= retry_until) {
tcp_write_err(sk);
return 1;
}
return 0;
}
查看线上linux版本为3.10；查看源码（搜索sysctl_tcp_retries2即可），TCP超时处理函数为tcp_write_timeout:
static int tcp_write_timeout(struct sock *sk)
{
if (retransmits_timed_out(sk, sysctl_tcp_retries1, 0, 0)) {
tcp_mtu_probing(icsk, sk);
dst_negative_advice(sk);
}
retry_until = sysctl_tcp_retries2;
if (retransmits_timed_out(sk, retry_until,
syn_set ? 0 : icsk->icsk_user_timeout, syn_set)) {
tcp_write_err(sk);
return 1;
}
return 0;
}
重传超时处理函数为retransmits_timed_out，可以看到先校验sysctl_tcp_retries1，如果超时则更新路由缓存；再次教研sysctl_tcp_retries2，如果超时则直接销毁socket并上报错误：
static void tcp_write_err(struct sock *sk)
{
sk->sk_err = sk->sk_err_soft ? : ETIMEDOUT;
sk->sk_error_report(sk);
tcp_done(sk);
}
我们的系统配置tcp_retries2<tcp_retries1；那tcp_retries2=2，如何计算得到重传最大超时时间呢？这就需要分析retransmits_timed_out实现逻辑：
static bool retransmits_timed_out(struct sock *sk,
unsigned int boundary,
unsigned int timeout,
bool syn_set)
{
start_ts = tcp_sk(sk)->retrans_stamp;
if (likely(timeout == 0)) {
linear_backoff_thresh = ilog2(TCP_RTO_MAX/rto_base);
//TCP_RTO_MAX=120s,rto_base=200ms,linear_backoff_thresh=9
if (boundary <= linear_backoff_thresh)
timeout = ((2 << boundary) - 1) * rto_base;
//timeout= (2^3-1)*200ms=1400ms
else
timeout = ((2 << linear_backoff_thresh) - 1) * rto_base +
(boundary - linear_backoff_thresh) * TCP_RTO_MAX;
}
return (tcp_time_stamp - start_ts) >= timeout;
}
boundary入参即为sysctl_tcp_retries2=2；计算出来的timeout=1400ms，start_ts为第一次的重传时间戳。这里就有点疑惑了，从上面的抓包可以看到，第一次重传时间为48.517秒，第四次重传的时间为49.927秒，时间差为1.41秒=1410毫秒>1400毫秒，也很接近1400毫秒；为什么还会有第四次重传呢？难道tcpdump输出的时间与内核实际记录的重传时间点有误差吗？还是计算出来的timeout错误呢？
小知识：
net.ipv4.tcp_syn_retries 配置可限制syn包重传次数；syn包第一次重传间隔为1秒，后续指数递增；
12:00:22.819581 IP xxxx.18639 > xxxx.4379: Flags [S], seq 260776364 12:00:23.821231 IP xxxx.18639 > xxxx.4379: Flags [S], seq 260776364 12:00:25.825250 IP xxxx.18639 > xxxx.4379: Flags [S], seq 260776364
参考文献
https://my.oschina.net/alchem...
-
怎么实现安卓+php 热更新方案？-icode9专业技术文章分享11-23
-
PHP 中怎么实现判断多个值是否为空、null 或者为 false？-icode9专业技术文章分享11-22
-
开源 PHP 商城项目 CRMEB 二次开发和部署教程11-11
-
怎么使用php在kaufland平台刊登商品？-icode9专业技术文章分享11-09
-
PHP的抽象类和接口是什么，有什么区别-icode9专业技术文章分享11-05
-
开源 PHP 商城项目 CRMEB 安装和使用教程11-01
-
用php和mysql写无限分类，有哪几种方法-icode9专业技术文章分享11-01
-
php数据分表导出时部分数据无法导出什么原因-icode9专业技术文章分享10-31
-
有经验的 PHP 开发者学习一门新的编程语言，有哪些推荐的有前景的语言-icode9专业技术文章分享10-30
-
php 检测图片是否篡改过-icode9专业技术文章分享10-21
-
fruitcake/php-cors 该怎么使用-icode9专业技术文章分享10-20
-
PHP7.1可以使用哪个版本的swoole-icode9专业技术文章分享10-18
-
php8 执行php -v提示 command not found是什么原因？-icode9专业技术文章分享10-17
-
nginx 怎么配置 php？-icode9专业技术文章分享10-17
-
怎么把PHP程序打包？-icode9专业技术文章分享09-28
