Added some debug logging to check on processing timing

Change-Id: If09f2afb572151bbefe3c21f284b478622ab5fe2
Signed-off-by: Ed Warnicke <eaw@cisco.com>

diff --git a/openflowplugin/src/main/java/org/opendaylight/openflowplugin/openflow/md/queue/TicketFinisher.java b/openflowplugin/src/main/java/org/opendaylight/openflowplugin/openflow/md/queue/TicketFinisher.java
index 61d213b5c3874b50d215f66994a3482d4ade8af0..e7c8ca8622581a9bc49c8c8cbb138f7e4e025d57 100644 (file)
--- a/openflowplugin/src/main/java/org/opendaylight/openflowplugin/openflow/md/queue/TicketFinisher.java
+++ b/openflowplugin/src/main/java/org/opendaylight/openflowplugin/openflow/md/queue/TicketFinisher.java
@@ -21,21 +21,21 @@ import org.slf4j.LoggerFactory;
  *
  */
 public class TicketFinisher<OUT> implements Runnable {
-    
+
     private static final Logger LOG = LoggerFactory
             .getLogger(TicketFinisher.class);
-    
+
     private final BlockingQueue<TicketResult<OUT>> queue;
     private final Map<Class<? extends OUT>, Collection<PopListener<OUT>>> popListenersMapping;
     private final RegisteredTypeExtractor<OUT> registeredOutTypeExtractor;
-    
+
     /**
      * @param queue
      * @param popListenersMapping
      * @param registeredOutTypeExtractor
      */
     public TicketFinisher(BlockingQueue<TicketResult<OUT>> queue,
-            Map<Class<? extends OUT>, Collection<PopListener<OUT>>> popListenersMapping, 
+            Map<Class<? extends OUT>, Collection<PopListener<OUT>>> popListenersMapping,
             RegisteredTypeExtractor<OUT> registeredOutTypeExtractor) {
         this.queue = queue;
         this.popListenersMapping = popListenersMapping;
@@ -49,10 +49,13 @@ public class TicketFinisher<OUT> implements Runnable {
             try {
                 //TODO:: handle shutdown of queue
                 TicketResult<OUT> result = queue.take();
+                long before = System.nanoTime();
+                LOG.debug("finishing ticket(before): {}, {} remain in queue, {} capacity remaining", System.identityHashCode(result),queue.size(), queue.remainingCapacity());
                 List<OUT> processedMessages = result.getResult().get();
-                LOG.debug("finishing ticket: {}", System.identityHashCode(result));
+                long after = System.nanoTime();
+                LOG.debug("finishing ticket(after): {}, {} remain in queue, {} capacity remaining, processingTime {} ns", System.identityHashCode(result),queue.size(), queue.remainingCapacity(),after-before);
                 for (OUT msg : processedMessages) {
-                    Class<? extends Object> registeredType = 
+                    Class<? extends Object> registeredType =
                             registeredOutTypeExtractor.extractRegisteredType(msg);
                     Collection<PopListener<OUT>> popListeners = popListenersMapping.get(registeredType);
                     if (popListeners == null) {

diff --git a/openflowplugin/src/main/java/org/opendaylight/openflowplugin/openflow/md/queue/TicketProcessorFactory.java b/openflowplugin/src/main/java/org/opendaylight/openflowplugin/openflow/md/queue/TicketProcessorFactory.java
index ff37cba3151956be7c7ac5f7f77a312d569d3f76..c72134fffd3aea08aee6d1d77762d180daef4d23 100644 (file)
--- a/openflowplugin/src/main/java/org/opendaylight/openflowplugin/openflow/md/queue/TicketProcessorFactory.java
+++ b/openflowplugin/src/main/java/org/opendaylight/openflowplugin/openflow/md/queue/TicketProcessorFactory.java
@@ -27,12 +27,12 @@ public class TicketProcessorFactory<IN, OUT> {
 
     protected static final Logger LOG = LoggerFactory
             .getLogger(TicketProcessorFactory.class);
-    
+
     protected VersionExtractor<IN> versionExtractor;
     protected RegisteredTypeExtractor<IN> registeredTypeExtractor;
     protected Map<TranslatorKey, Collection<IMDMessageTranslator<IN, List<OUT>>>> translatorMapping;
     protected MessageSpy<IN, OUT> spy;
-    
+
     /**
      * @param versionExtractor the versionExtractor to set
      */
@@ -69,7 +69,7 @@ public class TicketProcessorFactory<IN, OUT> {
      * @return runnable ticket processor
      */
     public Runnable createProcessor(final Ticket<IN, OUT> ticket) {
-        
+
         Runnable ticketProcessor = new Runnable() {
             @Override
             public void run() {
@@ -121,7 +121,10 @@ public class TicketProcessorFactory<IN, OUT> {
                         if (messageType.equals("PacketInMessage.class")) {
                             cookie = conductor.getAuxiliaryKey();
                         }
+                        long start = System.nanoTime();
                         List<OUT> translatorOutput = translator.translate(cookie, conductor.getSessionContext(), message);
+                        long end = System.nanoTime();
+                        LOG.debug("translator: {} elapsed time {} ns",translator,end-start);
                         if(translatorOutput != null && !translatorOutput.isEmpty()) {
                             result.addAll(translatorOutput);
                         }