起因-日志丢失
生产上出现过几次日志丢失的问题,我们日志每小时生成一个文件,然后每个小时刚到整点切换的时候会生成新文件然后正常输出日志,到了固定时点就空了,只有一个定时清理数据的线程打的几行日志。
通过分析,是因为我们的应用部署在weblogic上,每次重新发war包并不会重启weblogic,只是停止之前的应用,重新启动一个新的,而之前的应用有个别线程没能关闭,与新应用同时打日志,出现了问题。
泄漏的线程与新应用的线程各自持有一个log4j的appender,关键这两个appender的规则完全一致。
新应用的线程一直在打印日志,到了整点就切换,而泄漏的线程每半个小时才被唤醒一次,然后打印几句日志。
我们来看一下log4j切换日志的代码:
/**
Rollover the current file to a new file.
*/
void rollOver() throws IOException {
/* Compute filename, but only if datePattern is specified */
if (datePattern == null) {
errorHandler.error("Missing DatePattern option in rollOver().");
return;
}
String datedFilename = fileName+sdf.format(now);
// It is too early to roll over because we are still within the
// bounds of the current interval. Rollover will occur once the
// next interval is reached.
if (scheduledFilename.equals(datedFilename)) {
return;
}
// close current file, and rename it to datedFilename
this.closeFile();
//!!!!!!!!!!重点在这!!!!
//如果存在已经重名的就给删掉。
File target = new File(scheduledFilename);
if (target.exists()) {
target.delete();
}
File file = new File(fileName);
boolean result = file.renameTo(target);
if(result) {
LogLog.debug(fileName +" -> "+ scheduledFilename);
} else {
LogLog.error("Failed to rename ["+fileName+"] to ["+scheduledFilename+"].");
}
try {
// This will also close the file. This is OK since multiple
// close operations are safe.
this.setFile(fileName, true, this.bufferedIO, this.bufferSize);
}
catch(IOException e) {
errorHandler.error("setFile("+fileName+", true) call failed.");
}
scheduledFilename = datedFilename;
}
假如现在刚到10点了,因为新应用一直在打印日志,10点时切换了一个新日志,然后不停的打日志,结果到了10:15,另一个appender也要打日志了,它发现过了10点了,自己原来持有的日志还是9点点,就切换一个,发现已经有重名点,就删掉重建了,这就是原因。可是有人会说前一个appender持有的文件句柄文件被删了,它不应该报异常吗?经过我的实验,没有任何异常反应。
public static void main(String[] args) throws IOException {
File a = new File("test.txt");
BufferedWriter bw1 = new BufferedWriter(
new FileWriter(a));
bw1.write("aaaaaaaa");
bw1.flush();
a.delete();
bw1.write("aaaaaaaaa");
bw1.flush();
File b = new File("test.txt");
BufferedWriter bw2 = new BufferedWriter(
new FileWriter(b));
bw2.write("bbbbbbbbb");
bw2.flush();
bw1.write("aaaaaaaaa");
bw1.flush();
}
上面这段代码不会有任何异常,最终生成的文件内容是bbbbbbbbb。
这个问题只是线程泄漏带来的问题之一,还有与之对应的内存泄漏等其它问题。接下来就来分析一下线程泄漏等原因与如何避免此类问题。
应用服务器如何清理线程?
对于应用中自己起动的一些后台线程,应用服务器一般不会给你停掉。不了解weblogic怎么清理这些线程的,看了下tomcat的,tomcat默认并不会强制关闭这些线程。
先看tomcat中的一段警告日志:
七月 27, 2016 7:02:10 下午 org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
警告: The web application [firefly] appears to have started a thread named [memkv-gc-thread-0] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
sun.misc.Unsafe.park(Native Method)
Java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1090)
java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
java.lang.Thread.run(Thread.java:745)
在tomcat中有关停止这些线程有一个配置默认是关的,如果开了,它是用stop方法,也是有风险的。