首页 > 代码库 > 多线程下写日志
多线程下写日志
鄙人最近遇到了一个奇特的线上事故，记录一下，以备记忆。
鄙人所在的部门负责给公司提供各种基础库，即基础架构部门。最近某别的部门用本部门提供的支持多线程版本的日志库后，出现这样一个奇特的现象：当磁盘被日志写满以后，他们的数据文件的头部被写上了最新的日志！就是说，别的部门的程序的数据文件被日志数据给污染了。
这里先不介绍这个事故的原因。先说下这个日志库的写日志过程，其流程大致如下：
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)); //data file name
for (int idx = 0; idx < 10000; idx++) {
int fd = open(log_file_name, O_CREAT | O_APPEND | O_RDWR, 0666);
log_debug("1234567890qwertyuiopasdfghjklzxcvbnmQWERhello, %d", (int)(int_ptr)(arg));
close(fd);
}
pthread_exit(NULL);
return NULL;
}
#define MAX_THEAD_NUM 1000
int main()
{ // set log path: /home/alex/vfs/
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。
最终我采用了第二种解决方法，很好地解决了问题。如果你有更好的方法，欢迎评论。
此记，谢绝转载。
多线程下写日志