Bug 6745 Remove thread renaming and unnecessary logging 80/46180/2
authorAndrej Leitner <andrej.leitner@pantheon.tech>
Mon, 26 Sep 2016 08:05:36 +0000 (10:05 +0200)
committerAndrej Leitner <andrej.leitner@pantheon.tech>
Mon, 26 Sep 2016 12:32:37 +0000 (14:32 +0200)
 - change name format for thread pool
 - remove thread renaming and useless logging
 - remove duplicit time logging
 - update return values

Change-Id: I78abca1870d278c162a7f717ff800dd37c1d4234
Signed-off-by: Andrej Leitner <andrej.leitner@pantheon.tech>
applications/forwardingrules-sync/src/main/java/org/opendaylight/openflowplugin/applications/frsync/impl/AbstractFrmSyncListener.java
applications/forwardingrules-sync/src/main/java/org/opendaylight/openflowplugin/applications/frsync/impl/SimplifiedConfigListener.java
applications/forwardingrules-sync/src/main/java/org/opendaylight/openflowplugin/applications/frsync/impl/SimplifiedOperationalListener.java
applications/forwardingrules-sync/src/main/java/org/opendaylight/openflowplugin/applications/frsync/impl/SyncReactorClusterDecorator.java
applications/forwardingrules-sync/src/main/java/org/opendaylight/openflowplugin/applications/frsync/impl/SyncReactorFutureDecorator.java
applications/forwardingrules-sync/src/main/java/org/opendaylight/openflowplugin/applications/frsync/impl/SyncReactorFutureZipDecorator.java
applications/forwardingrules-sync/src/main/java/org/opendaylight/openflowplugin/applications/frsync/impl/SyncReactorGuardDecorator.java
applications/forwardingrules-sync/src/main/java/org/opendaylight/openflowplugin/applications/frsync/impl/SyncReactorImpl.java
applications/forwardingrules-sync/src/main/java/org/opendaylight/openflowplugin/applications/frsync/impl/SyncReactorRetryDecorator.java
applications/forwardingrules-sync/src/main/java/org/opendaylight/openflowplugin/applications/frsync/util/SyncCrudCounters.java
applications/forwardingrules-sync/src/test/java/org/opendaylight/openflowplugin/applications/frsync/impl/SyncReactorFutureZipDecoratorTest.java

