24

We are using the ScheduledExecutorService.scheduleAtFixedRate to perform an I/O Task every 100 ms. (The actual I/O Operation is performed by a third party library and we don't know exactly what is happening inside.)

Sometimes keeping up with the 100 ms intervals has some issues and we fall back to 500 ms. Since it is I/O, we weren't surprised, but we observed a strange behavior:

If a specific Thread runs, we are matching the 100 ms. If this thread is not running, we are falling back to 500 ms.

That specific Threads' run-method looks like this:

while(active){
  try {
    Thread.sleep(delay);
  } catch (InterruptedException e) {
    Thread.currentThread().interrupt();
    break;
  }
//some more stuff
}

Basically, when we use a short delay like 5 ms we get a better performance within the library. When we use longer delays like 1000 ms, performance is significantly worse.

It also seems to be platform-specific since we were not able to reproduce the problem (Java 8, Windows 10).

All that we know is that it's definitely the short sleep()-call causing the improvement since we could fix the issue by running a dummy thread just sleeping in short intervals.

Any explanation would be helpful to understand what is happening :-)

--- edit

Even more interesting: if we are adding not one but two new Threads only for short sleep intervals, it adds a little bit of performance. Not as significant as the first thread, but still like 20%.

--- edit 2

The System where we can observe the behavior: Intel Atom E3845 Windows 10

The System where we can't reproduce it: Intel i7-5820K Windows 10

We can't look up the source code but the library seems to run single-threaded (no new threads created) and creates a Socket connection.

Shehan Dhaleesha
  • 627
  • 1
  • 10
  • 30
Bastian
  • 371
  • 1
  • 8
  • 3
    Check [this](https://www.journaldev.com/1020/thread-sleep-java) And you'd better switch into [Timer](https://docs.oracle.com/javase/8/docs/api/java/util/Timer.html) or [Scheduled taks](https://spring.io/guides/gs/scheduling-tasks/) if you are using Spring Framework as soon as you can. There are a lot of disadvantages of using Thread.sleep for example - exceptions like IOException, or OutOfMemory, thread synchronization etc. – Victor Gubin Jun 05 '19 at 10:13
  • Thanks for the article. It writes that "Thread.sleep() interacts with the thread scheduler", maybe this "more active" interaction causes the thread scheduler to prioritize my other thread? But this is a very vague assumption. – Bastian Jun 05 '19 at 10:38
  • If you shure you are going to stop the thread to the really small interval, let's say a few microseconds you'd better use [Thread.yield](https://docs.oracle.com/javase/8/docs/api/java/lang/Thread.html#yield--) instead of sleep, sleep is bad choose for most cases (unless you are not working with some hardware, and you need this sleep to do something with the well known hardware delay) – Victor Gubin Jun 05 '19 at 12:20
  • 1
    Can you go in the code of the 3rd party library and check if it maintains a thread pool for the IO it does? If it does, and if the size or characteristics of it is somehow related to the existing number of Threads of the application, that might be connected to the difference in behavior. – Utku Özdemir Jun 05 '19 at 13:17
  • Another thing: Can you clarify in what kind of environment can you reproduce this problem? Win10/Java8 is where it is reproducible, or where it is not reproducible? Also, giving the number of CPU cores (physical/logical) can be helpful since this might be Thread scheduler/context switch related. – Utku Özdemir Jun 05 '19 at 13:22
  • 17
    Wild guesses, it could be a power saving features on the Atom. The short sleeps might prevent the CPU from switching to a lower power state, while the i7 have higher threshold before switching to low power. Another guess, process schedulers are usually designed to divide programs into two scheduling buckets: interactive programs (short time slices, low latency, optimised for reacting to UI or network generated events quickly) and batch programs (large time slices, higher latency, optimised to do heavy calculations). – Lie Ryan Jun 05 '19 at 14:09
  • Have you tried a profiler ? One quick tweak that comes to mind is using [prestartAllCoreThreads](https://docs.oracle.com/javase/8/docs/api/java/util/concurrent/ThreadPoolExecutor.html#prestartAllCoreThreads--) to improve the first task execution – yohlulz Oct 03 '19 at 06:59
  • "We can't look up the source code but the library seems to run single threaded (no new threads created) and creates a Socket connection.": well if it's in Java you can always try to decompile it. – Jean-François Fabre Jan 14 '20 at 09:28
  • Are there more threads running in your application? As you write yourself, it might be a scheduling issue. It is expensive to impossible to create the perfect schedule during runtime, so you will get a good-enough schedule. I think it is possible that an additional thread leads to a better overall schedule in specific cases. Also, JVM scheduling seems to be [both JVM and OS dependent](https://stackoverflow.com/q/2816011/2448440). Maybe add a [scheduling] tag to your question? – Qw3ry Jan 31 '20 at 10:11

1 Answers1

1

It might be a multi-threading visibility problem (hard to say without knowing the involved source/library).

The example is based on code from thread how-to-demonstrate-java-multithreading-visibility-problems.

Executing the following code will lead in infinite execution of thread t.

public class Test extends Thread {

    boolean keepRunning = true;

    public static void main(String[] args) throws InterruptedException {
        Test t = new Test();
        t.start();
        Thread.sleep(1000);
        t.keepRunning = false;
        System.out.println(System.currentTimeMillis() + ": keepRunning is false");
    }

    public void run() {
        int i = 0;
        while (keepRunning) {
            i++;
        }
        System.out.println("iterations: " + i);
    }
}

Reason is that thread t keeps its own local state of keepRunning and never get the updated state.

If you amend the run method to 

public void run() {
    int i = 0;
    while (keepRunning) {
        i++;
        System.out.println(i);
    }
    System.out.println("iterations: " + i);
}

it finish for example with

...
111955
111956
iterations: 111956
1582797899956: keepRunning is false

Q: How does this additional println statement change the behavior? A: System.out is a PrintStream and the println method is implemented as

public void println(boolean x) {
    synchronized (this) {
        print(x);
        newLine();
    }
}

The synchronized block lead to synchronization between the thread-local state and main memory.

Similar effect happen when you use a Thread.sleep(delay) instead.

public void run() {
    int i = 0;
    while (keepRunning) {
        i++;
        try {
            Thread.sleep(5);
        } catch(InterruptedException e) {
            System.out.println("interrupted");
            Thread.currentThread().interrupt();
        }
    }
    System.out.println("iterations: " + i);
}

example output

1582798987660: keepRunning is false
iterations: 197

You might try to replace the Thread.sleep(delay) by a System.out.println() statement to see if this would have a similar effect. Then it's most probably related to the above example.

edit To enforce that thread t gets the updated state the variable keepRunning can be declared as volatile.

public class Test extends Thread {

volatile boolean keepRunning = true;

public static void main(String[] args) throws InterruptedException {
    Test t = new Test();
    t.start();
    Thread.sleep(1000);
    t.keepRunning = false;
    System.out.println(System.currentTimeMillis() + ": keepRunning is false");
}

public void run() {
    int i = 0;
    while (keepRunning) {
        i++;
    }
    System.out.println("iterations: " + i);
}

}

example output

iterations: 1726941412
1582799612746: keepRunning is false
SubOptimal
  • 22,518
  • 3
  • 53
  • 69