多线程下写日志

原创
2014/10/31 17:29
阅读数 1.3K

        鄙人最近遇到了一个奇特的线上事故,记录一下,以备记忆。

        鄙人所在的部门负责给公司提供各种基础库,即基础架构部门。最近某别的部门用本部门提供的支持多线程版本的日志库后,出现这样一个奇特的现象:当磁盘被日志写满以后,他们的数据文件的头部被写上了最新的日志!就是说,别的部门的程序的数据文件被日志数据给污染了。

        这里先不介绍这个事故的原因。先说下这个日志库的写日志过程,其流程大致如下:

       step1  如果log的fd为-1,就重新通过C函数open再打开一个log_fd;

       step2  写log内容,即ssize_t size = write(log_fd, buf, len);

       step3  如果size等于len,则转step 7,否则继续step 8;

       step4  对log_fd加mutex锁;

       step5  close(log_fd);

       step6  log_fd赋值为-1;

       step7  解锁;

       step8  return。

       

       然后用户进程的逻辑大致为:

       logic1  当有新数据的时候,通过C函数open打开一个data_fd;

       logic2  write(data_fd, data, data_len);

       logic3  close(data_fd)。


        假设这样一个场景:有线程A先写了一条日志,线程B紧随其后也来写一条日志,线程C正常进行数据文件写操作。通过假设一下情况,在磁盘满的时候可能复现这个bug。假设程序运行过程是:

        过程1 线程A执行到step6,此时log_fd为3,线程A给log_fd赋值为-1;

        过程2 线程B执行到step2,此时log_fd仍然为3,但其实线程A已经将fd为3的文件关闭掉了,所以线程B持有的这个log_fd此时为非法描述符;

        过程3 线程C执行到logic2,因为线程A已经将fd 3归还给os,所以os此时把3给了data_fd,即data_fd为3。

        如果这个假设成立,那么在过程线程B的log内容一定会写到数据文件中。


       为了验证这个情况,先在公司的linux服务器建立了一个loop文件系统,简历步骤如下:

      1 dd if=/dev/zero of=/home/alex/100.img bs=1M count=100     # 在这一步建立一个容量为100M的loop设备
      2 mkfs.ext2 100.img                                                                          # 将loop设备格式化为ext2格式
      3 mount 100.img /home/alex/vfs -o loop -n                                  # 简历loop设备,将/home/alex/vfs目录映射到这个loop设备上

     由于设备的容量非常小,上面的bug就很容易重现,重现逻辑很简单,首先设置log的文件目录是/home/alex/vfs,然后启动1000个线程,每个线程的逻辑函数如下: 

void* thread_func(void *arg)
{
    char log_file_name[32];
    sprintf(log_file_name, "/tmp/%d",  (int)(int_ptr)(arg));
    for (int idx = 0; idx < 10000; idx++)
    {
        int fd = open(log_file_name, O_CREAT | O_APPEND | O_RDWR, 0666);
        log_debug("hello, %d", (int)(int_ptr)(arg));
	close(fd);
    }
	
    pthread_exit(NULL);
    return NULL;
}

#define	MAX_THEAD_NUM	1000
int main()
{
    pthread_t id[MAX_THEAD_NUM];
    for (int idx = 0; idx < MAX_THEAD_NUM; idx++) {
        pthread_create(id + idx,  NULL,  thread_func,  (void*)(intptr_t)(idx));
    }

    for (idx = 0; idx < thread_num; idx++) {
	pthread_join(id[idx], NULL);
    }

    return 0;
}



    上面的线程函在循环里不断的打开关闭数据文件,即其大小为0。程序运行完毕后,数据文件的大小若不为0,就能验证上面的假设。


    运行以上测试程序后,观察到大量的数据文件的大小不为0,其内容为log内容。其实这个事故还算幸运,若用户的数据不是输出到磁盘,而是通过tcp socket发送到别的机器,那么这个bug会导致tcp的流内容莫名其妙的乱掉,那问题就更不容易追查了。

    验证了假设,问题就很容易解决了。解决方法有两种:

    第一种方法,对fd加引用计数。即线程每获取一个新的log_fd时候,要增加一次引用次数;如果出现write失败的情况,要减小一次引用次数,当引用次数为0的时候,再close掉log_fd;

    第二种方法,使用tls(thread local storage)形式的log file。即每个线程都打开同一个log file,open函数的“mode参数”为“O_CREAT | O_APPEND | O_RDWR”,当写失败的时候,各自close各自的log_fd。

    最终我采用了第二种解决方法,很好地解决了问题。如果你有更好的方法,欢迎评论。


    此记,谢绝转载。

展开阅读全文
加载中
点击加入讨论🔥(2) 发布并加入讨论🔥
打赏
2 评论
14 收藏
0
分享
返回顶部
顶部