Remove excessive (trace) logging in FRS
[openflowplugin.git] / applications / forwardingrules-sync / src / main / java / org / opendaylight / openflowplugin / applications / frsync / impl / SyncReactorGuardDecorator.java
1 /**
2  * Copyright (c) 2016 Cisco Systems, Inc. and others.  All rights reserved.
3  *
4  * This program and the accompanying materials are made available under the
5  * terms of the Eclipse Public License v1.0 which accompanies this distribution,
6  * and is available at http://www.eclipse.org/legal/epl-v10.html
7  */
8
9 package org.opendaylight.openflowplugin.applications.frsync.impl;
10
11 import com.google.common.base.Preconditions;
12 import com.google.common.util.concurrent.FutureCallback;
13 import com.google.common.util.concurrent.Futures;
14 import com.google.common.util.concurrent.ListenableFuture;
15 import java.util.concurrent.Semaphore;
16 import java.util.concurrent.TimeUnit;
17 import javax.annotation.Nullable;
18 import org.opendaylight.openflowplugin.applications.frsync.SemaphoreKeeper;
19 import org.opendaylight.openflowplugin.applications.frsync.SyncReactor;
20 import org.opendaylight.openflowplugin.applications.frsync.util.PathUtil;
21 import org.opendaylight.openflowplugin.applications.frsync.util.SyncupEntry;
22 import org.opendaylight.yang.gen.v1.urn.opendaylight.flow.inventory.rev130819.FlowCapableNode;
23 import org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.NodeId;
24 import org.opendaylight.yangtools.yang.binding.InstanceIdentifier;
25 import org.slf4j.Logger;
26 import org.slf4j.LoggerFactory;
27
28 /**
29  * Decorator for NodeId level syncup locking.
30  */
31 public class SyncReactorGuardDecorator implements SyncReactor {
32
33     private static final Logger LOG = LoggerFactory.getLogger(SyncReactorGuardDecorator.class);
34
35     private final SyncReactor delegate;
36     private final SemaphoreKeeper<InstanceIdentifier<FlowCapableNode>> semaphoreKeeper;
37
38     public SyncReactorGuardDecorator(SyncReactor delegate,
39             SemaphoreKeeper<InstanceIdentifier<FlowCapableNode>> semaphoreKeeper) {
40         this.delegate = delegate;
41         this.semaphoreKeeper = semaphoreKeeper;
42     }
43
44     public ListenableFuture<Boolean> syncup(final InstanceIdentifier<FlowCapableNode> flowcapableNodePath,
45                                             final SyncupEntry syncupEntry) throws InterruptedException {
46         final NodeId nodeId = PathUtil.digNodeId(flowcapableNodePath);
47         final long stampBeforeGuard = System.nanoTime();
48         final Semaphore guard = summonGuardAndAcquire(flowcapableNodePath);
49         if (guard == null) {
50             return Futures.immediateFuture(false);
51         }
52         final long stampAfterGuard = System.nanoTime();
53
54         try {
55             if (LOG.isDebugEnabled()) {
56                 LOG.debug("syncup start {} waiting:{} guard:{} thread:{}",
57                         nodeId.getValue(),
58                         formatNanos(stampAfterGuard - stampBeforeGuard),
59                         guard,
60                         threadName());
61             }
62
63             final ListenableFuture<Boolean> endResult = delegate.syncup(flowcapableNodePath, syncupEntry);
64             Futures.addCallback(endResult, createSyncupCallback(guard, stampBeforeGuard, stampAfterGuard, nodeId));
65             return endResult;
66         } catch (InterruptedException e) {
67             releaseGuardForNodeId(guard);
68             throw e;
69         }
70     }
71
72     private static FutureCallback<Boolean> createSyncupCallback(final Semaphore guard,
73                                                                 final long stampBeforeGuard,
74                                                                 final long stampAfterGuard,
75                                                                 final NodeId nodeId) {
76         return new FutureCallback<Boolean>() {
77             @Override
78             public void onSuccess(@Nullable final Boolean result) {
79                 if (LOG.isDebugEnabled()) {
80                     final long stampFinished = System.nanoTime();
81                     LOG.debug("syncup finished {} took:{} rpc:{} wait:{} guard:{} permits thread:{}", nodeId.getValue(),
82                             formatNanos(stampFinished - stampBeforeGuard), formatNanos(stampFinished - stampAfterGuard),
83                             formatNanos(stampAfterGuard - stampBeforeGuard), guard.availablePermits(), threadName());
84                 }
85                 releaseGuardForNodeId(guard);
86             }
87             @Override
88             public void onFailure(final Throwable t) {
89                 final long stampFinished = System.nanoTime();
90                 LOG.warn("syncup failed {} took:{} rpc:{} wait:{} guard:{} permits thread:{}", nodeId.getValue(),
91                         formatNanos(stampFinished - stampBeforeGuard), formatNanos(stampFinished - stampAfterGuard),
92                         formatNanos(stampAfterGuard - stampBeforeGuard), guard.availablePermits(), threadName());
93                 releaseGuardForNodeId(guard);
94             }};
95     }
96
97     private static String formatNanos(final long nanos) {
98         return "'" + TimeUnit.NANOSECONDS.toMillis(nanos) + " ms'";
99     }
100
101     /**
102      * Get guard and lock for node.
103      * @param flowcapableNodePath II of node for which guard should be acquired
104      * @return semaphore guard
105      */
106     private Semaphore summonGuardAndAcquire(final InstanceIdentifier<FlowCapableNode> flowcapableNodePath) {
107         final NodeId nodeId = PathUtil.digNodeId(flowcapableNodePath);
108         final Semaphore guard = Preconditions.checkNotNull(semaphoreKeeper.summonGuard(flowcapableNodePath),
109                 "no guard for " + nodeId.getValue());
110         try {
111             guard.acquire();
112         } catch (InterruptedException e) {
113             LOG.warn("syncup summon {} failed {}", nodeId.getValue(), e);
114             return null;
115         }
116         if (LOG.isTraceEnabled()) {
117             LOG.trace("syncup summon {} guard:{} thread:{}", nodeId.getValue(), guard, threadName());
118         }
119         return guard;
120     }
121
122     /**
123      * Unlock and release guard.
124      * @param guard semaphore guard which should be unlocked
125      */
126     private static void releaseGuardForNodeId(final Semaphore guard) {
127         if (guard != null) {
128             guard.release();
129             if (LOG.isTraceEnabled()) {
130                 LOG.trace("syncup release guard:{} thread:{}", guard, threadName());
131             }
132         }
133     }
134
135     private static String threadName() {
136         final Thread currentThread = Thread.currentThread();
137         return currentThread.getName();
138     }
139 }