Adding some instrumentation to figure out where transient delays in creating pipeliner come from.

Change-Id: I7ad08a660f2915f6df4ceeaa63f798eaca0720a8

@@ -194,14 +194,12 @@ public class FlowObjectiveManager implements FlowObjectiveService {
     @Override
     @Override
     public void filter(DeviceId deviceId, FilteringObjective filteringObjective) {
     public void filter(DeviceId deviceId, FilteringObjective filteringObjective) {
         checkPermission(Permission.FLOWRULE_WRITE);
         checkPermission(Permission.FLOWRULE_WRITE);
-
         executorService.submit(new ObjectiveInstaller(deviceId, filteringObjective));
         executorService.submit(new ObjectiveInstaller(deviceId, filteringObjective));
     }
     }
 
 
     @Override
     @Override
     public void forward(DeviceId deviceId, ForwardingObjective forwardingObjective) {
     public void forward(DeviceId deviceId, ForwardingObjective forwardingObjective) {
         checkPermission(Permission.FLOWRULE_WRITE);
         checkPermission(Permission.FLOWRULE_WRITE);
-
         if (queueObjective(deviceId, forwardingObjective)) {
         if (queueObjective(deviceId, forwardingObjective)) {
             return;
             return;
         }
         }
@@ -211,14 +209,12 @@ public class FlowObjectiveManager implements FlowObjectiveService {
     @Override
     @Override
     public void next(DeviceId deviceId, NextObjective nextObjective) {
     public void next(DeviceId deviceId, NextObjective nextObjective) {
         checkPermission(Permission.FLOWRULE_WRITE);
         checkPermission(Permission.FLOWRULE_WRITE);
-
         executorService.submit(new ObjectiveInstaller(deviceId, nextObjective));
         executorService.submit(new ObjectiveInstaller(deviceId, nextObjective));
     }
     }
 
 
     @Override
     @Override
     public int allocateNextId() {
     public int allocateNextId() {
         checkPermission(Permission.FLOWRULE_WRITE);
         checkPermission(Permission.FLOWRULE_WRITE);
-
         return flowObjectiveStore.allocateNextId();
         return flowObjectiveStore.allocateNextId();
     }
     }
 
 
@@ -238,8 +234,7 @@ public class FlowObjectiveManager implements FlowObjectiveService {
 
 
     // Retrieves the device pipeline behaviour from the cache.
     // Retrieves the device pipeline behaviour from the cache.
     private Pipeliner getDevicePipeliner(DeviceId deviceId) {
     private Pipeliner getDevicePipeliner(DeviceId deviceId) {
-        Pipeliner pipeliner = pipeliners.get(deviceId);
-        return pipeliner;
+        return pipeliners.get(deviceId);
     }
     }
 
 
     private void setupPipelineHandler(DeviceId deviceId) {
     private void setupPipelineHandler(DeviceId deviceId) {
@@ -254,7 +249,6 @@ public class FlowObjectiveManager implements FlowObjectiveService {
             try {
             try {
                 // Otherwise create it and if it has pipeline behaviour, cache it
                 // Otherwise create it and if it has pipeline behaviour, cache it
                 handler = driverService.createHandler(deviceId);
                 handler = driverService.createHandler(deviceId);
-                bTime = now();
                 if (!handler.driver().hasBehaviour(Pipeliner.class)) {
                 if (!handler.driver().hasBehaviour(Pipeliner.class)) {
                     log.warn("Pipeline behaviour not supported for device {}",
                     log.warn("Pipeline behaviour not supported for device {}",
                              deviceId);
                              deviceId);
@@ -266,16 +260,15 @@ public class FlowObjectiveManager implements FlowObjectiveService {
             }
             }
 
 
             driverHandlers.put(deviceId, handler);
             driverHandlers.put(deviceId, handler);
-            cTime = now();
+            hTime = now();
         }
         }
 
 
         // Always (re)initialize the pipeline behaviour
         // Always (re)initialize the pipeline behaviour
         log.info("Driver {} bound to device {} ... initializing driver",
         log.info("Driver {} bound to device {} ... initializing driver",
                  handler.driver().name(), deviceId);
                  handler.driver().name(), deviceId);
         Pipeliner pipeliner = handler.behaviour(Pipeliner.class);
         Pipeliner pipeliner = handler.behaviour(Pipeliner.class);
-        dTime = now();
+        hbTime = now();
         pipeliner.init(deviceId, context);
         pipeliner.init(deviceId, context);
-        eTime = now();
         pipeliners.putIfAbsent(deviceId, pipeliner);
         pipeliners.putIfAbsent(deviceId, pipeliner);
     }
     }
 
 
@@ -288,7 +281,6 @@ public class FlowObjectiveManager implements FlowObjectiveService {
                     log.debug("mastership changed on device {}", event.subject());
                     log.debug("mastership changed on device {}", event.subject());
                     start = now();
                     start = now();
                     if (deviceService.isAvailable(event.subject())) {
                     if (deviceService.isAvailable(event.subject())) {
-                        aTime = now();
                         setupPipelineHandler(event.subject());
                         setupPipelineHandler(event.subject());
                     }
                     }
                     stopWatch();
                     stopWatch();
@@ -312,7 +304,6 @@ public class FlowObjectiveManager implements FlowObjectiveService {
                               event.subject().id());
                               event.subject().id());
                     start = now();
                     start = now();
                     if (deviceService.isAvailable(event.subject().id())) {
                     if (deviceService.isAvailable(event.subject().id())) {
-                        aTime = now();
                         log.debug("Device is now available {}", event.subject().id());
                         log.debug("Device is now available {}", event.subject().id());
                         setupPipelineHandler(event.subject().id());
                         setupPipelineHandler(event.subject().id());
                     }
                     }
@@ -339,7 +330,7 @@ public class FlowObjectiveManager implements FlowObjectiveService {
     // Temporary mechanism to monitor pipeliner setup time-cost; there are
     // Temporary mechanism to monitor pipeliner setup time-cost; there are
     // intermittent time where this takes in excess of 2 seconds. Why?
     // intermittent time where this takes in excess of 2 seconds. Why?
     private long start = 0, totals = 0, count = 0;
     private long start = 0, totals = 0, count = 0;
-    private long aTime, bTime, cTime, dTime, eTime;
+    private long hTime, hbTime;
     private static final long LIMIT = 500;
     private static final long LIMIT = 500;
 
 
     private long now() {
     private long now() {
@@ -351,9 +342,8 @@ public class FlowObjectiveManager implements FlowObjectiveService {
         totals += duration;
         totals += duration;
         count += 1;
         count += 1;
         if (duration > LIMIT) {
         if (duration > LIMIT) {
-            log.info("Pipeline setup took {} ms; avg {} ms; a={}, b={}, c={}, d={}, e={}",
-                     duration, totals / count, diff(aTime), diff(bTime),
-                     diff(cTime), diff(dTime), diff(eTime));
+            log.info("Pipeline setup took {} ms; avg {} ms; hTime={}, hbTime={}",
+                     duration, totals / count, diff(hTime), diff(hbTime));
         }
         }
     }
     }