某机房的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
/01/14-13:43    2.5     2.6     2.6     5.0    1.6K   
/01/14-13:44   11.5     5.3     3.5     5.0    1.6K   
/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

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

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

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

# tsar --io -i 1
Time            rrqms   wrqms      rs      ws   rsecs   wsecs  rqsize  qusize   await   svctm    util
/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
/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
/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
/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
/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跑着会影响线上服务。(而且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 

[admin@tfsxx vm]$ cat dirty_ratio  

[admin@tfsxx vm]$ cat dirty_expire_centisecs  

cat dirty_background_ratio  

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

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

. 有问题的机器,系统盘是两块磁盘做RAID1(linux md),其他系统盘都是裸盘
. 有问题的机器CPU8核,其他都是16核及以上

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

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

int main(int argc, char* argv[])
{
    if (argc != 4)
    {
        fprintf(stderr, "%s logfile interval countn", 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 keepaliven", 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 expiren", 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 failedn", path);
        return -1;
    }

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

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

    printf("write endn");

    sleep(expire);
    printf("closen");
    close(fd);

    printf("unlinkn");
    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阻塞的现象

 keepalive
05 keepalive
09 keepalive
13 keepalive
30 keepalive
34 keepalive

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

ref:
2014-01-15
blog.yunnotes.net


ccj 于 2017-12-20 23:18 修改
0 回复
需要 登录 后方可回复, 如果你还没有账号你可以 注册 一个帐号。