openflow-protocol-impl/src/main/java/org/opendaylight/openflowjava/protocol/impl/core/connection/OutboundQueueManager.java

   1 /*
   2  * Copyright (c) 2015 Pantheon Technologies s.r.o. 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 package org.opendaylight.openflowjava.protocol.impl.core.connection;
   9
  10 import com.google.common.base.Preconditions;
  11 import io.netty.channel.ChannelHandlerContext;
  12 import io.netty.channel.ChannelInboundHandlerAdapter;
  13 import java.net.InetSocketAddress;
  14 import java.util.ArrayDeque;
  15 import java.util.Iterator;
  16 import java.util.LinkedList;
  17 import java.util.Queue;
  18 import java.util.concurrent.TimeUnit;
  19 import java.util.concurrent.atomic.AtomicBoolean;
  20 import org.opendaylight.openflowjava.protocol.api.connection.OutboundQueueException;
  21 import org.opendaylight.openflowjava.protocol.api.connection.OutboundQueueHandler;
  22 import org.opendaylight.yang.gen.v1.urn.opendaylight.openflow.protocol.rev130731.BarrierInput;
  23 import org.opendaylight.yang.gen.v1.urn.opendaylight.openflow.protocol.rev130731.EchoReplyInput;
  24 import org.opendaylight.yang.gen.v1.urn.opendaylight.openflow.protocol.rev130731.EchoReplyInputBuilder;
  25 import org.opendaylight.yang.gen.v1.urn.opendaylight.openflow.protocol.rev130731.EchoRequestMessage;
  26 import org.opendaylight.yang.gen.v1.urn.opendaylight.openflow.protocol.rev130731.OfHeader;
  27 import org.slf4j.Logger;
  28 import org.slf4j.LoggerFactory;
  29
  30 final class OutboundQueueManager<T extends OutboundQueueHandler> extends ChannelInboundHandlerAdapter implements AutoCloseable {
  31     private static final Logger LOG = LoggerFactory.getLogger(OutboundQueueManager.class);
  32
  33     /**
  34      * This is the default upper bound we place on the flush task running
  35      * a single iteration. We relinquish control after about this amount
  36      * of time.
  37      */
  38     private static final long DEFAULT_WORKTIME_MICROS = TimeUnit.MILLISECONDS.toMicros(100);
  39
  40     /**
  41      * We re-check the time spent flushing every this many messages. We do this because
  42      * checking after each message may prove to be CPU-intensive. Set to Integer.MAX_VALUE
  43      * or similar to disable the feature.
  44      */
  45     private static final int WORKTIME_RECHECK_MSGS = 64;
  46
  47     /**
  48      * We maintain a cache of this many previous queues for later reuse.
  49      */
  50     private static final int QUEUE_CACHE_SIZE = 4;
  51
  52     private final Queue<OutboundQueueImpl> queueCache = new ArrayDeque<>(QUEUE_CACHE_SIZE);
  53     private final Queue<OutboundQueueImpl> activeQueues = new LinkedList<>();
  54     private final AtomicBoolean flushScheduled = new AtomicBoolean();
  55     private final ConnectionAdapterImpl parent;
  56     private final InetSocketAddress address;
  57     private final long maxBarrierNanos;
  58     private final long maxWorkTime;
  59     private final int queueSize;
  60     private final T handler;
  61
  62     // Updated from netty only
  63     private long lastBarrierNanos = System.nanoTime();
  64     private OutboundQueueImpl currentQueue;
  65     private boolean barrierTimerEnabled;
  66     private int nonBarrierMessages;
  67     private long lastXid = 0;
  68     private Integer shutdownOffset;
  69
  70     // Passed to executor to request triggering of flush
  71     private final Runnable flushRunnable = new Runnable() {
  72         @Override
  73         public void run() {
  74             flush();
  75         }
  76     };
  77
  78     // Passed to executor to request a periodic barrier check
  79     private final Runnable barrierRunnable = new Runnable() {
  80         @Override
  81         public void run() {
  82             barrier();
  83         }
  84     };
  85
  86     OutboundQueueManager(final ConnectionAdapterImpl parent, final InetSocketAddress address, final T handler,
  87         final int queueSize, final long maxBarrierNanos) {
  88         this.parent = Preconditions.checkNotNull(parent);
  89         this.handler = Preconditions.checkNotNull(handler);
  90         Preconditions.checkArgument(queueSize > 0);
  91         this.queueSize = queueSize;
  92         Preconditions.checkArgument(maxBarrierNanos > 0);
  93         this.maxBarrierNanos = maxBarrierNanos;
  94         this.address = address;
  95         this.maxWorkTime = TimeUnit.MICROSECONDS.toNanos(DEFAULT_WORKTIME_MICROS);
  96
  97         LOG.debug("Queue manager instantiated with queue size {}", queueSize);
  98         createQueue();
  99     }
 100
 101     T getHandler() {
 102         return handler;
 103     }
 104
 105     @Override
 106     public void close() {
 107         handler.onConnectionQueueChanged(null);
 108     }
 109
 110     private void retireQueue(final OutboundQueueImpl queue) {
 111         if (queueCache.offer(queue)) {
 112             LOG.trace("Saving queue {} for later reuse", queue);
 113         } else {
 114             LOG.trace("Queue {} thrown away", queue);
 115         }
 116     }
 117
 118     private void createQueue() {
 119         final long baseXid = lastXid;
 120         lastXid += queueSize + 1;
 121
 122         final OutboundQueueImpl cached = queueCache.poll();
 123         final OutboundQueueImpl queue;
 124         if (cached != null) {
 125             queue = cached.reuse(baseXid);
 126             LOG.trace("Reusing queue {} as {} on channel {}", cached, queue, parent.getChannel());
 127         } else {
 128             queue = new OutboundQueueImpl(this, baseXid, queueSize + 1);
 129             LOG.trace("Allocated new queue {} on channel {}", queue, parent.getChannel());
 130         }
 131
 132         activeQueues.add(queue);
 133         currentQueue = queue;
 134         handler.onConnectionQueueChanged(queue);
 135     }
 136
 137     private void scheduleBarrierTimer(final long now) {
 138         long next = lastBarrierNanos + maxBarrierNanos;
 139         if (next < now) {
 140             LOG.trace("Attempted to schedule barrier in the past, reset maximum)");
 141             next = now + maxBarrierNanos;
 142         }
 143
 144         final long delay = next - now;
 145         LOG.trace("Scheduling barrier timer {}us from now", TimeUnit.NANOSECONDS.toMicros(delay));
 146         parent.getChannel().eventLoop().schedule(barrierRunnable, next - now, TimeUnit.NANOSECONDS);
 147         barrierTimerEnabled = true;
 148     }
 149
 150     private void scheduleBarrierMessage() {
 151         final Long xid = currentQueue.reserveBarrierIfNeeded();
 152         if (xid == null) {
 153             LOG.trace("Queue {} already contains a barrier, not scheduling one", currentQueue);
 154             return;
 155         }
 156
 157         currentQueue.commitEntry(xid, handler.createBarrierRequest(xid), null);
 158         LOG.trace("Barrier XID {} scheduled", xid);
 159     }
 160
 161     /**
 162      * Flush an entry from the queue.
 163      *
 164      * @param now Time reference for 'now'. We take this as an argument, as
 165      *            we need a timestamp to mark barrier messages we see swinging
 166      *            by. That timestamp does not need to be completely accurate,
 167      *            hence we use the flush start time. Alternative would be to
 168      *            measure System.nanoTime() for each barrier -- needlessly
 169      *            adding overhead.
 170      *
 171      * @return Entry which was flushed, null if no entry is ready.
 172      */
 173     OfHeader flushEntry(final long now) {
 174         final OfHeader message = currentQueue.flushEntry();
 175         if (currentQueue.isFlushed()) {
 176             LOG.debug("Queue {} is fully flushed", currentQueue);
 177             createQueue();
 178         }
 179
 180         if (message == null) {
 181             return null;
 182         }
 183
 184         if (message instanceof BarrierInput) {
 185             LOG.trace("Barrier message seen, resetting counters");
 186             nonBarrierMessages = 0;
 187             lastBarrierNanos = now;
 188         } else {
 189             nonBarrierMessages++;
 190             if (nonBarrierMessages >= queueSize) {
 191                 LOG.trace("Scheduled barrier request after {} non-barrier messages", nonBarrierMessages);
 192                 scheduleBarrierMessage();
 193             } else if (!barrierTimerEnabled) {
 194                 scheduleBarrierTimer(now);
 195             }
 196         }
 197
 198         return message;
 199     }
 200
 201     /**
 202      * Invoked whenever a message comes in from the switch. Runs matching
 203      * on all active queues in an attempt to complete a previous request.
 204      *
 205      * @param message Potential response message
 206      * @return True if the message matched a previous request, false otherwise.
 207      */
 208     boolean onMessage(final OfHeader message) {
 209         LOG.trace("Attempting to pair message {} to a request", message);
 210
 211         Iterator<OutboundQueueImpl> it = activeQueues.iterator();
 212         while (it.hasNext()) {
 213             final OutboundQueueImpl queue = it.next();
 214             final OutboundQueueEntry entry = queue.pairRequest(message);
 215
 216             if (entry == null) {
 217                 continue;
 218             }
 219
 220             LOG.trace("Queue {} accepted response {}", queue, message);
 221
 222             // This has been a barrier request, we need to flush all
 223             // previous queues
 224             if (entry.isBarrier() && activeQueues.size() > 1) {
 225                 LOG.trace("Queue {} indicated request was a barrier", queue);
 226
 227                 it = activeQueues.iterator();
 228                 while (it.hasNext()) {
 229                     final OutboundQueueImpl q = it.next();
 230
 231                     // We want to complete all queues before the current one, we will
 232                     // complete the current queue below
 233                     if (!queue.equals(q)) {
 234                         LOG.trace("Queue {} is implied finished", q);
 235                         q.completeAll();
 236                         it.remove();
 237                         retireQueue(q);
 238                     } else {
 239                         break;
 240                     }
 241                 }
 242             }
 243
 244             if (queue.isFinished()) {
 245                 LOG.trace("Queue {} is finished", queue);
 246                 it.remove();
 247                 retireQueue(queue);
 248             }
 249
 250             return true;
 251         }
 252
 253         LOG.debug("Failed to find completion for message {}", message);
 254         return false;
 255     }
 256
 257     private void scheduleFlush() {
 258         if (flushScheduled.compareAndSet(false, true)) {
 259             LOG.trace("Scheduling flush task on channel {}", parent.getChannel());
 260             parent.getChannel().eventLoop().execute(flushRunnable);
 261         } else {
 262             LOG.trace("Flush task is already present on channel {}", parent.getChannel());
 263         }
 264     }
 265
 266     void ensureFlushing(final OutboundQueueImpl queue) {
 267         Preconditions.checkState(currentQueue.equals(queue));
 268         scheduleFlush();
 269     }
 270
 271     /**
 272      * Periodic barrier check.
 273      */
 274     protected void barrier() {
 275         LOG.debug("Channel {} barrier timer expired", parent.getChannel());
 276         barrierTimerEnabled = false;
 277         if (shutdownOffset != null) {
 278             LOG.trace("Channel shut down, not processing barrier");
 279             return;
 280         }
 281
 282         final long now = System.nanoTime();
 283         final long sinceLast = now - lastBarrierNanos;
 284         if (sinceLast >= maxBarrierNanos) {
 285             LOG.debug("Last barrier at {} now {}, elapsed {}", lastBarrierNanos, now, sinceLast);
 286             // FIXME: we should be tracking requests/responses instead of this
 287             if (nonBarrierMessages == 0) {
 288                 LOG.trace("No messages written since last barrier, not issuing one");
 289             } else {
 290                 scheduleBarrierMessage();
 291             }
 292         }
 293     }
 294
 295     private void rescheduleFlush() {
 296         /*
 297          * We are almost ready to terminate. This is a bit tricky, because
 298          * we do not want to have a race window where a message would be
 299          * stuck on the queue without a flush being scheduled.
 300          *
 301          * So we mark ourselves as not running and then re-check if a
 302          * flush out is needed. That will re-synchronized with other threads
 303          * such that only one flush is scheduled at any given time.
 304          */
 305         if (!flushScheduled.compareAndSet(true, false)) {
 306             LOG.warn("Channel {} queue {} flusher found unscheduled", parent.getChannel(), this);
 307         }
 308
 309         conditionalFlush();
 310     }
 311
 312     private void shutdownFlush() {
 313         long entries = 0;
 314
 315         // Fail all queues
 316         final Iterator<OutboundQueueImpl> it = activeQueues.iterator();
 317         while (it.hasNext()) {
 318             final OutboundQueueImpl queue = it.next();
 319
 320             entries += queue.failAll(OutboundQueueException.DEVICE_DISCONNECTED);
 321             if (queue.isFinished()) {
 322                 LOG.trace("Cleared queue {}", queue);
 323                 it.remove();
 324             }
 325         }
 326
 327         LOG.debug("Cleared {} queue entries from channel {}", entries, parent.getChannel());
 328
 329         Preconditions.checkNotNull(currentQueue, "Current queue should not be null yet");
 330         if (currentQueue.isShutdown(shutdownOffset)) {
 331             currentQueue = null;
 332             handler.onConnectionQueueChanged(null);
 333             LOG.debug("Channel {} shutdown complete", parent.getChannel());
 334         } else {
 335             LOG.trace("Channel {} current queue not completely flushed yet", parent.getChannel());
 336             rescheduleFlush();
 337         }
 338     }
 339
 340     /**
 341      * Perform a single flush operation.
 342      */
 343     protected void flush() {
 344         // If the channel is gone, just flush whatever is not completed
 345         if (shutdownOffset != null) {
 346             shutdownFlush();
 347             return;
 348         }
 349
 350         final long start = System.nanoTime();
 351         final long deadline = start + maxWorkTime;
 352
 353         LOG.debug("Dequeuing messages to channel {}", parent.getChannel());
 354
 355         long messages = 0;
 356         for (;; ++messages) {
 357             if (!parent.getChannel().isWritable()) {
 358                 LOG.trace("Channel is no longer writable");
 359                 break;
 360             }
 361
 362             final OfHeader message = flushEntry(start);
 363             if (message == null) {
 364                 LOG.trace("The queue is completely drained");
 365                 break;
 366             }
 367
 368             final Object wrapper;
 369             if (address == null) {
 370                 wrapper = new MessageListenerWrapper(message, null);
 371             } else {
 372                 wrapper = new UdpMessageListenerWrapper(message, null, address);
 373             }
 374             parent.getChannel().write(wrapper);
 375
 376             /*
 377              * Check every WORKTIME_RECHECK_MSGS for exceeded time.
 378              *
 379              * XXX: given we already measure our flushing throughput, we
 380              *      should be able to perform dynamic adjustments here.
 381              *      is that additional complexity needed, though?
 382              */
 383             if ((messages % WORKTIME_RECHECK_MSGS) == 0 && System.nanoTime() >= deadline) {
 384                 LOG.trace("Exceeded allotted work time {}us",
 385                         TimeUnit.NANOSECONDS.toMicros(maxWorkTime));
 386                 break;
 387             }
 388         }
 389
 390         if (messages > 0) {
 391             LOG.debug("Flushing {} message(s) to channel {}", messages, parent.getChannel());
 392             parent.getChannel().flush();
 393         }
 394
 395         final long stop = System.nanoTime();
 396         LOG.debug("Flushed {} messages in {}us to channel {}",
 397                 messages, TimeUnit.NANOSECONDS.toMicros(stop - start), parent.getChannel());
 398
 399         rescheduleFlush();
 400     }
 401
 402     /**
 403      * Schedule a queue flush if it is not empty and the channel is found
 404      * to be writable. May only be called from Netty context.
 405      */
 406     private void conditionalFlush() {
 407         if (currentQueue.needsFlush()) {
 408             scheduleFlush();
 409         } else {
 410             LOG.trace("Queue is empty, no flush needed");
 411         }
 412     }
 413
 414     private void conditionalFlush(final ChannelHandlerContext ctx) {
 415         Preconditions.checkState(ctx.channel().equals(parent.getChannel()), "Inconsistent channel %s with context %s", parent.getChannel(), ctx);
 416         conditionalFlush();
 417     }
 418
 419     @Override
 420     public void channelActive(final ChannelHandlerContext ctx) throws Exception {
 421         super.channelActive(ctx);
 422         conditionalFlush(ctx);
 423     }
 424
 425     @Override
 426     public void channelWritabilityChanged(final ChannelHandlerContext ctx) throws Exception {
 427         super.channelWritabilityChanged(ctx);
 428         conditionalFlush(ctx);
 429     }
 430
 431     @Override
 432     public void channelInactive(final ChannelHandlerContext ctx) throws Exception {
 433         super.channelInactive(ctx);
 434
 435         LOG.debug("Channel {} initiating shutdown...", parent.getChannel());
 436
 437         /*
 438          * We are dealing with a multi-threaded shutdown, as the user may still
 439          * be reserving entries in the queue. We are executing in a netty thread,
 440          * so neither flush nor barrier can be running, which is good news.
 441          *
 442          * We will eat up all the slots in the queue here and mark the offset first
 443          * reserved offset and free up all the cached queues. We then schedule
 444          * the flush task, which will deal with the rest of the shutdown process.
 445          */
 446         shutdownOffset = currentQueue.startShutdown();
 447         queueCache.clear();
 448         LOG.trace("Channel {} reserved all entries at offset {}", parent.getChannel(), shutdownOffset);
 449         scheduleFlush();
 450     }
 451
 452     @Override
 453     public String toString() {
 454         return String.format("Channel %s queue [flushing=%s]", parent.getChannel(), flushScheduled.get());
 455     }
 456
 457     void onEchoRequest(final EchoRequestMessage message) {
 458         final EchoReplyInput reply = new EchoReplyInputBuilder().setData(message.getData()).setVersion(message.getVersion()).setXid(message.getXid()).build();
 459         parent.getChannel().writeAndFlush(reply);
 460     }
 461 }