线上dataserver假死问题分析

作者：[e-mail]
博客：ydzhang.blog.chinaunix.net | blog.yunnotes.net
微博：

某机房的TFS集群上线后，集群内一直有部分dataserver(DS)出现假死的现象，这里的假死意思是，Nameserver（NS)认为DS挂了，但实际上DS正常的在运行，但因为DS的心跳消息没有及时发送达NS，导致NS认为DS挂了。

假死的问题之前也有出过，之前为了方便定位，DS每发一次心跳前会打印一条日志，方便定位假死是由"NS还是DS造成的”；DS的行为类似于下面的代码。

keepalive(ns_ip_port)
{ 
    log("keepalive to some ns" + current_time) // 调用write syscall，buffer io do_keepalive_to_ns() 
    sleep 4 // 心跳间隔4s 
} 

DS假死时日志如下

[2014-01-15 13:43:10.819975] INFO  heart_manager.cpp:142 [1481599296] KEEPALIVE, who: 0 
[2014-01-15 13:43:14.820651] INFO  heart_manager.cpp:142 [1481599296] KEEPALIVE, who: 0 
[2014-01-15 13:43:18.821228] INFO  heart_manager.cpp:142 [1481599296] KEEPALIVE, who: 0 
[2014-01-15 13:43:22.821699] INFO  heart_manager.cpp:142 [1481599296] KEEPALIVE, who: 0 
[2014-01-15 13:43:27.354043] INFO  heart_manager.cpp:142 [1481599296] KEEPALIVE, who: 0 
[2014-01-15 13:43:31.354403] INFO  heart_manager.cpp:142 [1481599296] KEEPALIVE, who: 0 
[2014-01-15 13:43:40.826496] INFO  heart_manager.cpp:142 [1481599296] KEEPALIVE, who: 0 
[2014-01-15 13:43:44.827094] INFO  heart_manager.cpp:142 [1481599296] KEEPALIVE, who: 0

正常时，每4s一次心跳，但43:31心跳后，下一次心跳是在43:40，间隔了9s，而NS连续两次（8s)没收到DS的心跳就认为DS挂了，9s的心跳间隔导致NS认为DS已经挂了。

---

假死时，DS的load情况如下

# tsar --load -i 1 
Time           load1   load5  load15    runq    plit 
15/01/14-13:43   2.5     2.6     2.6     5.0    1.6K 
15/01/14-13:44  11.5     5.3     3.5     5.0    1.6K 
15/01/14-13:45  7.2      5.2     3.6     1.0    1.6K  

出现问题的这批机器比较老，都是8核的CPU， 从load记录看，假死时机器的load1飙高很多。DS是IO密集型的应用，占用的CPU资源很少，在DS的机器上，同时部署了imgsrc服务（主要从TFS里读取图片，然后根据请求的需要，对图片进行处理），是CPU密集型的应用。

怀疑是imgsrc的请求太多，把CPU资源耗光，导致DS进程hang住，但调查后发现所有的imgsrc都绑定在0-5号CPU。

# ps aux | grep httpd | grep -v grep | awk '{print $2}' | xargs -n 1 taskset -p 
pid 1466's current affinity mask: 3f
pid 2131's current affinity mask: 3f 
pid 18967's current affinity mask: 3f
pid 19160's current affinity mask: 3f 
pid 21750's current affinity mask: 3f
pid 24749's current affinity mask: 3f 
pid 25517's current affinity mask: 3f
pid 28073's current affinity mask: 3f 
pid 29239's current affinity mask: 3f
pid 31045's current affinity mask: 3f 
pid 31652's current affinity mask: 3f 

请教了内核组的木名同学，得到如下有用的信息

1. 进程绑定cpu后，fork出来的子进程会继承cpu的绑定属性
2. 根据进程调度的策略，不太可能出现进程持续9s没有得到运行时间片
3. load并不仅仅表示“在运行的进程数，D住的进程也算” 

---

假死时，DS系统盘的IO如下

