javamultithreadingthreadpoolexecutorjstack

Thread dump show state of thread always TIMED_WAITING


I have created a program in which it is using Executor framework. I have created a single thread which is scheduled periodically.

Here is the complete source code of the same:

package com.example;
import java.security.SecureRandom;
import java.util.Date;
import java.util.concurrent.Executors;
import java.util.concurrent.ScheduledExecutorService;
import java.util.concurrent.TimeUnit;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class ExecutorFrameworkDemo {

    private static final Logger LOGGER = LoggerFactory.getLogger(ExecutorFrameworkDemo.class);

    static {
        long refresh = 120000;
        long initialDelay = 120000;
        ScheduledExecutorService scheduledThreadPool = null;
        SecureRandom sr = new SecureRandom();
        scheduledThreadPool = Executors.newSingleThreadScheduledExecutor((Runnable run) -> {
        Thread t = Executors.defaultThreadFactory().newThread(run);
        t.setDaemon(true);
        t.setName("Demo-pool");
        t.setUncaughtExceptionHandler(
                (thread, e) -> LOGGER.error("Uncaught exception for Demo-pool thread " + thread.getName(), e));
        return t;
    });

    scheduledThreadPool.scheduleAtFixedRate(() -> {
        System.out.println("Executing thread " + Thread.currentThread().toString() + "at" + new Date());

    }, initialDelay + sr.nextInt((int) refresh / 4), refresh + sr.nextInt((int) refresh / 4),
            TimeUnit.MILLISECONDS);
    }
    public static void main(String[] args) throws InterruptedException {
        System.out.println("Inside main thread");
        Thread.sleep(50000000);
        System.out.println("Inside main thread, after main's Sleep delay");
    }
}

It creates a single thread which runs in a fixed Schedule; in fact I do see the output , after every 2 mins + few seconds.

At the same time I took Thread dump continuously, with the hope that at one point-in-time the thread state would be RUNNABLE, however it is always giving me TIMED_WAITED.

Below is actual Thread dump for the same:


"Demo-pool" #12 daemon prio=5 os_prio=31 tid=0x00007f96f3230000 nid=0x5603 waiting on condition [0x0000700007752000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000007976182f0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748) 

Is it matter of chance I am not able to see the RUNNABLE state?

I am taking thread dumps using jstack, using a shell-script , in an infinite loop, as below:

Script to take Thread-dump:

#!/bin/bash
itr=0
while true
  do
     (( ++itr ))
      jstack $1 > jstack_Iteration_${itr}
  done

where, $1 is the PID of the java process, passed as command argument.


Solution

  • To see a thread in RUNNABLE would mean, that you do the dump in the exact microsecond where it does the System.out.println. That's unlikely as hell. Do a more time consuming implementation of your Runnable e.g. a busy wait in form of a loop:

    for (int i = 0; i < 10000000; i++) {
        // do nothing
    }
    

    Don't do a Thread.sleep or wait, otherwise you'd end up in another state than RUNNABLE.