这两天被一个问题困扰:内核出现异常的时候会存在狂刷日志的情况,而且日志为同一个,此时日志回滚和日志不断抢占日志文件资源,导致内核卡死
那解决该问题的思路有两个:
1,从源头改内核卡死的原因
卡死都是从logrotate开始,cron设置logrotate三分钟运行一次,当大于10M运行一次,一般卡死三五个logrotate就卡死卡死其他进程了
卡死logrotate的原因:syslog-ng在一刻不停的在打印日志文件,一直占用messages文件,而logrotate会在其大于10M的时候 通过配置:copytruncate 来进行转储的,该操作会复制当前的日志文件,然后清空原来的文件,关于该方式的一个说明如下:
这个方案的思路是把正在输出的日志拷(copy)一份出来,再清空(trucate)原来的日志。详细步骤如下:
-
拷贝程序当前正在输出的日志文件,保存文件名为滚动结果文件名。这期间程序照常输出日志到原来的文件中,原来的文件名也没有变。
-
清空程序正在输出的日志文件。清空后程序输出的日志还是输出到这个日志文件中,因为清空文件只是把文件的内容删除了,文件的inode编号并没有发生变化,变化的是元信息中文件内容的信息。
结果上看,旧的日志内容存在滚动的文件里,新的日志输出到空的文件里。实现了日志的滚动。
这个方案有两个有趣的地方。
-
文件清空并不影响到输出日志的程序的文件表里的文件位置信息,因为各进程的文件表是独立的。那么文件清空后,程序输出的日志应该接着之前日志的偏移位置输出,这个位置之前会被
\0
填充才对。但实际上logroate清空日志文件后,程序输出的日志都是从文件开始处开始写的。这是怎么做到的?这个问题让我纠结了很久,直到某天灵光一闪,这不是logrotate做的,而是成熟的写日志的方式,都是用O_APPEND
的方式写的。如果程序没有用O_APPEND
方式打开日志文件,变会出现copytruncate后日志文件前面会被一堆\0
填充的情况。 -
日志在拷贝完到清空文件这段时间内,程序输出的日志没有备份就清空了,这些日志不是丢了吗?是的,copytruncate有丢失部分日志内容的风险。所以能用create的方案就别用copytruncate。所以很多程序提供了通知我更新打开日志文件的功能来支持create方案,或者自己做了日志滚动,不依赖logrotate。
我猜测是在转储的时候,对该文件的清空操作一直被搁置,因为文件一直在被写入,从而造成的D僵死进程logrotate。详细原因有待我进一步研习。。。
2,修改日志系统,优化日志的回滚机制或者打印机制
从修改日志系统的思路出发,又有三四个详细方案:
方案一:使用syslog-ng的原有的垃圾信息处理机制去屏蔽当前的垃圾信息,这个功能是在研究syslog-ng的时候发现的 ,在官方的说明文档 中:http://www.balabit.com/products/syslog_ng/reference/book1.html 有一个这样的参数:
1126: | KW_GC_BUSY_THRESHOLD '(' LL_NUMBER ')' { /* ignored */; }
1127: | KW_GC_IDLE_THRESHOLD '(' LL_NUMBER ')' { /* ignored */; }
#if ENABLE_FEATURE_SYSLOGD_DUP timestamp_and_log_internal("ENABLE_FEATURE_SYSLOGD_DUP (941) "); #define TIME_LOG_LEN 20 if ((option_mask32 & OPT_dup) && (sz == last_sz)) { timestamp_and_log_internal("ENABLE_FEATURE_SYSLOGD_DUP (946) "); if (memcmp((last_buf+TIME_LOG_LEN), (recvbuf+TIME_LOG_LEN), (sz-TIME_LOG_LEN)) == 0)//ignoge time index { timestamp_and_log_internal("ENABLE_FEATURE_SYSLOGD_DUP (949) "); continue; } } last_sz = sz; #endif
就是对比上一次日志的长度,是否跟本次相同,如果相同再对比其内容是否一模一样。
2,只有打印语句:timestamp_and_log_internal 可以辅助调试,但是有诸多不便。当然必要的时候syslog也是可以用上一用的。
本以为打开了该功能就可以了,但是有一个问题:日志的时间戳会导致两次日志内容memcmp的对比不一致,也就是说完全相同的日志打印,时间戳肯定是不一致的,就算重复粒度大,也会导致一秒打一次的效果。
去除时间戳:修改syslog-ng.conf :template g_tmpl { template("$YEAR $R_STAMP $HOST $MSGHDR $MSG\n");}; 本条宏语句中的YEAR等就是时间,这些宏也是syslog-ng自身提供的,可以在它的官方说明文档中找到。
当然去除时间戳是一种丢西瓜的做法,对以后定位问题有诸多的不便,那么怎么改呢?如下:
if (memcmp((last_buf+TIME_LOG_LEN), (recvbuf+TIME_LOG_LEN), (sz-TIME_LOG_LEN)) == 0)//ignoge time index
去除时间戳的对比,只对比日志的内容,实际日志的内容的长度用宏:TIME_LOG_LEN来表明,此语句会自动只对比TIME_LOG_LEN之后的内容,也就是屏蔽了时间戳的对比。
至此,大致算解决了问题,但是对于单一重复的是有用的,但是如果多条的重复?又将如何处理?
下一步着手添加对十条的日志记录,以确定是否要将日志信息记录到日志文件。