# tsar --io -i 1
Time            rrqms   wrqms      rs      ws   rsecs   wsecs  rqsize  qusize   await   svctm    util
15/01/14-13:41    0.0    11.6     0.1    13.8     2.4   100.8     7.4     0.0    11.6     4.1     5.7
15/01/14-13:42    0.0     9.3     0.2    13.5     1.6    90.6     6.7     0.0    11.4     4.1     5.6
15/01/14-13:43    0.0    11.3     0.5    14.0     5.6   100.8     7.3     0.0    11.2     4.2     6.1
15/01/14-13:44    0.0    1.1K     0.5    69.5     3.6    8.7K    68.7    44.0   639.4     5.5    38.1
15/01/14-13:45    0.9     9.6     7.1    16.1   278.2   101.8    16.4     0.0     9.6     3.6     8.4 

从IO的信息可以看出，假死时系统盘的每秒IO数、IO大小都有明显增加（14==>69，100==> 4.7K)。经过了解，write在脏页超过阈值等条件下，会同步等待内核回收内存，是可能导致write阻塞很长时间的。

同时再分析DS的日志发现，13:43:40以后还打出过时间戳为31s的日志，这些也证明是write调用阻塞。

[2014-01-15 13:43:10.819975] INFO  heart_manager.cpp:142 [1481599296] KEEPALIVE, who: 0
[2014-01-15 13:43:14.820651] INFO  heart_manager.cpp:142 [1481599296] KEEPALIVE, who: 0
[2014-01-15 13:43:18.821228] INFO  heart_manager.cpp:142 [1481599296] KEEPALIVE, who: 0
[2014-01-15 13:43:22.821699] INFO  heart_manager.cpp:142 [1481599296] KEEPALIVE, who: 0
[2014-01-15 13:43:27.354043] INFO  heart_manager.cpp:142 [1481599296] KEEPALIVE, who: 0
[2014-01-15 13:43:31.354403] INFO  heart_manager.cpp:142 [1481599296] KEEPALIVE, who: 0
上面这行日志产生的时间是31s，实际上打印的时间是36s
[2014-01-15 13:43:40.826496] INFO  heart_manager.cpp:142 [1481599296] KEEPALIVE, who: 0
[2014-01-15 13:43:44.827094] INFO  heart_manager.cpp:142 [1481599296] KEEPALIVE, who: 0 

---

接下来的问题时，是谁在写数据? 首先想到的是机器后台的crontab任务

1. 删日志: 定期检查机器系统盘剩余空间是否足够，如不足则删除一批最老的日志
2. 监控日志: 定期分析服务进程新产生的日志，分析是否存在一些特定的关键字

但经过核对，时间点以及这两个crontab引起的负载跟这里的IO是完全不匹配的。

三百同学建议，但问题是"不确定集群内哪台机器、什么时候会出出现这种现象，没有任何规律"，而且都在线上服务，一直让blktrace跑着会影响线上服务。（而且blktrace本身也对IO行为有影响，这里有介绍把blktrace的输出定向到网络的方法）

---

如何才能低开销的找出被写的文件？

从44分统计到的IO来看，IO的总大小约为4700 * 512 * 60，接近300M，增加的大小很明显，而服务进程的日志正常情况是不会增加这么快的，只要这些写不是“覆盖写”，那么每隔一段时间df看看，就能知道是哪个分区增加的。

在集群内所有机器运行了如下脚本，每隔30s把df的输出重定向到文件

for((i=1;i<=1440;i++)); do date >> /tmp/dfinfo
    df | grep md >> /tmp/dfinfo  
    sleep 30 done

假死现象再次出现时，发想tmp目录的空间增长了不少，跟写的大小吻合。/tmp目录下文件不多，基本都是很小的文件，所以可以断定，这个文件产生后马上就会被删除掉，将脚本进行了修改，除了输出df的信息，还将ls -l /tmp的输出记录下来

for((i=1;i<=1440;i++)); do date >> /tmp/dfinfo
    df | grep md >> /tmp/dfinfo
    date >> /tmp/tmp_dir_files
    ls -l /tmp >> /tmp/tmp_dir_files
    sleep 30 done

