web應用借助於結構:spring mvc + quartz結構,部署到tomcat容器時,shutdown時的error信息:
appears to have started a thread named [schedulerFactoryBean_Worker-1] but has failed to stop it. This is very likely to create a memory leak
quartz的thread終止的確保,加了個servletListener,工作就是顯示的使用shutdown方法:
@Override public void contextDestroyed(ServletContextEvent sce) { LogAgent.debug(LoggerEnum.SYS_INFO, "QUARTZ.context destroy start."); WebApplicationContext webApplicationContext = (WebApplicationContext) sce.getServletContext() .getAttribute(WebApplicationContext.ROOT_WEB_APPLICATION_CONTEXT_ATTRIBUTE); org.springframework.scheduling.quartz.SchedulerFactoryBean fact = (org.springframework.scheduling.quartz.SchedulerFactoryBean) webApplicationContext .getBean("schedulerFactoryBean"); if (fact != null) { try { LogAgent.debug(LoggerEnum.SYS_INFO, "shedule shutdown start."); fact.getScheduler().shutdown(); LogAgent.debug(LoggerEnum.SYS_INFO, "shedule shutdown end."); } catch (SchedulerException e) { LogAgent.error(LoggerEnum.ERROR_INFO, e); } } try { Thread.sleep(1000); } catch (InterruptedException e) { LogAgent.error(LoggerEnum.ERROR_INFO, e); } LogAgent.debug(LoggerEnum.SYS_INFO, "QUARTZ.context destroy end."); }
接着的提示信息:
created a ThreadLocal with key of type [org.apache.commons.lang.builder.ReflectionToStringBuilder$1] (value [org.apache.commons.lang.builder.ReflectionToStringBuilder$1@1a08777c]) and a value of type [java.util.HashSet] (value [[]]) but failed to remove it when the web application was stopped. This is very likely to create a memory leak.
檢查了代碼,發現日志輸出的部分,有個類使用了類:org.apache.commons.lang.builder.ToStringBuilder,其內部實現使用了org.apache.commons.lang.builder.ReflectionToStringBuilder,再跟進的時候發現,ToStringBuilder的append方法,在append和toString的時候,向ToStringStyle register或unregister(就是threadlocal的set obj和 remove);跟蹤代碼時發現明顯該threadlocal在每次toString時都有remove,不應該會出現leak memory的傾向才對(若運行一半異常還是有可能,但該方法就是一個日志記錄,所以無這方面的擔心),最后檢查pom時發現,commons-lang有兩個包,分別是appache-lang和commons-lang:jar名都是commons-lang,刪掉appache-lang的這個warn警告就沒出現了(我也不記得了,為什么會引入兩個commons-lang)。
結果再運行時,發現另一個錯誤了:
信息: Illegal access: this web application instance has been stopped already. Could not load ch.qos.logback.core.status.WarnStatus. The eventual following stack trace is caused by an error thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access, and has no functional impact. java.lang.IllegalStateException at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1588) at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1547) at ch.qos.logback.classic.LoggerContext.noAppenderDefinedWarning(LoggerContext.java:175) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:267) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:442) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:396) at ch.qos.logback.classic.Logger.debug(Logger.java:503) at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:612)
首先級別上來看,是信息,不是錯誤;
但是本着看到error stack就不爽的本質,了解了一把,原因大致如此:
- quartz的SimpleThreadPool在初始化的時候,啟動了一定數量的線程:WorkerThread,然后它就讓WorkerThread自己滴去干活了。
- 然后當容器發出shutdown的信號時,pool就告訴workerthread們,要shutdown了,現在問題來了,看代碼:
/** * <p> * Signal the thread that it should terminate. * </p> */ void shutdown() { run.set(false); }
很明顯,這就是它的shutdown方法,它並不是要自己殺掉自己,而是告知自己的當前狀態是false了,再來看看該狀態作用的地方:
1 @Override 2 public void run() { 3 boolean ran = false; 4 5 while (run.get()) { 6 try { 7 synchronized(lock) { 8 while (runnable == null && run.get()) { 9 lock.wait(500); 10 } 11 12 if (runnable != null) { 13 ran = true; 14 runnable.run(); 15 } 16 } 17 } catch (InterruptedException unblock) { 18 // do nothing (loop will terminate if shutdown() was called 19 try { 20 getLog().error("Worker thread was interrupt()'ed.", unblock); 21 } catch(Exception e) { 22 // ignore to help with a tomcat glitch 23 } 24 } catch (Throwable exceptionInRunnable) { 25 try { 26 getLog().error("Error while executing the Runnable: ", 27 exceptionInRunnable); 28 } catch(Exception e) { 29 // ignore to help with a tomcat glitch 30 } 31 } finally { 32 synchronized(lock) { 33 runnable = null; 34 } 35 // repair the thread in case the runnable mucked it up... 36 if(getPriority() != tp.getThreadPriority()) { 37 setPriority(tp.getThreadPriority()); 38 } 39 40 if (runOnce) { 41 run.set(false); 42 clearFromBusyWorkersList(this); 43 } else if(ran) { 44 ran = false; 45 makeAvailable(this); 46 } 47 48 } 49 } 50 51 //if (log.isDebugEnabled()) 52 try { 53 getLog().debug("WorkerThread is shut down."); 54 } catch(Exception e) { 55 // ignore to help with a tomcat glitch 56 } 57 }
其實就是第5行,對run進行判斷,如果是false,就直接退出了。
所以pool的shut通知並不是馬上就能被執行,如果線程正好走while判斷條件,馬上就會被退出;
如果該thread無任務可做時,見第8行:lock.wait(500),所以會wait,這個時候再退出,結果去getLog的時候,loggerContextListener.destroy先執行,無logger了,所以會有該信息。
-
解決辦法就是:
將log的listener放到最后(如果有多個listener的話):
<listener> <listener-class>com.xxx.listener.QuartzLitener</listener-class> </listener> <listener> <listener-class>com.xxx.web.listener.LogbackListener</listener-class> </listener>