JVM issue: concurrency is affected by changing the date of the system! [part 2]

Based on a lot of questions I received in various mailing lists related to the previous post and in order to make the issue simpler and clearer I decided to go back to a binary deliverable (code) that shows the problem, hope this helps!

This is my PreciousPool class, that handles Precious resources:

import java.text.SimpleDateFormat;
import java.util.ArrayList;
import java.util.Date;
import java.util.List;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.locks.Condition;
import java.util.concurrent.locks.Lock;
import java.util.concurrent.locks.ReentrantLock;

public class PreciousPool {

    public static class Precious {
        private final int id;

        private Precious() {
            this.id = 100+(int)(Math.random()*900.0);
        }

        public String toString() {
            return "Precious n."+id;
        }
    }

    private final Lock lock;
    private final Condition ready;
    private final long timeoutInMillis;

    private final List preciousLended;
    private final List preciousAvailable;

    public PreciousPool(int size, long timeoutInSeconds) {
        this.lock = new ReentrantLock();
        this.ready = lock.newCondition();

        this.timeoutInMillis = 1000L*timeoutInSeconds;
        this.preciousLended =  new ArrayList();
        this.preciousAvailable = new ArrayList();

        for (int i = 0; i < size; i++) {
            preciousAvailable.add(new Precious());
        }
    }

    public Precious obtain()  {
        lock.lock();
        try {
            // if no precious are available we wait for the specified timeout (releasing the lock so that others can try)
            if (preciousAvailable.size() == 0) {
                try {
                    ready.await(timeoutInMillis, TimeUnit.MILLISECONDS);
                } catch (InterruptedException e) {
                    Thread.currentThread().interrupt();
                    throw new RuntimeException("Somebody interrupted me!", e);
                }
            }

            // if a precious is available we unload it and return to the caller, otherwise null
            if (preciousAvailable.size() > 0) {
                Precious value = preciousAvailable.remove(0);
                preciousLended.add(value);
                return value;
            } else {
                return null;
            }
        } finally {
            lock.unlock();
        }
    }

    public void release(Precious value) {
        lock.lock();
        try {
            if (!preciousLended.remove(value))
                throw new RuntimeException("Element "+value+" was not lended!");

            // if a precious is returned we put it back and signal to anybody waiting
            preciousAvailable.add(value);
            ready.signalAll();
        } finally {
            lock.unlock();
        }
    }

    public static void main(String args[]) {
        final int size = 3;
        final PreciousPool pool = new PreciousPool(size, 5);

        // let's exhaust the pool
        for (int i=0; i<size; i++)
            dump(pool.obtain());

        // and as we are stubborn we continuosly ask for a new one
        while(true) {
            dump(pool.obtain());
        }
    }

    private static void dump(Precious precious) {
        if (precious == null)
            log("I did not get my precious :(");
        else
            log("I did get my precious! "+precious);
    }

    private static void log(String message) {
        final String now = new SimpleDateFormat("HH:mm:ss:SSSS ").format(new Date());
        System.out.println(now + message);
    }
}

So, the main is a single thread (no need for multithreading here, let’s keep it simple), that first exhaust the whole pool and then keep asking, without success, for a resource. Stubborn guy, I say, but it happens. If you run this program everything works as expected: you are greeted by a three successful Precious and then an endless list of failures, that it continuously grow. All good 🙂

02:34:40:0061 I did get my precious! Precious n.156
02:34:40:0062 I did get my precious! Precious n.991
02:34:40:0062 I did get my precious! Precious n.953
02:34:45:0064 I did not get my precious!
02:34:50:0065 I did not get my precious!
02:34:55:0066 I did not get my precious!
02:35:00:0067 I did not get my precious!
02:35:05:0068 I did not get my precious!
[...]

But guess what happens when, while the program is running, I change the date of my system back of one hour? Everything stops, it’s simple as that. No prints, nothing, zero, nada. Now, If it wasn’t so late, I would probably wait one hour in order to have my program restored to his normal process, but as a customer I won’t be terribly happy 🙂

