李乐问题描述3月25日早上8:00左右返回上线时，发现getTestInfos接口请求部分返回空数据。Kibana查询异常请求日志，输入参数正常；整理接口业务逻辑是根据入参从Redis查询返回空数据导致的。进一步确认：1）Redis在查询数据时没有抛出异常；2）数据确实存在于Redis中；3）只是偶尔有一些请求无法从Redis获取数据。10点25分左右，重启业务进程和confd，恢复正常。两个问题：1）为什么有些请求获取不到Redis数据；2）为什么重启服务会恢复原状MultipleRedisinstances,tw通过key-hash将请求分发到具体的Redis实例。架构如下：etcd作为注册中心，tw将自己的信息ip:port:weight注册到etcd；业务机部署confd进程，从etcd中拉取tw配置，同步配置到业务流程。进一步了解：晚上11点14分24日，一个tw实例出现“故障”，2分钟左右恢复。Kibana查询日志验证，晚上11点14分访问Redis时，出现短暂的异常“readerroronconnection”，之后没有捕获到异常。查看confd日志，晚上11点14分（删除一个tw），晚上11点16分（tw恢复），上午10点25分（confd重启），拉取tw配置是否正确，同步配置到业务流程配置文件正确，如下：DEBUGGotthefollowingmapfromstorexxxxDEBUGTargetconfig/home/www/xxxx/conf/redis.phpinsync等，上面写着重启业务进程，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.phpkill&&/usr/local/php7/bin/php/home/www/xxxx/daemon/baseserver/start.phpstart”原来业务流程是通过confd提供的“reload_cmd”实现的（配置改变时重启命令），但是写错导致业务流程不重启。另外，业务代码通过长连接与tw通信。这是一个线索。当tw出现故障恢复时，业务流程并没有重启，所以配置没有更新成功，重新连接tw。导致业务流程和这个tw的连接不正常，所以拿不到数据。进一步思考，如果tw挂了再重启，那么业务流程之前与tw建立的所有连接都是异常的（如果没有重连机制的话）；而我们只有2个tw实例，请求平均分配到2个tw实例，那么理论上应该有50%左右的请求是拿不到数据的。根据kibana统计，异常请求占正常请求的比例只有2%左右。经咨询，原来是晚上11点14分，由于所在机器的网线故障导致tw短时间失去连接，tw进程没有重启。猜测：tw断线期间，业务进程执行查询请求，phpredis扩展由于连接异常导致读写数据错误，抛出异常“readerroronconnection”；而如果此时同时标记了连接异常，并且没有后续的连接机制不连接，那么这些连接上的所有请求都会失败。上面提到，业务服务基于Swoole构建，master-manager-work进程模式，work进程真正负责处理请求，每个work进程与每个tw进程建立长连接。配置业务服务工作进程数为256个，业务机应用数为19个，即总连接数接近5000个；另外，晚上11点14分异常“readerroronconnection”的次数。约为100；可以计算出“异常”连接的比例约为2%。接近异常请求的比例。分析验证?事实就是我们猜想的吗？这里还有两个问题需要验证：1）当抛出“readerroronconnection”异常时，phpredis扩展是如何处理连接的？2)短暂失去连接后，tw恢复，phpredis扩展是否重新发起连接？查看业务机redis扩展版本为3.1.2，下载对应源码：https://github.com/phpredis/p.../usr/local/php7/bin/php--riredisredisRedisSupport=>enabledRedisVersion=>3.1.2Availableserializers=>php全局搜索“readerroronconnection”关键字，可以发现在请求数据发送后等待接收数据时出现：if(php_stream_gets(redis_sock->stream,inbuf,1024)==NULL){REDIS_STREAM_CLOSE_MARK_FAILED(redis_sock);zend_throw_exception(redis_exception_ce,"连接读取错误",0TSRMLS_CC);returnNULL;}php_stream_gets在什么情况下返回null？1）读数据超时；2)读取数据错误。当phpredis没有设置超时时间时，默认是根据PHP配置default_socket_timeout=60s；而kibana查询日志可以发现，当出现异常时，请求处理时间为3.2s，因此超时无法读取数据。timestamp:March24th2020,23:14:10.367x_response:{"stat":0,"msg":"readerroronconnection","data":[]}x_duration:3.225我们用下面的程序来模拟线上问题:connect('127.0.0.1',4379);$redis->set('phpredis','phpredis');睡觉（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/phptest.phpstring(8)"phpredis"string(24)"readerroronconnection"bool(false)可以看出抛出“readerroronconnection”异常后，最后使用该方法获取数据时，phpredis直接返回假。通过strace跟踪进程系统调用；注意：测试环境配置和线上环境一样，这里的网络断开是通过iptables-AINPUT-s$ip-jDROP模拟的；第一次GET：正常接收redis返回结果sendto(4,"*2\r\n$3\r\nGET\r\n$8\r\nphpredis\r\n",27,MSG_DONTWAIT,NULL,0)=27poll([{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)=27poll([{fd=4,events=POLLIN|POLLERR|POLLHUP}],1,60000)=1([{fd=4,revents=POLLIN|POLLERR|POLLHUP}])从(4,0x7fe562477000,8192,MSG_DONTWAIT,NULL,NULL)=-1ETIMEDOUT(Connectiontimedout)可以明显看出poll方法返回，recvfrom尝试读取数据但出现ETIMEDOUT错误；原因是网络断开，TCP发送数据错误导致底层连接异常。第三次GET：phpredis没有调用sendto发起请求（因为上一步的错误导致TCP连接异常关闭）；write是将结果打印到标准输出；nanosleep({5,0},0x7ffc97f85a10)=0write(1,"bool(false)\n",12)=12直接关闭连接；sendto(4,"*2\r\n$3\r\nGET\r\n$8\r\nphpredis\r\n",27,MSG_DONTWAIT,NULL,0)=27poll([{fd=4,events=POLLIN|POLLERR|POLLHUP}],1,60000)=0(Timeout)close(4)phpredis补充另外一个问题，phpredis在抛出异常“readerroronconnection”时会关闭连接，后续处理为什么没有订购时重试机制？这种问题其实只出现在低版本，高版本有重试措施。我们可以看一下5.2.0版本的代码：当phpredis发生异常时，关闭socket，设置状态为REDIS_SOCK_STATUS_DISCONNECTED；每次执行命令都会调用redis_sock_get—>redis_sock_server_open；若函数判断状态为REDIS_SOCK_STATUS_DISCONNECTED，则发起重连；PHP_REDIS_APIRedisSock*redis_sock_get(zval*id,intno_throw){if((redis_sock=redis_sock_get_instance(id,no_throw))==NULL){returnNULL;}if(redis_sock_server_open(redis_sock)<0){spprintf(&errmsg,0,"Redis服务器%s:%d消失了",ZSTR_VAL(redis_sock->host),REDIS_THROW_EXCEPTION(errmsg,0);returnNULL;}returnredis_sock;}PHP_REDIS_APIintredis_sock_server_open(RedisSock*redis_sock){if(redis_sock){switch(redis_sock->status){caseREDIS_SOCK_STATUS_FAILED:returnFAILURE;caseREDIS_SOCK_STATUS_DISCONNECTED:returnredis_sock_connect(redis_sock);default:returnSUCCESS;}}最后返回FAILURE;}，说说我们常见的phpredis异常：Connectionlost：正常连接时，如果redis进程被杀死；它将尝试重新连接10次，如果仍然失败，则抛出异常；并且redis_sock状态将被设置为REDIS_SOCK_STATUS_FAILED；readerroronconnection：底层socket读取数据超时（默认60秒）或者读取socket出错时，抛出该异常，同时设置redis_sock状态为REDIS_SOCK_STATUS_DISCONNECTED；Redisserverwonderaway:$redis->connect()连接失败时返回false，执行后续命令时直接抛出此异常；Connectionclosed：手动调用closeredis关闭后，再次执行命令时抛出异常；为什么是3.2秒？最后，还有一个问题需要研究验证。为什么出现异常时所有请求的响应时间都是3.2秒？这是什么决定的？我们知道，线上异常的“readerroronconnection”是由于tw机器网络线路故障。这时发送命令请求时，TCP层理论上会经过重传，最终发送失败。是不是TCP层重传造成的3.2秒？基于以上实验，我们的tcpdump抓包分析：11:35:48.316384IPxxxx.18587>xxxx.4379:Flags[P.],seq990267312:990267339retransmission1=>11:35:48.517231IPxxxx.18587>xxxx.4379:标志[P.],seq990267312:990267339重传2=>11:35:48.718245IPxxxx.18587>xxxx.4379:标志[P.],seq990267312:990267339重传3=>11:35:49.121243IPxxxx.18587>xxxx.4379:Flags[P.],seq990267312:990267339重传4=>11:35:49.927245IPxxxx.18587>xxxx.4379:Flags[P.],seq992:99267399028.73394第一次发送数据，初始超时时间约为200ms；48.5秒超时定时器触发，第一次重传，并设置超时定时器200ms；48.7秒超时定时器触发，第二次重传，并设置超时定时器为400ms；49.1秒超时定时器触发，第三次重传，超时定时器设置为800ms；触发49.9秒超时定时器，第4次重传，超时定时器设置为1600ms；第四次重传超时后，没有进行下一次重试，总时间为49.9-48.3+1.6=3.2秒。另外可以清楚的看到，重传超时时间呈指数增长；通过tcpdump抓包分析，网络原因导致TCP重传，我们可以看到TCP重传总共耗时3.2秒；刚好接近异常请求的处理时间；还有一个问题：为什么TCP重传时间限制在3.2秒？它由系统配置决定：$sysctl-a|greptcp_retriesnet.ipv4.tcp_retries1=3net.ipv4.tcp_retries2=2tcp_retries1tcp_retries2配置limit为TCP包最大重传时间（计算）；tries1主要会更新路由缓存；如果超过tcp_retries2，内核会直接销毁socket并返回ETIMEDOUT；注意：网上也有tcp_retries1tcp_retries2限制重传次数的资料；读者可以查看linux2.6.5版本的源码，真正限制了重传次数，逻辑如下：staticinttcp_write_timeout(structsock*sk){retry_until=sysctl_tcp_retries2;如果(icsk->icsk_retransmits>=retry_until){tcp_write_err(sk);返回1；}返回0;};查看源码（sysctl_tcp_retries2搜索即可），TCP超时处理函数为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);返回1；可以看到首先检查了sysctl_tcp_retries1，如果超时则更新路由缓存；又教研了sysctl_tcp_retries2，如果超时，直接销毁socket，报错：staticvoidtcp_write_err(structsock*sk){sk->sk_err=sk->sk_err_soft?：超时；sk->sk_error_report(sk);tcp_done(sk);}我们的系统配置tcp_retries2
