title: Thread dies inexplicably
body: <p>I have a Java process that has recently started using up 100% CPU time. Using <code>jdb</code> I discovered this was caused by a <code>ThreadPoolExecutor</code> repeatedly creating threads.</p>
  
  <p>The executor in question is defined as:</p>
  
  <pre><code>private final ScheduledExecutorService _scheduler = Executors.newScheduledThreadPool(0, new NamedThreadFactory("OrderServiceScheduler", true, null));
  </code></pre>
  
  <p>The only task scheduled is:</p>
  
  <pre><code>_scheduler.scheduleAtFixedRate(new Runnable() { @Override public void run() {  s_log.info("Resetting order books"); _liveOrderBook.clear(); } }, 
                                 midnightTodayInMs, 
                                 TimeUnit.MILLISECONDS.convert(1, TimeUnit.DAYS), 
                                 TimeUnit.MILLISECONDS);
  </code></pre>
  
  <p>The log statement never gets printed (I'm 99% sure that <code>INFO</code> level logging is enabled for this logger).</p>
  
  <p>I first ran <code>trace go methods</code> in jdb and saw a lot lines like:</p>
  
  <pre><code>Method entered: "thread=OrderServiceScheduler-thread-22237794", com.kbcfp.util.NamedThreadFactory.newThread(), line=45 bci=0
  Method entered: "thread=OrderServiceScheduler-thread-22237794", org.apache.log4j.helpers.ThreadLocalMap.childValue(), line=34 bci=0
  Method exited: return value = null, "thread=OrderServiceScheduler-thread-22237794", org.apache.log4j.helpers.ThreadLocalMap.childValue(), line=38 bci=15
  Method exited: return value = instance of java.lang.Thread(name='OrderServiceScheduler-thread-22237795', id=6388), "thread=OrderServiceScheduler-thread-22237794", com.kbcfp.util.NamedThreadFactory.newThread(), line=52 bci=68
  </code></pre>
  
  <p>So I set a breakpoint in <code>org.apache.log4j.helpers.ThreadLocalMap.childValue</code> and kept proceeding until the thread stops executing unexpectedly (immediately after the last <code>next, thread</code>OrderServiceScheduler-thread-151389734<code>isn't listed in the output of</code>threads`):</p>
  
  <pre><code>&gt; stop in org.apache.log4j.helpers.ThreadLocalMap.childValue
  Set breakpoint org.apache.log4j.helpers.ThreadLocalMap.childValue
  &gt;
  Breakpoint hit: "thread=OrderServiceScheduler-thread-151389734", org.apache.log4j.helpers.ThreadLocalMap.childValue(), line=34 bci=0
  
  OrderServiceScheduler-thread-151389734[1] clear org.apache.log4j.helpers.ThreadLocalMap.childValue
  Removed: breakpoint org.apache.log4j.helpers.ThreadLocalMap.childValue
  OrderServiceScheduler-thread-151389734[1] where
    [1] org.apache.log4j.helpers.ThreadLocalMap.childValue (ThreadLocalMap.java:34)
    [2] java.lang.ThreadLocal$ThreadLocalMap.&lt;init&gt; (ThreadLocal.java:353)
    [3] java.lang.ThreadLocal$ThreadLocalMap.&lt;init&gt; (ThreadLocal.java:261)
    [4] java.lang.ThreadLocal.createInheritedMap (ThreadLocal.java:236)
    [5] java.lang.Thread.init (Thread.java:401)
    [6] java.lang.Thread.&lt;init&gt; (Thread.java:652)
    [7] com.kbcfp.util.NamedThreadFactory.newThread (NamedThreadFactory.java:45)
    [8] java.util.concurrent.ThreadPoolExecutor$Worker.&lt;init&gt; (ThreadPoolExecutor.java:598)
    [9] java.util.concurrent.ThreadPoolExecutor.addWorker (ThreadPoolExecutor.java:913)
    [10] java.util.concurrent.ThreadPoolExecutor.processWorkerExit (ThreadPoolExecutor.java:992)
    [11] java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1,128)
    [12] java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:603)
    [13] java.lang.Thread.run (Thread.java:722)
  OrderServiceScheduler-thread-151389734[1] next
  &gt;
  Step completed: "thread=OrderServiceScheduler-thread-151389734", org.apache.log4j.helpers.ThreadLocalMap.childValue(), line=35 bci=5
  
  OrderServiceScheduler-thread-151389734[1] next
  &gt;
  Step completed: "thread=OrderServiceScheduler-thread-151389734", org.apache.log4j.helpers.ThreadLocalMap.childValue(), line=38 bci=14
  
  OrderServiceScheduler-thread-151389734[1] next
  &gt;
  Step completed: "thread=OrderServiceScheduler-thread-151389734", com.kbcfp.util.NamedThreadFactory.newThread(), line=45 bci=40
  
  OrderServiceScheduler-thread-151389734[1] next
  &gt;
  Step completed: "thread=OrderServiceScheduler-thread-151389734", com.kbcfp.util.NamedThreadFactory.newThread(), line=48 bci=41
  
  OrderServiceScheduler-thread-151389734[1] next
  &gt;
  Step completed: "thread=OrderServiceScheduler-thread-151389734", com.kbcfp.util.NamedThreadFactory.newThread(), line=49 bci=49
  
  OrderServiceScheduler-thread-151389734[1] next
  &gt;
  Step completed: "thread=OrderServiceScheduler-thread-151389734", com.kbcfp.util.NamedThreadFactory.newThread(), line=52 bci=67
  
  OrderServiceScheduler-thread-151389734[1] next
  &gt;
  </code></pre>
  
  <p>Our <code>NamedThreadFactory</code> class isn't doing anything exciting:</p>
  
  <pre><code>  44: public Thread newThread(Runnable r) {
    45:   Thread t = new Thread(_group, r,
    46:       _namePrefix + _threadNumber.getAndIncrement(),
    47:       0);
    48:   t.setDaemon(_makeDaemon);
    49:   if(_overridePriority != null) {
    50:     t.setPriority(_overridePriority);
    51:   }
    52:   return t;
    53: }
  </code></pre>
  
  <p>As far as I can tell, the next line of execution should be 914 of <code>ThreadPoolExecutor</code>, but the thread dies instead.  Why?</p>
  
  <p>For reference, this is running on JDK 1.7.0_07, on a Solaris x86 host.  </p>
  
  <p>The only change I've made is the addition of ActiveMQ's client library.  My suspicion is that this has something to do with the addition of slf4j (specifically <code>slf4j-api-1.6.6.jar</code>, and <code>slf4j-log4j12-1.6.6.jar</code>) to the classpath, but I can't prove this.</p>
  
  <p><strong>UPDATE</strong></p>
  
  <p>I've changed the executed task to be a separate class:</p>
  
  <pre><code>public class TestingFoo implements Runnable 
  {
    private final Logger s_log;
  
    public TestingFoo(final Logger log)
    {
      s_log = log;
    }
  
    @Override 
    public void run() 
    {  
      try
      {
        s_log.info("Resetting order books"); 
    //    _liveOrderBook.clear(); 
      }
      catch (final Throwable t)
      {
        t.printStackTrace();
      }
    }
  }
  </code></pre>
  
  <p>I've set a <code>jdb</code> breakpoint at the <code>log.info</code> line and it's not getting hit.  Also, I'm not seeing a stack trace being printed on stderr (or the log4j file). Additionally, I've put another <code>s_log.info</code> line before the task is scheduled and that <em>is</em> printed.</p>
  
  <p>I'm now downloading JDK 1.7.0_21 to see if that makes a difference.</p>
  
  <p><strong>UPDATE 2</strong></p>
  
  <p>This was due to setting the core pool size to zero, as Peter Lawrey touched on his answer.  However, instead of having the effect of causing nothing to run, it caused the <code>ThreadPoolExecutor</code>'s <code>runWorker</code> method to exit immediately.  The gist of the method looks like:</p>
  
  <pre><code>runWorker(Worker) {
      ...
      while (task != null || (task = getTask()) != null) {
        ...
        task.run();
        ...
      }
      processWorkerExit(..);
  }
  </code></pre>
  
  <p>Setting the core pool size causes <code>getTask</code> to return <code>null</code> without blocking for a task to be submitted.  This causes the loop to exit, <code>processWorkerExit</code> then gets called which creates another thread to replace the exiting one.</p>
  
  <p>I believe the issues I saw with the debugger were due to JIT'ed out code.  I put in a <code>Thread.sleep</code> statement into the thread factory to slow down the creation of threads which meant I had time to attach the debugger before any optimisations were applied.</p>
  
  <p>TL;DR: I'm an idiot.</p>
  
  <p><strong>UPDATE 3</strong></p>
  
  <p>For anyone that may come across this in the future... There's another <a href="https://stackoverflow.com/questions/2335702/scheduledthreadpoolexecutor-and-corepoolsize-0">similar question on SO</a> that mentions this behaviour has changed in Java 7.  Prior to the change, having a core size of zero would, as Peter Lawrey suggested, cause no threads to ever get created (<a href="http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=7091003" rel="nofollow noreferrer">bug report</a>).  A <a href="http://hg.openjdk.java.net/jdk8/tl/jdk/rev/8dab38c07b6b" rel="nofollow noreferrer">change</a> was put in to ensure one thread gets created, which appears to have the effect of causing threads to get created repeatedly.  This can be reproduced with code very similar to the test case in the bug report:</p>
  
  <pre><code>import java.util.concurrent.Executors;
  import java.util.concurrent.ScheduledExecutorService;
  import java.util.concurrent.TimeUnit;
  
  class ScheduledExecutorTest {
      public static void main(String[] args) throws InterruptedException {
          final ScheduledExecutorService ex = Executors.newScheduledThreadPool(0);
          ex.scheduleWithFixedDelay(new Runnable() {
              @Override
              public void run() {
                  System.out.println("hello");
              }
          }, 1, 1, TimeUnit.SECONDS);
  
          while (true)
              Thread.sleep(1000);
      }
  }
  </code></pre>