Töten (Joda) Zeit

Eines Tages kommt einer unserer Tester zu uns an den Tisch und sagt uns: "Die Testumgebung (Weblogic Container auf IBM JDK 1.4.2) hängt"... Also beenden wir Weblogic, starten es erneut und lassen den Tester sein Szenario nachspielen. Es gelingt ihm, das hängende Verhalten zu reproduzieren. Also kommen die Java Forces zum Einsatz, um das Problem zu finden. Da das JDK ein 1.4.2 JDK ist, können wir die Java5 jconsole nicht verwenden, um die JVM zu untersuchen. Am einfachsten ist es daher, zunächst einen Stack-Dump zu erstellen, da wir sehen wollen, was die Threads tun. Bei einer sorgfältigen Inspektion der Dump-Datei finden wir zunächst diesen beunruhigenden Schnipsel. 3LKMONOBJECT com.xebia.client.domain.impl.ReleaseRunImpl@189DDCA8/189DDCB0: Flat locked by thread ident 0x23, entry count 1 3LKNOTIFYQ Waiting to be notified: 3LKWAITNOTIFY "ExecuteThread: '9' for queue: 'weblogic.kernel.Default'" (0x6E6AA08) 3LKWAITNOTIFY "ExecuteThread: '21' for queue: 'weblogic.kernel.Default'" (0x69512F0) 3LKWAITNOTIFY "ExecuteThread: '17' for queue: 'weblogic.kernel.Default'" (0x694C0B0) 3LKWAITNOTIFY "ExecuteThread: '5' for queue: 'weblogic.kernel.Default'" (0x6937598) 3LKWAITNOTIFY "ExecuteThread: '6' for queue: 'weblogic.kernel.Default'" (0x6937988) 3LKWAITNOTIFY "ExecuteThread: '18' for queue: 'weblogic.kernel.Default'" (0x694D538) 3LKWAITNOTIFY "ExecuteThread: '10' for queue: 'weblogic.kernel.Default'" (0x69431D0) 3LKWAITNOTIFY "ExecuteThread: '22' for queue: 'weblogic.kernel.Default'" (0x6952788) 3LKWAITNOTIFY "ExecuteThread: '14' for queue: 'weblogic.kernel.Default'" (0x6948318) 3LKWAITNOTIFY "ExecuteThread: '15' for queue: 'weblogic.kernel.Default'" (0x69497A0) 3LKWAITNOTIFY "ExecuteThread: '23' for queue: 'weblogic.kernel.Default'" (0x6953C20) 3LKWAITNOTIFY "ExecuteThread: '19' for queue: 'weblogic.kernel.Default'" (0x694E9C0) 3LKWAITNOTIFY "ExecuteThread: '11' for queue: 'weblogic.kernel.Default'" (0x6944580) 3LKWAITNOTIFY "ExecuteThread: '7' for queue: 'weblogic.kernel.Default'" (0x6E6A1E8) 3LKWAITNOTIFY "ExecuteThread: '8' for queue: 'weblogic.kernel.Default'" (0x6E6A5D8) 3LKWAITNOTIFY "ExecuteThread: '16' for queue: 'weblogic.kernel.Default'" (0x694AC28) 3LKWAITNOTIFY "ExecuteThread: '4' for queue: 'weblogic.kernel.Default'" (0x69371A8) 3LKWAITNOTIFY "ExecuteThread: '20' for queue: 'weblogic.kernel.Default'" (0x694FE58) Eine Menge Threads warten darauf, dass der Thread mit der Kennung 0x23 eine Instanz des ReleaseRunImpl freigibt. Bei der weiteren Untersuchung des Dumps finden wir schnell heraus, welcher Thread dies ist und was er tut: 2LKFLATMON ident 0x23 "ExecuteThread: '24' for queue: 'weblogic.kernel.Default'" (0x69550B8) ee 0x06954EE0 .... 3XMTHREADINFO "ExecuteThread: '24' for queue: 'weblogic.kernel.Default'" (TID:0x101E8930, sys_thread_t:0x69550B8, state:R, native ID:0x114C) prio=5 4XESTACKTRACE at org.joda.time.format.PeriodFormatterBuilder$FieldFormatter.isSupported(PeriodFormatterBuilder.java(Compiled Code)) 4XESTACKTRACE at org.joda.time.format.PeriodFormatterBuilder$FieldFormatter.getFieldValue(PeriodFormatterBuilder.java(Compiled Code)) 4XESTACKTRACE at org.joda.time.format.PeriodFormatterBuilder$FieldFormatter.countFieldsToPrint(PeriodFormatterBuilder.java:1017) 4XESTACKTRACE at org.joda.time.format.PeriodFormatterBuilder$Composite.countFieldsToPrint(PeriodFormatterBuilder.java:1719) 4XESTACKTRACE at org.joda.time.format.PeriodFormatterBuilder$Separator.calculatePrintedLength(PeriodFormatterBuilder.java:1568) 4XESTACKTRACE at org.joda.time.format.PeriodFormatterBuilder$Separator.calculatePrintedLength(PeriodFormatterBuilder.java:1564) 4XESTACKTRACE at org.joda.time.format.PeriodFormatterBuilder$Separator.calculatePrintedLength(PeriodFormatterBuilder.java:1564) 4XESTACKTRACE at org.joda.time.format.PeriodFormatter.print(PeriodFormatter.java:240) 4XESTACKTRACE at com.xebia.client.domain.impl.AbstractRun.formatMillisToStringPeriod(AbstractRun.java:395) Der Thread mit der ID 24 scheint damit beschäftigt zu sein, eine für Menschen lesbare Form von Millisekunden unter Verwendung der joda-time-Bibliothek zu drucken. Wir verwenden bereits die neueste stabile (1.4) Version dieser Bibliothek. Was ist nun zu tun? Warum bleibt der PeriodFormatter bei formatMillisToStringPeriod hängen? Es hängt nicht immer, also könnte es nur bei bestimmten Werten liegen, aber bei welchen Werten dann? Lassen Sie uns einen JUnit-Testfall erstellen, der dem Verhalten von formatMillisToStringPeriod sehr ähnlich ist, damit wir ein paar Werte ausprobieren können.