See also
The full saga, all the articles I published on the matter:

Advertisements

9 thoughts on “JVM issue: concurrency is affected by changing the date of the system! [part 2]

  1. Pingback: JVM issue: concurrency is affected by changing the date of the system! | It can't rain forever...
  2. This isn’t particularly remarkable when you look at the implementation of await(long, TimeUnit) in java.util.concurrent.locks.AbstractQueuedSynchronizer.

    The simplified version of the loop it has there (with some arbitrary values for discussion):

    long nanosTimeout = 5_000_000 // 5 seconds
    long lastTime = System.nanoTime(); // 1_000_000
    while (true) {
    if (nanosTimeout <= 0L) { // A
    break;
    }
    long now = System.nanoTime(); // B
    nanosTimeout -= now – lastTime; // C
    lastTime = now; // D
    }

    Now if we step through what's happening here:

    // Loop 1
    // A = 5_000_000 <= 0L = false
    // B = now = 1_001_000
    // C = nanosTimeout = 5_000_000 – (1_001_000 – 1_000_000) = 4_999_000
    // D = lastTime = 1_001_000

    // Loop 2
    // A = 4_999_000 <= 0L = false
    // B = now = 1_002_000
    // C = nanosTimeout = 4_999_000 – (1_002_000 – 1_001_000) = 4_998_000
    // D = lastTime = 1_002_000

    // Set current time (eg System.nanoTime()) = 100_000

    // Loop 3
    // A = 4_998_000 < 0 = false
    // B = now = 101_000
    // C = nanosTimeout = 4_998_000 – (101_000 – 1_002_000) = 5_899_000
    // D = lastTime = 101_000

    // Loop 4
    // A = 5_899_000 <= 0L = false
    // B = now = 102_000
    // C = nanosTimeout = 5_899_000 – (102_000 – 101_000) = 5_888_000
    // D = lastTime = 102_000

    You can see that when the time is set between loop 2 and 3, the timeout value jumps back up in accordance with the clock shift.

    What is worthy of remark here is that the javadoc and method signatures of await(long, TimeUnit) behaves as you'd probably expect await(Date) to – that is, the implementation effectively waits until now+timeout has elapsed, as opposed to N time units have passed (eg a per-TimeUnit countdown which should be relatively safe to clock shifts).

    • Well, as bad as it looks, it’s the correct way to implement a wait following the specs. If you red in fact on the the documentation you will notice that all the wait() function family can return spuriously: in that situation you will have to take in account the elapsed time fully execute the wait.

      It all goes down, however, to the implementation of System.nanoTime(), that should be independent from the wall clock. And it’s not 🙂

  3. This isn’t particularly remarkable – NTP goes through great pains (giving up eventually) to SLOW DOWN your clock to move it backwards.

    If you’re forcibly changing your clock backwards without a restart as a habit, you’re eventually going to destroy something (like apparently the JVM) that depends on clocks moving forwards, always.

    As an example, this’ll break Oracle RAC, badly. Or apache logs will slow 0 or negative times for completing requests.

    Etc.

    • We do not have the luxury of controlling the installation on customer premises, and this problem is caused by a bad design in the implementation (see my next article for a deeper insight, available soon). Also, this behaviour is not acceptable by a platform like the JVM: remember, the JVM is affected by this issue, so we are talking not only about Java but also any other language that runs on the VM (think about Scala, Python, Ruby).
      Would you accept such behavior from your OS? I do not think so.

  4. Pingback: JVM issue: concurrency is affected by changing the date of the system! [part 3] | It can't rain forever...
  5. Pingback: Ziemliches fettes Java-Problem…. - Java Blog | Javainsel-Blog
  6. Pingback: JVM issue: concurrency is affected by changing the date of the system! [part 4] | It can't rain forever...
  7. Pingback: JVM issue: concurrency is affected by changing the date of the system! [part 2] | Ragnarok Connection

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s