Delay in the Finally block after try block completion

I am trying to run the below concurrency code:

import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.TimeUnit;

public class TestThread {

public static void main(final String[] arguments) throws 
InterruptedException {
  ExecutorService executor = Executors.newSingleThreadExecutor();

  try {
     executor.submit(new Task());
     System.out.println("Shutdown executor");
     executor.shutdown();
     executor.awaitTermination(5, TimeUnit.SECONDS);
  } catch (InterruptedException e) {
     System.err.println("tasks interrupted");
  } finally {

     if (!executor.isTerminated()) {
        System.err.println("cancel non-finished tasks");
     }
     executor.shutdownNow();
     System.out.println("shutdown finished");
  }
 }

static class Task implements Runnable {

  public void run() {

     try {
        int duration = 6;
        System.out.println("Running Task!");
        TimeUnit.SECONDS.sleep(duration);
     } catch (InterruptedException e) {
        e.printStackTrace();
     }
  }
  }     
}

and the output is :

Shutdown executor
Running Task!
shutdown finished
cancel non-finished tasks
java.lang.InterruptedException: sleep interrupted

According to the output it seems finally block is skipped and code after the finally block is executed first and later the finally block is executed. Doesn't this contradict the normal flow of the code which is finally gets executed after the try/catch block is complete?

EDIT : Tried

System.out.flush();
System.err.flush();

after every print as per one of the suggestions but still the same output.

EDIT:

I am using an online Compiler.

1 answer

  • answered 2018-01-13 17:42 davidxxx

    I suppose that you expect that these two traces be reversed as these are declared in the reverse order :

    shutdown finished

    cancel non-finished tasks

    I think that the issue comes from the mixing of System.err and System.out.
    These are not the same streams. So both their flushing and their displaying may be performed at distinct times.

    According to the application/system that displays the output (IDE, OS command line, online compiler/executor), at least 2 things may create an ordering issue :

    • the autoflush of these streams may be or not enabled
    • the displaying order of traces may not be synchronized between these two streams in the "output/console" of the application/system.

    As workaround to display outputs according to the timeline :

    • flush the streams (System.out.flush() and System.err.flush()) after each print() invocation.
      It may work but no guarantee as the application/system that writes the output may not synchronize the displaying of these two streams through the timeline.

    • endeavor to use only System.out and use System.err only for error situations where the program will exit. It will reduce interleave possibilities.

    • if the last idea is not suitable because it matters to distinguish clearly the two kinds of output, use a logging library (Logback or Log4j2 preferably with SLF4J in facade) that allows to trace information with precision (date, time, severity level, ...) and to read them in the actual order of the program flow timeline.


    Here is the same code that uses only System.out :
    I added //1, //2,... comment for the expected order of the output.

    public class TestThread {
    
        public static void main(final String[] arguments) throws InterruptedException {
            ExecutorService executor = Executors.newSingleThreadExecutor();
    
            try {
                executor.submit(new Task());
                System.out.println("Shutdown executor"); // 1
                executor.shutdown();
                executor.awaitTermination(5, TimeUnit.SECONDS);
            } catch (InterruptedException e) {
                System.out.println("tasks interrupted"); // not invoked because caught in Task.run()
            } finally {
    
                if (!executor.isTerminated()) {
                    System.out.println("cancel non-finished tasks"); // 3
                }
                executor.shutdownNow();
                System.out.println("shutdown finished"); // 4
            }
        }
    
        static class Task implements Runnable {
    
            public void run() {
    
                try {
                    int duration = 6;
                    System.out.println("Running Task!");  // 2
                    TimeUnit.SECONDS.sleep(duration);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }
        }
    }
    

    The output is now as expected and it should be the same wherever the program is run : command line, IDE, ...

    Shutdown executor

    Running Task!

    cancel non-finished tasks

    shutdown finished

    java.lang.InterruptedException: sleep interrupted

    Note that :

    java.lang.InterruptedException: sleep interrupted

    may still differ in the order as it is written by Throwable.printStackTrace() that relies on system.err.