public class PeriodFormatterTest extends TestCase {
  private PeriodFormatter pf;
  protected void setUp() throws Exception {
  super.setUp();
  pf = new PeriodFormatterBuilder().printZeroAlways().printZeroRarelyFirst().appendWeeks()
  .appendSuffix(" Woche", " weken").appendSeparator(" ").appendDays().appendSuffix(" dag", " dagen").appendSeparator(" ").appendHours()
  .appendSuffix(" uur", " uur").appendSeparator(" ").minimumPrintedDigits(2).printZeroAlways().appendMinutes().appendSuffix(":", ":")
  .appendSeconds().appendSuffix(" minuut", " minuten").toFormatter();
  }
  public void testPeriodFormatter_aPeriod() {
  formatMillisToStringPeriod(4000, "PT4S", "00:04 minuten");
  }
  public void testPeriodFormatter_0Period() {
  formatMillisToStringPeriod(0, "PT0S", "00:00 minuten");
  }
  private void formatMillisToStringPeriod(long periodTime, String toStringExpected, String printExpected) {
  DateTime start = new DateTime();
  Zeitraum p = new Zeitraum(start, start.plus(periodTime));
  assertEquals(toStringExpected, p.toString());
  assertEquals(printExpected, pf.print(p));
  }
}

Die Ausführung dieses Tests in Eclipse zeigt keine Probleme, also versuchen wir den Maven-Build. Und siehe da, plötzlich bleibt Maven bei der Ausführung des 2. Testfalls im JUnit-Test hängen. Als wir eine Prozessauflistung vornehmen, erkennen wir plötzlich unseren Fehler. Der Maven-Build läuft mit demselben IBM JDK 1.4.2, das auch unser Container verwendet, aber Eclipse verwendet sein Standard-Java5-JDK. Wir gehen also zurück und konfigurieren Eclipse neu. Das ist besser, jetzt hängt es auch bei der Ausführung des JUnit-Tests in Eclipse. Und noch etwas fällt uns auf: Die CPU läuft bei 100% Auslastung Amok. Wir müssen uns den Joda-Time-Code ansehen, um herauszufinden, was da schief läuft. Der bestmögliche Kandidat, nach dem wir suchen können, ist eine Endlosschleife, da dies die 100%ige Auslastung der CPU erklären würde. Eine genaue Untersuchung der Methoden, die wir im Stacktrace sehen, führt uns in die Richtung des folgenden Codeschnipsels (aus der Methode FieldFormatter.getFieldValue, Zeilen 1437:1445 von PeriodFormatterBuilder.java):

if (isZero(period) && iFieldFormatters[iFieldType] == this) {
  for (int i = Math.min(iFieldType, 8 ) - 1; i  >= 0; i++) {
  if (isSupported(type, i) && iFieldFormatters[i] != null) {
  return Long.MAX_VALUE;
  }
  }
} sonst {
  return Long.MAX_VALUE;
}

Wir sehen, dass diese Methode eine Schleife mit offenem Ende hat. Das int-Feld iFieldType hat einen Bereich von 0 aufwärts. Das bedeutet, dass die Schleife nur für iFieldType mit dem Wert 0 (sofort) endet. Für jeden anderen Wert von iFieldType wird die Schleife an sich nie enden. Die einzige Möglichkeit, aus dieser Schleife auszubrechen, besteht darin, dass die if-Anweisung den Wert true annimmt. Schauen wir uns an, was isSupported tut, um ein Gefühl dafür zu bekommen, ob dies ein Problem darstellt.

