Zeit läuft rückwärts

[magomi]

Hallo allerseits,

das Umfeld: ich move gerade für einen Serverumzug mehrere Java-Applikationen von physischen Servern auf VMWare-Partitionen. Auf den Partitionen läuft ein RedHat Enterprise Linux 4. Gehostet wird auf einem ESX-Server.

In den Java-Applikationen wird fürs Performance-Monitoring relativ oft mit System.currentTimeMillis() die Systemzeit geholt. Danach werden die Zeiten verglichen und die Differenz als Ablaufzeit für einen speziellen Codeabschnitt irgendwo ausgegeben. Naturgemäß muss diese immer größer 0 oder max. (bei hinreichend kurzer Zeit zwischen den beiden Abfragen) gleich 0 sein. Wir haben aber nun den Fall, dass bei Aufrufen kurz hintereinander der zweite Aufruf einen Zeitstempel liefert, der vor (!) dem Zeitstempel des ersten Aufrufs liegt. Danach fliegt uns die Applikation um die Ohren.

Ich habe das Phänomen mit verschiedenen JDK-Versionen getestet (1.4.2_09, 1.4.2_13, 1.5.0_10). Es tritt auf den VMWare-Partitionen immer auf. Auf physischen Servern ist das nicht zu beobachten.

Deshalb meine Frage in die Runde ob jemand so ein hässliches Phänomen schonmal beobachtet hat und mir gegebenenfalls mit einem Tipp zur Eliminierung dieses Problems helfen kann.

Viele Dank schonmal, Marco

edit: JDK-Versionen berichtigt

 

[Wildcard]

Durchaus möglich das es sich um einen Bug handelt.
Auch zB die WinXP API ist verbuggt, was dazu führt das zu häufiges Aufrufen von System.currentTimeMillis() die Systemzeit verstellt.
Lässt sich das mit System.nanoTime() reproduzieren?

 

[magomi]

Lässt sich das mit System.nanoTime() reproduzieren?

Ja.

Habs gerade mal mit 'nem 1.5.0_10er JDK getestet. Hier mal der "Versuchsaufbau":

long startNS = System.nanoTime();
long start = System.currentTimeMillis();
while (true) {
     long currentNS = System.nanoTime();
     long current = System.currentTimeMillis();
     if (currentNS < startNS) {
         System.out.println(
                "======== " + (new Date()) + " =========\n" +
                "\tstartNS:   " + startNS + "\n" +
                "\tstart:     " + start + "\n" +
                "\t---------------------------------------------\n" +
                "\tcurrentNS: " + currentNS + "\n" +
                "\tcurrent:   " + current + "\n" +
                "===========================================");
    }
    start = System.currentTimeMillis();
    startNS = System.nanoTime();
}

Das Ergebnis ist eine unendliche Liste von Ausgaben folgender Art:

======== Sun May 13 15:32:53 MEST 2007 =========
        startNS:   1179063173330874000
        start:     1179063173330
        ---------------------------------------------
        currentNS: 1179063173330093000
        current:   1179063173330
===========================================

Ich hoffe nicht, dass das ein Bug im JDK ist. Denn wir haben keinerlei Möglichkeit an dem vorgegebenen Setup (RHEL auf VMWare und JDK 1.4.2) zu drehen. Und auf den Quellcode der Applikation (zumindest auf die Teile die da krachen) fehlt uns auch der Zugriff. Mist elender ;-)

Viele Grüße, Marco

 

[Wildcard]

Nein, ich sehe den Bug eher auf seiten von VM-Ware.
Schließlich wird die API des Betriebssystems verwendet, welche wiederrum den CPU Takt verwendet.
Die Kommunikation mit der CPU läuft über VMWare, also würde ich das Problem dort vermuten.