Once again, I apologize for the wall of text. However, most of it is
pretty quick and dirty code, so it should be easy to skim.
I'm guessing the end result is harmless?
It does seem like a race condition. Everything seems to work fine
until shutdown. When DEBUG is set in logging, you get the following in
catalina.out:
Oct 18, 2010 4:12:38 PM org.apache.catalina.loader.WebappClassLoader
clearReferencesThreads
SEVERE: The web application [/QSchedule] appears to have started a
thread named [SampleScheduler_Worker-1] but has failed to stop it.
This is very likely to create a memory leak.
Oct 18, 2010 4:12:38 PM org.apache.catalina.loader.WebappClassLoader
clearReferencesThreads
SEVERE: The web application [/QSchedule] appears to have started a
thread named [SampleScheduler_Worker-2] but has failed to stop it.
This is very likely to create a memory leak.
Oct 18, 2010 4:12:38 PM org.apache.catalina.loader.WebappClassLoader
clearReferencesThreads
SEVERE: The web application [/QSchedule] appears to have started a
thread named [SampleScheduler_Worker-3] but has failed to stop it.
This is very likely to create a memory leak.
Oct 18, 2010 4:12:38 PM org.apache.catalina.loader.WebappClassLoader loadClass
INFO: Illegal access: this web application instance has been stopped
already. Could not load java.io.PrintStream. 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:1531)
at
org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1491)
at org.apache.log4j.helpers.LogLog.error(LogLog.java:142)
at
org.apache.log4j.helpers.PatternParser$DatePatternConverter.convert(PatternParser.java:447)
at org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:64)
at org.apache.log4j.PatternLayout.format(PatternLayout.java:503)
at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301)
at org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
at
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
at org.apache.log4j.Category.callAppenders(Category.java:203)
at org.apache.log4j.Category.forcedLog(Category.java:388)
at org.apache.log4j.Category.log(Category.java:853)
at org.slf4j.impl.Log4jLoggerAdapter.debug(Log4jLoggerAdapter.java:204)
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:595)
log4j:ERROR Error occured while converting date.
java.lang.NullPointerException
at java.lang.AbstractStringBuilder.append(Unknown Source)
at java.lang.StringBuffer.append(Unknown Source)
at org.apache.log4j.helpers.ISO8601DateFormat.format(ISO8601DateFormat.java:132)
at java.text.DateFormat.format(Unknown Source)
at
org.apache.log4j.helpers.PatternParser$DatePatternConverter.convert(PatternParser.java:444)
at org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:64)
at org.apache.log4j.PatternLayout.format(PatternLayout.java:503)
at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301)
at org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
at
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
at org.apache.log4j.Category.callAppenders(Category.java:203)
at org.apache.log4j.Category.forcedLog(Category.java:388)
at org.apache.log4j.Category.log(Category.java:853)
at org.slf4j.impl.Log4jLoggerAdapter.debug(Log4jLoggerAdapter.java:204)
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:595)
log4j:ERROR Error occured while converting date.
java.lang.NullPointerException
at java.lang.AbstractStringBuilder.append(Unknown Source)
at java.lang.StringBuffer.append(Unknown Source)
at org.apache.log4j.helpers.ISO8601DateFormat.format(ISO8601DateFormat.java:132)
at java.text.DateFormat.format(Unknown Source)
at
org.apache.log4j.helpers.PatternParser$DatePatternConverter.convert(PatternParser.java:444)
at org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:64)
at org.apache.log4j.PatternLayout.format(PatternLayout.java:503)
at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301)
at org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
at
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
at org.apache.log4j.Category.callAppenders(Category.java:203)
at org.apache.log4j.Category.forcedLog(Category.java:388)
at org.apache.log4j.Category.log(Category.java:853)
at org.slf4j.impl.Log4jLoggerAdapter.debug(Log4jLoggerAdapter.java:204)
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:595)
log4j:ERROR Error occured while converting date.
java.lang.NullPointerException
at java.lang.AbstractStringBuilder.append(Unknown Source)
at java.lang.StringBuffer.append(Unknown Source)
at org.apache.log4j.helpers.ISO8601DateFormat.format(ISO8601DateFormat.java:132)
at java.text.DateFormat.format(Unknown Source)
at
org.apache.log4j.helpers.PatternParser$DatePatternConverter.convert(PatternParser.java:444)
at org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:64)
at org.apache.log4j.PatternLayout.format(PatternLayout.java:503)
at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301)
at org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
at
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
at org.apache.log4j.Category.callAppenders(Category.java:203)
at org.apache.log4j.Category.forcedLog(Category.java:388)
at org.apache.log4j.Category.log(Category.java:853)
at org.slf4j.impl.Log4jLoggerAdapter.debug(Log4jLoggerAdapter.java:204)
at
org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:595)
Here's the relevant portions of the class in question (both
from org.quartz.simpl.SimpleThreadPool):
try {
getLog().debug("WorkerThread is shut down.");
} catch(Exception e) {
// ignore to help with a tomcat glitch
}
And part of the shutdown code - lots of hard-coded wait times:
public void shutdown(boolean waitForJobsToComplete) {
synchronized (nextRunnableLock) {
isShutdown = true;
if(workers == null) // case where the pool wasn't even initialize()ed
return;
// signal each worker thread to shut down
Iterator workerThreads = workers.iterator();
while(workerThreads.hasNext()) {
WorkerThread wt = (WorkerThread) workerThreads.next();
wt.shutdown();
availWorkers.remove(wt);
}
// Give waiting (wait(1000)) worker threads a chance to shut down.
// Active worker threads will shut down after finishing their
// current job.
nextRunnableLock.notifyAll();
if (waitForJobsToComplete == true) {
// wait for hand-off in runInThread to complete...
while(handoffPending) {
try { nextRunnableLock.wait(100); } catch(Throwable t) {}
}
// Wait until all worker threads are shut down
while (busyWorkers.size() > 0) {
WorkerThread wt = (WorkerThread) busyWorkers.getFirst();
try {
getLog().debug(
"Waiting for thread " + wt.getName()
+ " to shut down");
// note: with waiting infinite time the
// application may appear to 'hang'.
nextRunnableLock.wait(2000);
} catch (InterruptedException ex) {
}
}
getLog().debug("shutdown complete");
}
}
}
Looking at the above code, there's a wait of 2.1 seconds per thread?
If that's the case, then the 3 threads will take up to 6.3 seconds
while waiting.
What's odd is that I don't see the entry: "Waiting for thread " name "
to shut down" in any of the logs.
Here's some admittedly ugly code I put together:
The listener:
package org.mdeggers.qschedule.utils;
import java.io.IOException;
import java.io.InputStream;
import java.util.Date;
import java.util.Properties;
import javax.servlet.ServletContextEvent;
import javax.servlet.ServletContextListener;
import org.apache.log4j.Logger;
import org.quartz.JobDetail;
import org.quartz.Scheduler;
import org.quartz.SchedulerException;
import org.quartz.SchedulerFactory;
import org.quartz.Trigger;
import org.quartz.TriggerUtils;
import org.quartz.impl.StdSchedulerFactory;
/**
* Web application lifecycle listener.
* @author mdeggers
*/
public class DIYCronListener implements ServletContextListener {
private static final Logger log = Logger.getLogger(DIYCronListener.class);
private SchedulerFactory schedFactory = null;
private Scheduler scheduler = null;
@Override
public void contextInitialized(ServletContextEvent sce) {
int schedInterval =
Integer.parseInt(sce.getServletContext().getInitParameter("quartz:schedule-interval"));
String propsFile =
sce.getServletContext().getInitParameter("quartz:config-file");
Properties props = new Properties();
// loading properties file
InputStream in =
this.getClass().getClassLoader().getResourceAsStream(propsFile);
try {
props.load(in);
} catch (IOException ex) {
log.fatal("Failed to load properties file: ", ex);
}
try {
in.close();
} catch (IOException ex) {
log.fatal("Failed to close properties file: ", ex);
}
// creating the scheduler factory
try {
schedFactory = new StdSchedulerFactory(props);
log.info("Got scheduler factory with the appropriate properties");
// getting the scheduler
try {
scheduler = schedFactory.getScheduler();
log.info("Got scheduler from schedule factory");
} catch (SchedulerException ex) {
log.fatal("Failed to get a scheduler: ", ex);
}
} catch (SchedulerException ex) {
log.fatal("Failed to get a scheduler factory: ", ex);
}
// creating the job - yep, hardcoded
String jobName = "LogJob";
JobDetail jobDetail = new JobDetail(jobName, DumbJob.class);
// creating the trigger
Trigger trigger = TriggerUtils.makeSecondlyTrigger(schedInterval);
trigger.setStartTime(new Date());
trigger.setName(jobName);
// now try to start the scheduler and add the job
if (scheduler != null) {
try {
scheduler.start();
log.info("Scheduler started");
// try to add the job
try {
Date jobDate = scheduler.scheduleJob(jobDetail, trigger);
log.info("Job started: " + jobName + " on " +
jobDate.toString());
} catch (SchedulerException ex) {
log.fatal("Failed to add job: ", ex);
}
} catch (SchedulerException ex) {
log.fatal("Failed to start scheduler", ex);
}
}
log.info("I have started.");
}
@Override
public void contextDestroyed(ServletContextEvent sce) {
boolean qWait =
Boolean.parseBoolean(sce.getServletContext().getInitParameter("quartz:shutdown-wait"));
try {
if (scheduler.isStarted()) {
try {
scheduler.shutdown(qWait);
log.info("Shutting down scheduler");
} catch (SchedulerException ex) {
log.fatal("Failed to shut down scheduler: ", ex);
}
} else {
log.info("Scheduler returns not started");
}
} catch (SchedulerException ex) {
log.fatal("Could not determine if scheduler was started", ex);
}
}
}
The job:
package org.mdeggers.qschedule.utils;
import org.apache.log4j.Logger;
import org.quartz.Job;
import org.quartz.JobExecutionContext;
import org.quartz.JobExecutionException;
/**
*
* @author mdeggers
*/
public class DumbJob implements Job {
private static final Logger log = Logger.getLogger(DumbJob.class);
public DumbJob() {
}
@Override
public void execute(JobExecutionContext context) throws
JobExecutionException {
log.info("Hello from the Dumb job.");
}
}
The log4j.xml file:
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration PUBLIC 'PUBLIC:-//log4j/log4j Configuration//EN'
'log4j.dtd'>
<log4j:configuration>
<appender name="FA" class="org.apache.log4j.FileAppender">
<param name="File" value="${log4j.home}/qschedule.log"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d %-5p %c.%M:%L - %m%n"/>
</layout>
</appender>
<appender name="QA" class="org.apache.log4j.FileAppender">
<param name="File" value="${log4j.home}/quartz-debug.log"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d %-5p %c.%M:%L - %m%n"/>
</layout>
</appender>
<!-- debug for quartz scheduler - trying to find out where the holdup is -->
<logger name="org.quartz">
<level value="DEBUG"/>
<appender-ref ref="QA"/>
</logger>
<!-- info from my classes -->
<logger name="org.mdeggers">
<level value="INFO"/>
<appender-ref ref="FA"/>
</logger>
</log4j:configuration>
The properties file (quartz.properties)
org.quartz.scheduler.instanceName = SampleScheduler
org.quartz.scheduler.instanceId = 1
org.quartz.scheduler.rmi.export = false
org.quartz.scheduler.rmi.proxy = false
org.quartz.threadPool.class = org.quartz.simpl.SimpleThreadPool
org.quartz.threadPool.threadCount = 3
org.quartz.jobStore.class = org.quartz.simpl.RAMJobStore
org.quartz.scheduler.skipUpdateCheck = true
And the corresponding parts of the web.xml file:
<context-param>
<description>Quartz scheduler configuration file</description>
<param-name>quartz:config-file</param-name>
<param-value>quartz.properties</param-value>
</context-param>
<context-param>
<description>Time in seconds between scheduler executions</description>
<param-name>quartz:schedule-interval</param-name>
<param-value>150</param-value>
</context-param>
<context-param>
<description>Quartz scheduler wait to finish jobs before
shutdown</description>
<param-name>quartz:shutdown-wait</param-name>
<param-value>true</param-value>
</context-param>
<listener>
<description>Do it yourself Quartz Scheduler</description>
<listener-class>org.mdeggers.qschedule.utils.DIYCronListener</listener-class>
</listener>
The log files generated look reasonable.
qschedule.log:
2010-10-18 16:08:01,067 INFO
org.mdeggers.qschedule.utils.DIYCronListener.contextInitialized:50
- Got scheduler factory with the appropriate properties
2010-10-18 16:08:01,289 INFO
org.mdeggers.qschedule.utils.DIYCronListener.contextInitialized:54
- Got scheduler from schedule factory
2010-10-18 16:08:01,308 INFO
org.mdeggers.qschedule.utils.DIYCronListener.contextInitialized:75
- Scheduler started
2010-10-18 16:08:01,335 INFO
org.mdeggers.qschedule.utils.DIYCronListener.contextInitialized:79
- Job started: LogJob on Mon Oct 18 16:08:01 PDT 2010
2010-10-18 16:08:01,336 INFO
org.mdeggers.qschedule.utils.DIYCronListener.contextInitialized:87
- I have started.
2010-10-18 16:08:01,394 INFO
org.mdeggers.qschedule.utils.DumbJob.execute:25
- Hello from the Dumb job.
2010-10-18 16:10:31,309 INFO
org.mdeggers.qschedule.utils.DumbJob.execute:25
- Hello from the Dumb job.
2010-10-18 16:12:38,494 INFO
org.mdeggers.qschedule.utils.DIYCronListener.contextDestroyed:97
- Shutting down scheduler
quartz-debug.log:
2010-10-18 16:08:01,276 INFO
org.quartz.core.SchedulerSignalerImpl.<init>:60 - Initialized
Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
2010-10-18 16:08:01,277 INFO
org.quartz.core.QuartzScheduler.<init>:219 - Quartz Scheduler v.1.8.3 created.
2010-10-18 16:08:01,281 INFO org.quartz.simpl.RAMJobStore.initialize:139 -
RAMJobStore initialized.
2010-10-18 16:08:01,284 INFO
org.quartz.core.QuartzScheduler.initialize:241 - Scheduler meta-data:
Quartz Scheduler (v1.8.3) 'SampleScheduler' with instanceId '1'
Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
NOT STARTED.
Currently in standby mode.
Number of jobs executed: 0
Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 3 threads.
Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support
persistence.
and is not clustered.
2010-10-18 16:08:01,286 INFO
org.quartz.impl.StdSchedulerFactory.instantiate:1275 - Quartz
scheduler 'SampleScheduler' initialized from an externally provided
properties instance.
2010-10-18 16:08:01,288 INFO
org.quartz.impl.StdSchedulerFactory.instantiate:1279 - Quartz
scheduler version: 1.8.3
2010-10-18 16:08:01,306 INFO org.quartz.core.QuartzScheduler.start:497
- Scheduler SampleScheduler_$_1 started.
2010-10-18 16:08:01,346 DEBUG
org.quartz.simpl.SimpleJobFactory.newJob:50 - Producing instance of
Job 'DEFAULT.LogJob', class=org.mdeggers.qschedule.utils.DumbJob
2010-10-18 16:08:01,394 DEBUG org.quartz.core.JobRunShell.run:215 -
Calling execute on job DEFAULT.LogJob
2010-10-18 16:10:31,306 DEBUG
org.quartz.simpl.SimpleJobFactory.newJob:50 - Producing instance of
Job 'DEFAULT.LogJob', class=org.mdeggers.qschedule.utils.DumbJob
2010-10-18 16:10:31,307 DEBUG org.quartz.core.JobRunShell.run:215 -
Calling execute on job DEFAULT.LogJob
2010-10-18 16:12:38,487 INFO
org.quartz.core.QuartzScheduler.shutdown:613 - Scheduler
SampleScheduler_$_1 shutting down.
2010-10-18 16:12:38,491 INFO
org.quartz.core.QuartzScheduler.standby:534 - Scheduler
SampleScheduler_$_1 paused.
2010-10-18 16:12:38,492 DEBUG
org.quartz.simpl.SimpleThreadPool.shutdown:366 - shutdown complete
2010-10-18 16:12:38,493 INFO
org.quartz.core.QuartzScheduler.shutdown:683 - Scheduler
SampleScheduler_$_1 shutdown complete.
. . . just my two cents
/mde/
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
