记一次PHP偶现获取不到Redis数据排查过程

LNMPRG源码研究

李乐

问题描述

  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实例。架构如下:
phpredis.png

  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...

阅读 3.2k

一群热爱代码的人 研究Nginx PHP Redis Memcache Beanstalk 等源码 以及一群热爱前端的人

7k 声望
12.6k 粉丝
0 条评论

一群热爱代码的人 研究Nginx PHP Redis Memcache Beanstalk 等源码 以及一群热爱前端的人

7k 声望
12.6k 粉丝
文章目录
宣传栏