index e3dbc99c425be8969279cf175b99d989bdb9ed8a..ba70e32c58d91271bde7740dba6a885e97f61457 100644 (file)
@@ -26,6 +26,7 @@ import org.slf4j.LoggerFactory;
  * Abstract Listener for node changes.
  */
 public abstract class AbstractFrmSyncListener<T extends DataObject> implements NodeListener<T> {
+
     private static final Logger LOG = LoggerFactory.getLogger(AbstractFrmSyncListener.class);
 
     @Override
@@ -41,7 +42,7 @@ public abstract class AbstractFrmSyncListener<T extends DataObject> implements N
                     final ListenableFuture<Boolean> future = optFuture.get();
                     final Boolean ret = future.get(15000, TimeUnit.MILLISECONDS);
                     if (LOG.isTraceEnabled()) {
-                        LOG.trace("syncup return [{}] for {} from {} listener", ret, nodeId.getValue(), dsType());
+                        LOG.trace("Syncup return [{}] for {} from {} listener", ret, nodeId.getValue(), dsType());
                     }
                 }
             } catch (InterruptedException e) {
index abc686e144d256dc097cdd54d8dad81a331f850a..7204f8297f8a5555483716abb63638d53a96749b 100644 (file)
@@ -29,6 +29,7 @@ import org.slf4j.LoggerFactory;
  * Listens to config changes and delegates sync entry to {@link SyncReactor}.
  */
 public class SimplifiedConfigListener extends AbstractFrmSyncListener<FlowCapableNode> {
+
     private static final Logger LOG = LoggerFactory.getLogger(SimplifiedConfigListener.class);
     private final SyncReactor reactor;
     private final FlowCapableNodeSnapshotDao configSnapshot;
index 9e9d103ce02203a582de2e2ad2c828757d93c8f6..424a98daebc3b7456b864abb5a89a013ea305ea7 100644 (file)
@@ -43,9 +43,9 @@ import org.slf4j.LoggerFactory;
  * Listens to operational changes and starts reconciliation through {@link SyncReactor} when necessary.
  */
 public class SimplifiedOperationalListener extends AbstractFrmSyncListener<Node> {
+
     private static final Logger LOG = LoggerFactory.getLogger(SimplifiedOperationalListener.class);
     public static final String DATE_AND_TIME_FORMAT = "yyyy-MM-dd'T'HH:mm:ss.SSSXXX";
-
     private final SyncReactor reactor;
     private final FlowCapableNodeSnapshotDao operationalSnapshot;
     private final FlowCapableNodeDao configDao;
index 53f8dfe94231e811a7354b28647de822d2ca6a25..37cbb547f8ccfb2eda3c5fb3d0392c8a9d5e8048 100644 (file)
@@ -24,6 +24,7 @@ import org.slf4j.LoggerFactory;
  * Decorator for cluster related issues.
  */
 public class SyncReactorClusterDecorator implements SyncReactor {
+
     private static final Logger LOG = LoggerFactory.getLogger(SyncReactorClusterDecorator.class);
     private final SyncReactor delegate;
     private final DeviceMastershipManager deviceMastershipManager;
index c279e9f9cb5e6c830cde696a65ea8a8ed7cb5a35..dab77ff13b6c72140c0397fcfe501ab053a1a727 100644 (file)
@@ -27,7 +27,7 @@ import org.slf4j.LoggerFactory;
 public class SyncReactorFutureDecorator implements SyncReactor {
 
     private static final Logger LOG = LoggerFactory.getLogger(SyncReactorFutureDecorator.class);
-    public static final String FRM_RPC_CLIENT_PREFIX = "FRM-RPC-client-";
+    public static final String FRM_RPC_CLIENT_PREFIX = "FRS-executor-";
     private final SyncReactor delegate;
     private final ListeningExecutorService executorService;
 
@@ -40,15 +40,13 @@ public class SyncReactorFutureDecorator implements SyncReactor {
                                             final SyncupEntry syncupEntry) throws InterruptedException {
         final NodeId nodeId = PathUtil.digNodeId(flowcapableNodePath);
         return executorService.submit(() -> {
-            final String oldThreadName = updateThreadName(nodeId);
             try {
-                final Boolean ret = doSyncupInFuture(flowcapableNodePath, syncupEntry).get(10000, TimeUnit.MILLISECONDS);
-                return ret;
+                final Boolean futureResult = doSyncupInFuture(flowcapableNodePath, syncupEntry)
+                        .get(10000, TimeUnit.MILLISECONDS);
+                return futureResult;
             } catch (TimeoutException e) {
-                LOG.warn("doSyncupInFuture timeout occured {}", nodeId.getValue(), e);
-                return false;
-            } finally {
-                updateThreadName(oldThreadName);
+                LOG.warn("Syncup future timeout occured {}", nodeId.getValue(), e);
+                return Boolean.FALSE;
             }
         });
     }
@@ -57,25 +55,4 @@ public class SyncReactorFutureDecorator implements SyncReactor {
                                                          final SyncupEntry syncupEntry) throws InterruptedException {
         return delegate.syncup(flowcapableNodePath, syncupEntry);
     }
-
-    private String updateThreadName(final NodeId nodeId) {
-        final Thread currentThread = Thread.currentThread();
-        final String oldName = currentThread.getName();
-        if (oldName.startsWith(SyncReactorFutureDecorator.FRM_RPC_CLIENT_PREFIX)) {
-            currentThread.setName(oldName + "@" + nodeId.getValue());
-        } else {
-            LOG.warn("Try to update foreign thread name {} {}", nodeId, oldName);
-        }
-        return oldName;
-    }
-
-    private void updateThreadName(final String name) {
-        final Thread currentThread = Thread.currentThread();
-        final String oldName = currentThread.getName();
-        if (oldName.startsWith(SyncReactorFutureDecorator.FRM_RPC_CLIENT_PREFIX)) {
-            currentThread.setName(name);
-        } else {
-            LOG.warn("Try to update foreign thread name {} {}", oldName, name);
-        }
-    }
 }
index 5dd431aeab461cfbaa34f6f652fe956cc227744d..3f7c78259854b9a86f6b498c32d35c3da988e014 100644 (file)
@@ -27,8 +27,6 @@ import org.slf4j.LoggerFactory;
  */
 public class SyncReactorFutureZipDecorator extends SyncReactorFutureDecorator {
 
-    private static final Logger LOG = LoggerFactory.getLogger(SyncReactorFutureZipDecorator.class);
-
     @GuardedBy("compressionGuard")
     private final Map<InstanceIdentifier<FlowCapableNode>, SyncupEntry> compressionQueue = new HashMap<>();
     private final Semaphore compressionGuard = new Semaphore(1, false);
@@ -45,7 +43,7 @@ public class SyncReactorFutureZipDecorator extends SyncReactorFutureDecorator {
             if (newTaskNecessary) {
                 super.syncup(flowcapableNodePath, syncupEntry);
             }
-            return Futures.immediateFuture(true);
+            return Futures.immediateFuture(Boolean.TRUE);
         } finally {
             compressionGuard.release();
         }
@@ -55,7 +53,7 @@ public class SyncReactorFutureZipDecorator extends SyncReactorFutureDecorator {
                                                          final SyncupEntry syncupEntry) throws InterruptedException {
         final SyncupEntry lastCompressionState = removeLastCompressionState(flowcapableNodePath);
         if (lastCompressionState == null) {
-            return Futures.immediateFuture(true);
+            return Futures.immediateFuture(Boolean.TRUE);
         } else {
             return super.doSyncupInFuture(flowcapableNodePath, lastCompressionState);
         }
index defe9a0051a2d0d789a2120027fdbfe587b81c77..d44c171b511fc37d8235b267fffef18faa604ee0 100644 (file)
@@ -31,7 +31,6 @@ import org.slf4j.LoggerFactory;
 public class SyncReactorGuardDecorator implements SyncReactor {
 
     private static final Logger LOG = LoggerFactory.getLogger(SyncReactorGuardDecorator.class);
-
     private final SyncReactor delegate;
     private final SemaphoreKeeper<InstanceIdentifier<FlowCapableNode>> semaphoreKeeper;
 
@@ -47,24 +46,19 @@ public class SyncReactorGuardDecorator implements SyncReactor {
         final long stampBeforeGuard = System.nanoTime();
         final Semaphore guard = summonGuardAndAcquire(flowcapableNodePath);
         if (guard == null) {
-            return Futures.immediateFuture(false);
+            return Futures.immediateFuture(Boolean.FALSE);
         }
         final long stampAfterGuard = System.nanoTime();
 
         try {
             if (LOG.isDebugEnabled()) {
-                LOG.debug("syncup start {} waiting:{} guard:{} thread:{}",
-                        nodeId.getValue(),
-                        formatNanos(stampAfterGuard - stampBeforeGuard),
-                        guard,
-                        threadName());
+                LOG.debug("Syncup guard acquired and running for {} ", nodeId.getValue());
             }
-
             final ListenableFuture<Boolean> endResult = delegate.syncup(flowcapableNodePath, syncupEntry);
             Futures.addCallback(endResult, createSyncupCallback(guard, stampBeforeGuard, stampAfterGuard, nodeId));
             return endResult;
         } catch (InterruptedException e) {
-            releaseGuardForNodeId(guard);
+            releaseGuard(guard);
             throw e;
         }
     }
@@ -78,19 +72,19 @@ public class SyncReactorGuardDecorator implements SyncReactor {
             public void onSuccess(@Nullable final Boolean result) {
                 if (LOG.isDebugEnabled()) {
                     final long stampFinished = System.nanoTime();
-                    LOG.debug("syncup finished {} took:{} rpc:{} wait:{} guard:{} permits thread:{}", nodeId.getValue(),
+                    LOG.debug("Syncup finished {} took:{} rpc:{} wait:{}", nodeId.getValue(),
                             formatNanos(stampFinished - stampBeforeGuard), formatNanos(stampFinished - stampAfterGuard),
-                            formatNanos(stampAfterGuard - stampBeforeGuard), guard.availablePermits(), threadName());
+                            formatNanos(stampAfterGuard - stampBeforeGuard));
                 }
-                releaseGuardForNodeId(guard);
+                releaseGuard(guard);
             }
             @Override
             public void onFailure(final Throwable t) {
                 final long stampFinished = System.nanoTime();
-                LOG.warn("syncup failed {} took:{} rpc:{} wait:{} guard:{} permits thread:{}", nodeId.getValue(),
+                LOG.warn("Syncup failed {} took:{} rpc:{} wait:{}", nodeId.getValue(),
                         formatNanos(stampFinished - stampBeforeGuard), formatNanos(stampFinished - stampAfterGuard),
-                        formatNanos(stampAfterGuard - stampBeforeGuard), guard.availablePermits(), threadName());
-                releaseGuardForNodeId(guard);
+                        formatNanos(stampAfterGuard - stampBeforeGuard));
+                releaseGuard(guard);
             }};
     }
 
@@ -106,15 +100,15 @@ public class SyncReactorGuardDecorator implements SyncReactor {
     private Semaphore summonGuardAndAcquire(final InstanceIdentifier<FlowCapableNode> flowcapableNodePath) {
         final NodeId nodeId = PathUtil.digNodeId(flowcapableNodePath);
         final Semaphore guard = Preconditions.checkNotNull(semaphoreKeeper.summonGuard(flowcapableNodePath),
-                "no guard for " + nodeId.getValue());
+                "No guard for " + nodeId.getValue());
         try {
             guard.acquire();
         } catch (InterruptedException e) {
-            LOG.warn("syncup summon {} failed {}", nodeId.getValue(), e);
+            LOG.warn("Syncup summon {} failed {}", nodeId.getValue(), e);
             return null;
         }
         if (LOG.isTraceEnabled()) {
-            LOG.trace("syncup summon {} guard:{} thread:{}", nodeId.getValue(), guard, threadName());
+            LOG.trace("Syncup summon {} guard:{}", nodeId.getValue(), guard);
         }
         return guard;
     }
@@ -123,17 +117,12 @@ public class SyncReactorGuardDecorator implements SyncReactor {
      * Unlock and release guard.
      * @param guard semaphore guard which should be unlocked
      */
-    private static void releaseGuardForNodeId(final Semaphore guard) {
+    private static void releaseGuard(final Semaphore guard) {
         if (guard != null) {
             guard.release();
             if (LOG.isTraceEnabled()) {
-                LOG.trace("syncup release guard:{} thread:{}", guard, threadName());
+                LOG.trace("Syncup release guard:{} thread:{}", guard);
             }
         }
     }
-
-    private static String threadName() {
-        final Thread currentThread = Thread.currentThread();
-        return currentThread.getName();
-    }
 }
index d66c30f7deabb50390a3a31ee7dd24d77b6e926c..d1cb342cd0bc9703ee8b36173cb5536081ee505a 100644 (file)
@@ -87,7 +87,6 @@ public class SyncReactorImpl implements SyncReactor {
                 groupsToAddOrUpdate, metersToAddOrUpdate, flowsToAddOrUpdate,
                 flowsToRemove, metersToRemove, groupsToRemove);
 
-        counters.setStartNano(System.nanoTime());
         final ListenableFuture<RpcResult<Void>> bootstrapResultFuture = RpcResultBuilder.<Void>success().buildFuture();
         final ListenableFuture<RpcResult<Void>> resultVehicle = syncPlanPushStrategy.executeSyncStrategy(
                 bootstrapResultFuture, input, counters);
@@ -103,12 +102,11 @@ public class SyncReactorImpl implements SyncReactor {
                     final CrudCounts meterCrudCounts = counters.getMeterCrudCounts();
                     final CrudCounts groupCrudCounts = counters.getGroupCrudCounts();
                     LOG.debug("syncup outcome[{}] (added/updated/removed): flow={}/{}/{}, group={}/{}/{}, " +
-                                    "meter={}/{}/{}, took={} ms, errors={}",
+                                    "meter={}/{}/{}, errors={}",
                             nodeId.getValue(),
                             flowCrudCounts.getAdded(), flowCrudCounts.getUpdated(), flowCrudCounts.getRemoved(),
                             groupCrudCounts.getAdded(), groupCrudCounts.getUpdated(), groupCrudCounts.getRemoved(),
                             meterCrudCounts.getAdded(), meterCrudCounts.getUpdated(), meterCrudCounts.getRemoved(),
-                            TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - counters.getStartNano()),
                             Arrays.toString(input.getErrors().toArray()));
                 }
                 return input.isSuccessful();
index 95194980ca37e2af97f8a5b84155ebbc50a6ccf9..e8c9b3ee71f98792239907ad587cc3b5ac3135d3 100644 (file)
@@ -27,7 +27,6 @@ import org.slf4j.LoggerFactory;
 public class SyncReactorRetryDecorator implements SyncReactor {
 
     private static final Logger LOG = LoggerFactory.getLogger(SyncReactorRetryDecorator.class);
-
     private final SyncReactor delegate;
     private final ReconciliationRegistry reconciliationRegistry;
 
@@ -42,7 +41,7 @@ public class SyncReactorRetryDecorator implements SyncReactor {
         final NodeId nodeId = PathUtil.digNodeId(flowcapableNodePath);
         if (syncupEntry.isOptimizedConfigDelta() && reconciliationRegistry.isRegistered(nodeId)) {
             LOG.debug("Config change ignored because {} is in reconcile.", nodeId.getValue());
-            return Futures.immediateFuture(Boolean.FALSE);
+            return Futures.immediateFuture(Boolean.TRUE);
         }
 
         ListenableFuture<Boolean> syncupResult = delegate.syncup(flowcapableNodePath,syncupEntry);
@@ -52,11 +51,10 @@ public class SyncReactorRetryDecorator implements SyncReactor {
             public Boolean apply(Boolean result) {
                 if (result) {
                     reconciliationRegistry.unregisterIfRegistered(nodeId);
-                    return true;
                 } else {
                     reconciliationRegistry.register(nodeId);
-                    return false;
                 }
+                return result;
             }
         });
     }
index 487f0650828d1e0d7b9434ca1a36f3092fb65c13..3b512aae383ff2ad14dd070ca8fe098bf0bcd3d7 100644 (file)
@@ -15,7 +15,6 @@ public class SyncCrudCounters {
     private final CrudCounts flowCrudCounts;
     private final CrudCounts groupCrudCounts;
     private final CrudCounts meterCrudCounts;
-    private long startNano;
 
     public SyncCrudCounters() {
         flowCrudCounts = new CrudCounts();
@@ -35,15 +34,6 @@ public class SyncCrudCounters {
         return meterCrudCounts;
     }
 
-
-    public long getStartNano() {
-        return startNano;
-    }
-
-    public void setStartNano(final long startNano) {
-        this.startNano = startNano;
-    }
-
     public void resetAll() {
         getGroupCrudCounts().setUpdated(0);
         getGroupCrudCounts().setAdded(0);
index e8b9157de928c24ff290fb9bb35ff31cb90ecf30..c49ab73a94701ea965904cb77d07004b5e7798f7 100644 (file)
@@ -65,7 +65,7 @@ public class SyncReactorFutureZipDecoratorTest {
     public void setUp() {
         final ExecutorService executorService = Executors.newSingleThreadExecutor(new ThreadFactoryBuilder()
                 .setDaemon(false)
-                .setNameFormat("frsync-test%d")
+                .setNameFormat(SyncReactorFutureDecorator.FRM_RPC_CLIENT_PREFIX)
                 .setUncaughtExceptionHandler((thread, e) -> LOG.error("Uncaught exception {}", thread, e))
                 .build());
         syncThreadPool = MoreExecutors.listeningDecorator(executorService);