commit 556bda809f6f2301dfa9afdf313cfb25f308c887
author Sergiy Matusevych <motus@apache.org> Tue Oct 18 16:39:35 2016 -0700
committer Markus Weimer <weimer@apache.org> Wed Oct 19 10:34:58 2016 -0700
tree b3137fd9e24fcdf66528d2e1d978ef79943c5908
parent 44ee29c04f37c7aec4d952e2e6ce5e3efb49775f

[REEF-1645] Fix the issue with assertion in RuntimeClock.stop() and log numClientAlarms

JIRA:
  [REEF-1645](https://issues.apache.org/jira/browse/REEF-1645)

Pull Request:
  This closes #1160

lang/java/reef-wake/wake/src/main/java/org/apache/reef/wake/time/runtime/RuntimeClock.java

diff --git a/lang/java/reef-wake/wake/src/main/java/org/apache/reef/wake/time/runtime/RuntimeClock.java b/lang/java/reef-wake/wake/src/main/java/org/apache/reef/wake/time/runtime/RuntimeClock.java
index 64ae63a..523bce3 100644
--- a/lang/java/reef-wake/wake/src/main/java/org/apache/reef/wake/time/runtime/RuntimeClock.java
+++ b/lang/java/reef-wake/wake/src/main/java/org/apache/reef/wake/time/runtime/RuntimeClock.java
@@ -124,7 +124,15 @@
     final Time alarm = new ClientAlarm(this.timer.getCurrent() + offset, handler);
 
     if (LOG.isLoggable(Level.FINEST)) {
-      LOG.log(Level.FINEST, "Schedule alarm: {0}", alarm);
+
+      final int eventQueueLen;
+      synchronized (this.schedule) {
+        eventQueueLen = this.numClientAlarms;
+      }
+
+      LOG.log(Level.FINEST,
+          "Schedule alarm: {0} Outstanding client alarms: {1}",
+          new Object[] {alarm, eventQueueLen});
     }
 
     synchronized (this.schedule) {
@@ -178,10 +186,12 @@
       this.exceptionCausedStop = exception;
 
       final Time stopEvent = new StopTime(this.timer.getCurrent());
-      LOG.log(Level.FINE, "Stop scheduled immediately: {0}", stopEvent);
+      LOG.log(Level.FINE,
+          "Stop scheduled immediately: {0} Outstanding client alarms: {1}",
+          new Object[] {stopEvent, this.numClientAlarms});
 
-      this.numClientAlarms = 0;
       assert this.numClientAlarms >= 0;
+      this.numClientAlarms = 0;
 
       this.schedule.clear();
       this.schedule.add(stopEvent);
@@ -209,7 +219,9 @@
       this.isClosed = true;
 
       final Time stopEvent = new StopTime(Math.max(this.timer.getCurrent(), this.lastClientAlarm + 1));
-      LOG.log(Level.FINE, "Graceful shutdown scheduled: {0}", stopEvent);
+      LOG.log(Level.FINE,
+          "Graceful shutdown scheduled: {0} Outstanding client alarms: {1}",
+          new Object[] {stopEvent, this.numClientAlarms});
 
       this.schedule.add(stopEvent);
       this.schedule.notify();
@@ -308,10 +320,11 @@
 
           if (this.isIdle()) {
             // Handle an idle clock event, without locking this.schedule
-            this.handlers.onNext(new IdleClock(timer.getCurrent()));
+            this.handlers.onNext(new IdleClock(this.timer.getCurrent()));
           }
 
           final Time event;
+          final int eventQueueLen;
           synchronized (this.schedule) {
 
             while (this.schedule.isEmpty()) {
@@ -333,24 +346,24 @@
 
             // Remove the event from the schedule and process it:
             event = this.schedule.pollFirst();
-          }
-
-          LOG.log(Level.FINER, "Process event: {0}", event);
-          assert event != null;
-
-          if (event instanceof Alarm) {
 
             if (event instanceof ClientAlarm) {
               --this.numClientAlarms;
               assert this.numClientAlarms >= 0;
             }
 
+            eventQueueLen = this.numClientAlarms;
+          }
+
+          assert event != null;
+
+          LOG.log(Level.FINER,
+              "Process event: {0} Outstanding client alarms: {1}", new Object[] {event, eventQueueLen});
+
+          if (event instanceof Alarm) {
             ((Alarm) event).run();
-
           } else {
-
             this.handlers.onNext(event);
-
             if (event instanceof StopTime) {
               break; // we're done.
             }