Merge "Fixed debug log messages."
[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.controller.md.sal.common.api.data.LogicalDatastoreType;
19 import org.opendaylight.openflowplugin.applications.frsync.SemaphoreKeeper;
20 import org.opendaylight.openflowplugin.applications.frsync.SyncReactor;
21 import org.opendaylight.openflowplugin.applications.frsync.util.PathUtil;
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 FlowCapableNode configTree, final FlowCapableNode operationalTree,
46                                             final LogicalDatastoreType dsType) throws InterruptedException {
47         final NodeId nodeId = PathUtil.digNodeId(flowcapableNodePath);
48         LOG.trace("syncup guard {}", nodeId.getValue());
49
50         final long stampBeforeGuard = System.nanoTime();
51         final Semaphore guard = summonGuardAndAcquire(flowcapableNodePath);
52         if (guard == null) {
53             return Futures.immediateFuture(false);
54         }
55         final long stampAfterGuard = System.nanoTime();
56
57         try {
58             if (LOG.isDebugEnabled()) {
59                 LOG.debug("syncup start {} waiting:{} guard:{} thread:{}", nodeId.getValue(),
60                         formatNanos(stampAfterGuard - stampBeforeGuard),
61                         guard, threadName());
62             }
63
64             final ListenableFuture<Boolean> endResult =
65                     delegate.syncup(flowcapableNodePath, configTree, operationalTree, dsType);
66
67             Futures.addCallback(endResult, new FutureCallback<Boolean>() {
68                 @Override
69                 public void onSuccess(@Nullable final Boolean result) {
70                     if (LOG.isDebugEnabled()) {
71                         final long stampFinished = System.nanoTime();
72                         LOG.debug("syncup finished {} took:{} rpc:{} wait:{} guard:{} permits thread:{}", nodeId.getValue(),
73                                 formatNanos(stampFinished - stampBeforeGuard),
74                                 formatNanos(stampFinished - stampAfterGuard),
75                                 formatNanos(stampAfterGuard - stampBeforeGuard),
76                                 guard.availablePermits(), threadName());
77                     }
78
79                     releaseGuardForNodeId(guard);
80                 }
81
82                 @Override
83                 public void onFailure(final Throwable t) {
84                     if (LOG.isDebugEnabled()) {
85                         final long stampFinished = System.nanoTime();
86                         LOG.warn("syncup failed {} took:{} rpc:{} wait:{} guard:{} permits thread:{}", nodeId.getValue(),
87                                 formatNanos(stampFinished - stampBeforeGuard),
88                                 formatNanos(stampFinished - stampAfterGuard),
89                                 formatNanos(stampAfterGuard - stampBeforeGuard),
90                                 guard.availablePermits(), threadName());
91                     }
92
93                     releaseGuardForNodeId(guard);
94                 }
95             });
96             return endResult;
97         } catch (InterruptedException e) {
98             releaseGuardForNodeId(guard);
99             throw e;
100         }
101     }
102
103     private String formatNanos(long nanos) {
104         return "'" + TimeUnit.NANOSECONDS.toMillis(nanos) + " ms'";
105     }
106
107     /**
108      * Get guard and lock for node.
109      * @param flowcapableNodePath II of node for which guard should be acquired
110      * @return semaphore guard
111      */
112     private Semaphore summonGuardAndAcquire(final InstanceIdentifier<FlowCapableNode> flowcapableNodePath) {
113         final NodeId nodeId = PathUtil.digNodeId(flowcapableNodePath);
114         final Semaphore guard = Preconditions.checkNotNull(semaphoreKeeper.summonGuard(flowcapableNodePath),
115                 "no guard for " + nodeId.getValue());
116         try {
117             guard.acquire();
118         } catch (InterruptedException e) {
119             LOG.error("syncup summon {} failed {}", nodeId.getValue(), e);
120             return null;
121         }
122         LOG.trace("syncup summon {} guard:{} thread:{}", nodeId.getValue(), guard, threadName());
123         return guard;
124     }
125
126     /**
127      * Unlock and release guard.
128      * @param guard semaphore guard which should be unlocked
129      */
130     private void releaseGuardForNodeId(final Semaphore guard) {
131         if (guard != null) {
132             guard.release();
133             LOG.trace("syncup release guard:{} thread:{}", guard, threadName());
134         }
135     }
136
137     private static String threadName() {
138         final Thread currentThread = Thread.currentThread();
139         return currentThread.getName();
140     }
141
142 }