最后终于发现写到临时文件是magick-xxx，是imagemagick产生的临时文件，imgsrc用到imagemagick库。

-rw-r--r-- 1 admin  admin 72821 Jan 12 00:52 dfinfo
drwx------ 2 root   root 16384 Mar 17 2011 lost+found 
-rw------- 1 admin  admin 284262410 Jan 12 00:51 magick-18109OuBPadq0wFec 

---

接下来的问题，为什么这种假死现象，只出现在某一批机器上？

看了vm相关参数后，发现这批机器/etc/sysctl.conf文件中包含如下配置，这是TFS很早期的一些配置参数，提高刷盘的频率，降低数据处于不安全状态的时间。

vm.dirty_writeback_centisecs = 100
vm.dirty_ratio = 8
vm.dirty_expire_centisecs = 200
vm.dirty_background_ratio = 3 

至此，本以为问题就找到了，但把这些参数恢复到跟其他机器一致后，问题还是存在。

[admin@tfsxx vm]$ cat dirty_writeback_centisecs 
500
[admin@tfsxx vm]$ cat dirty_ratio  
20
[admin@tfsxx vm]$ cat dirty_expire_centisecs  
3000
cat dirty_background_ratio  
10 

把有问题的机器的IO调度器从cfq改成deadline，问题也还是存在。

对比有问题的机器硬件配置，不同的地方

1. 有问题的机器，系统盘是两块磁盘做RAID1（linux md），其他系统盘都是裸盘
2. 有问题的机器CPU8核，其他都是16核及以上 

---

请内核组的同学帮忙分析，为了简化问题，写了两个模拟程序，能把问题复现出来

模拟心跳的程序，每隔interval发一次心跳，心跳前输出一条日志到log_file

int main(int argc, char* argv[])
{
    if (argc != 4)
    {
        fprintf(stderr, "%s logfile interval count\n", argv[0]);
        return -1;
    }

    char* logfile = argv[1];
    int32_t interval = atoi(argv[2]);
    int32_t count = atoi(argv[3]);

    int fd = open(logfile, O_RDWR | O_CREAT, 0644);
    assert(fd >= 0);

   for (int i = 0; i < count; i++)
   {
       char buf[4096];
       sprintf(buf, "%d keepalive\n", time(NULL));
       write(fd, buf, strlen(buf));
       sleep(interval);
   }

   close(fd);

   return 0;
 } 

生成临时文件的模拟程序，写数据到path文件，每次bs字节，写count次，expire秒后关闭文件并删除

int main(int argc, char* argv[])
{
    if (argc != 5)
    {
        fprintf(stderr, "usage: %s path bs count expire\n", argv[0]);
        return -1;
    }

    char* path = argv[1];
    int32_t bs = atoi(argv[2]);
    int32_t count = atoi(argv[3]);
    int32_t expire = atoi(argv[4]);

    int fd = open(path, O\_RDWR | O\_CREAT);
    if (fd < 0)
    {
        fprintf(stderr, "%s open failed\n", path);
        return -1;
    }


    char* buf = (char*)malloc(bs * sizeof(char));

    printf("write begin\n");
    for (int i = 0; i < count; i++)
    {
        write(fd, buf, bs);
    }

    printf("write end\n");

    sleep(expire);
    printf("close\n");
    close(fd);


    printf("unlink\n");
    unlink(path);

    free(buf);

    return 0;
} 

复现问题步骤

1. 后台启动心跳模拟程序 ./keepalive keealive.log 4 100 & 【4s一次，发100次】
2. 启动生成临时文件模拟程序 ./sim /tmp/simfile 4096 200000 15 【写200K次4096字节数据到临时文件】

观察keepalive.log就能发现write阻塞的现象

1389760901 keepalive
1389760905 keepalive
1389760909 keepalive
1389760913 keepalive
1389760930 keepalive
1389760934 keepalive 

913 keepalive后，下一次keepalive是930，间隔了7s，说明write系统调用（printf打日志）耗时3s。

阅读原文