記一次PHP偶現獲取不到Redis數據排查過程

時間  2020-04-09
標籤 一次 php 獲取 不到 redis 數據 排查 過程 欄目 PHP 简体版
原文   原文鏈接

李樂php

問題描述

  3月25號早晨8點左右線上迴歸時，發現getTestInfos接口部分請求返回空數據。kibana查詢異常請求日誌，輸入參數正常；梳理接口業務邏輯，是根據輸入參數從Redis查詢數據返回空致使。linux

  進一步確認：1）Redis查詢數據時未拋異常；2）Redis中確實存在該數據；3）只有偶爾部分請求沒法從Redis獲取數據。git

  10點25左右，重啓業務進程與confd，恢復正常。github

  兩個疑問：1）爲何部分請求會獲取不到Redis的數據；2）爲何重啓服務能夠恢復redis

現狀梳理

  已知：服務並非直連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配置正確，切同步配置到業務進程配置文件正確，以下：php7

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

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程