记一次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...