boolean isSupported(PeriodType type, int field) {
  Schalter (Feld) {
  Standard:
  return false;
  Fall YEARS: // 0
  return type.isSupported(DurationFieldType.years());
  Fall MONTHS: // 1
  return type.isSupported(DurationFieldType.months());
  Fall WEEKS: // 2
  return type.isSupported(DurationFieldType.weeks());
  Fall DAYS: // 3
  return type.isSupported(DurationFieldType.days());
  Fall STUNDEN: // 4
  return type.isSupported(DurationFieldType.hours());
  Fall MINUTEN: // 5
  return type.isSupported(DurationFieldType.minutes());
  Fall SECONDS: // 6
  return type.isSupported(DurationFieldType.seconds());
  Fall MILLIS: // 7
  return type.isSupported(DurationFieldType.millis());
  case SECONDS_MILLIS: // durchfallen // 8
  case SECONDS_OPTIONAL_MILLIS: // 9
  return type.isSupported(DurationFieldType.seconds()) ||
  type.isSupported(DurationFieldType.millis());
  }
}

Ok, das Problem wird offensichtlich. Wenn iFieldType aus irgendeinem Grund aus dem Bereich [0,9] herausfällt, wird isSupported immer false zurückgeben, was wiederum bedeuten würde, dass die obige Schleife niemals enden würde. Ok, vielleicht haben wir hier etwas, lassen Sie uns ein paar Haltepunkte setzen, um zu sehen, was schief läuft... Leider scheint das nicht zu funktionieren. Wenn Sie den Code mit einem Debugger durchgehen, wird das Problem irgendwie auf magische Weise behoben und die Tests enden normal, wie wir es eigentlich erwartet hätten. Das wirft ein Problem auf. Wir beschließen, zum Debugging im alten Stil zurückzukehren, d.h. die Protokollierung hinzuzufügen, um das Problem zu erkennen.

for (int i = Math.min(iFieldType, 8 ) - 1; i  >= 0; i++) {
  log.info("Unbegrenzte Schleifenbildung i = " + i + ", und iFieldType = " + iFieldType);
  if (isSupported(type, i) && iFieldFormatters[i] != null) {
  return Long.MAX_VALUE;
  }
}

Nachdem wir die Schleife auf diese Weise geändert haben, sehen wir die folgende Anweisung wiederholt im Protokoll vorbeiziehen: Feb 14, 2007 11:37:27 AM org.joda.time.format.PeriodFormatterBuilder$FieldFormatter getFieldValue INFO: Unbounded looping i = 2147483647, and iFieldType = 4 Das ist seltsam. Irgendwie scheint der Wert unserer Schleifenvariablen in einem Augenblick von 3 (dem Minimum von 4 und 8, minus 1) auf Integer.MAX_VALUE gesprungen zu sein. Selbst in einer normalen kleinen Schleife würde es ziemlich viel Zeit in Anspruch nehmen, über 2 Milliarden Iterationen durchzuführen. Eine genauere Betrachtung des Protokolls zeigt jedoch, dass es irgendwie bei Integer.MAX_VALUE anfängt. Glücklicherweise können wir daraus schließen, dass die IBM JDK-Leute Math.min korrekt implementiert haben, also muss es ein anderes Problem geben. Wenn Sie den Code so umschreiben, dass er dem nächsten Schnipsel ähnelt, ist das Problem gelöst, aber die Ursache ist nicht bekannt.

int i = Math.min(iFieldType, 8 );
i--;
für (; i  >= 0; i++) {
  log.info("Unbegrenzte Schleifenbildung i = " + i + ", und iFieldType = " + iFieldType);
  if (isSupported(type, i) && iFieldFormatters[i] != null) {
  return Long.MAX_VALUE;
  }
}

Dies behebt natürlich nicht das Problem, dass die Schleife immer noch potenziell unbegrenzt ist. Der Ersteller von joda-time hätte überprüfen sollen, dass die Schleifenvariable keinen Wert außerhalb des Bereichs annimmt, in dem sie Bedeutung hat. Hätte er das getan, wäre das Problem, das wir hier untersucht haben, nie aufgetreten. Mit den aus dieser Sitzung gewonnenen Erkenntnissen haben wir einen Patch erstellt und ihn den Entwicklern übermittelt, der die beanstandeten Zeilen wie folgt aussehen lässt:

int i = Math.min(iFieldType, 8 );
i--;
für (; i  >= 0 && i  <  10; i++) {
  log.info("Unbegrenzte Schleifenbildung i = " + i + ", und iFieldType = " + iFieldType);
  if (isSupported(type, i) && iFieldFormatters[i] != null) {
  return Long.MAX_VALUE;
  }
}

Das Ergebnis dieser Debugging-Sitzung gab uns gemischte Gefühle. Einerseits ist es uns gelungen, das Problem zu finden und eine Lösung dafür zu finden. Wir haben jedoch immer noch keinen direkten Anhaltspunkt dafür, was der Unterschied zwischen der Initialisierung der Schleifenvariable in 2 Anweisungen und der Initialisierung innerhalb der for-Anweisung ist. Es scheint sicher zu sein, dass das IBM JDK für diese beiden Fälle unterschiedlichen Bytecode erzeugt, so dass die Schleifenvariable im neuen Fall plötzlich korrekt initialisiert wird.