org.apache.drill.exec.store.TimedRunnable Maven / Gradle / Ivy

Go to download
/**
 * Licensed to the Apache Software Foundation (ASF) under one
 * or more contributor license agreements.  See the NOTICE file
 * distributed with this work for additional information
 * regarding copyright ownership.  The ASF licenses this file
 * to you under the Apache License, Version 2.0 (the
 * "License"); you may not use this file except in compliance
 * with the License.  You may obtain a copy of the License at
 *
 * http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 */
package org.apache.drill.exec.store;

import java.io.IOException;
import java.util.List;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.ExecutionException;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.Future;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.TimeoutException;

import org.apache.drill.common.concurrent.ExtendedLatch;
import org.apache.drill.common.exceptions.UserException;
import org.slf4j.Logger;

import com.google.common.base.Stopwatch;
import com.google.common.collect.Lists;

/**
 * Class used to allow parallel executions of tasks in a simplified way. Also maintains and reports timings of task completion.
 * TODO: look at switching to fork join.
 * @param  The time value that will be returned when the task is executed.
 */
public abstract class TimedRunnable implements Runnable {

  private static long TIMEOUT_PER_RUNNABLE_IN_MSECS = 15000;

  private volatile Exception e;
  private volatile long threadStart;
  private volatile long timeNanos;
  private volatile V value;

  @Override
  public final void run() {
    long start = System.nanoTime();
    threadStart=start;
    try{
      value = runInner();
    }catch(Exception e){
      this.e = e;
    }finally{
      timeNanos = System.nanoTime() - start;
    }
  }

  protected abstract V runInner() throws Exception ;
  protected abstract IOException convertToIOException(Exception e);

  public long getThreadStart(){
    return threadStart;
  }
  public long getTimeSpentNanos(){
    return timeNanos;
  }

  public final V getValue() throws IOException {
    if(e != null){
      if(e instanceof IOException){
        throw (IOException) e;
      }else{
        throw convertToIOException(e);
      }
    }

    return value;
  }

  private static class LatchedRunnable implements Runnable {
    final CountDownLatch latch;
    final Runnable runnable;

    public LatchedRunnable(CountDownLatch latch, Runnable runnable){
      this.latch = latch;
      this.runnable = runnable;
    }

    @Override
    public void run() {
      try{
        runnable.run();
      }finally{
        latch.countDown();
      }
    }
  }

  /**
   * Execute the list of runnables with the given parallelization.  At end, return values and report completion time
   * stats to provided logger. Each runnable is allowed a certain timeout. If the timeout exceeds, existing/pending
   * tasks will be cancelled and a {@link UserException} is thrown.
   * @param activity Name of activity for reporting in logger.
   * @param logger The logger to use to report results.
   * @param runnables List of runnables that should be executed and timed.  If this list has one item, task will be
   *                  completed in-thread. Runnable must handle {@link InterruptedException}s.
   * @param parallelism  The number of threads that should be run to complete this task.
   * @return The list of outcome objects.
   * @throws IOException All exceptions are coerced to IOException since this was build for storage system tasks initially.
   */
  public static  List run(final String activity, final Logger logger, final List> runnables, int parallelism) throws IOException {
    Stopwatch watch = Stopwatch.createStarted();
    long timedRunnableStart=System.nanoTime();
    if(runnables.size() == 1){
      parallelism = 1;
      runnables.get(0).run();
    }else{
      parallelism = Math.min(parallelism,  runnables.size());
      final ExtendedLatch latch = new ExtendedLatch(runnables.size());
      final ExecutorService threadPool = Executors.newFixedThreadPool(parallelism);
      try{
        for(TimedRunnable runnable : runnables){
          threadPool.submit(new LatchedRunnable(latch, runnable));
        }

        final long timeout = (long)Math.ceil((TIMEOUT_PER_RUNNABLE_IN_MSECS * runnables.size())/parallelism);
        if (!latch.awaitUninterruptibly(timeout)) {
          // Issue a shutdown request. This will cause existing threads to interrupt and pending threads to cancel.
          // It is highly important that the task Runnables are handling interrupts correctly.
          threadPool.shutdownNow();

          try {
            // Wait for 5s for currently running threads to terminate. Above call (threadPool.shutdownNow()) interrupts
            // any running threads. If the runnables are handling the interrupts properly they should be able to
            // wrap up and terminate. If not waiting for 5s here gives a chance to identify and log any potential
            // thread leaks.
            threadPool.awaitTermination(5, TimeUnit.SECONDS);
          } catch (final InterruptedException e) {
            logger.warn("Interrupted while waiting for pending threads in activity '{}' to terminate.", activity);
          }

          final String errMsg = String.format("Waited for %dms, but tasks for '%s' are not complete. " +
              "Total runnable size %d, parallelism %d.", timeout, activity, runnables.size(), parallelism);
          logger.error(errMsg);
          throw UserException.resourceError()
              .message(errMsg)
              .build(logger);
        }
      } finally {
        if (!threadPool.isShutdown()) {
          threadPool.shutdown();
        }
      }
    }

    List values = Lists.newArrayList();
    long sum = 0;
    long max = 0;
    long count = 0;
    // measure thread creation times
    long earliestStart=Long.MAX_VALUE;
    long latestStart=0;
    long totalStart=0;
    IOException excep = null;
    for(final TimedRunnable reader : runnables){
      try{
        values.add(reader.getValue());
        sum += reader.getTimeSpentNanos();
        count++;
        max = Math.max(max, reader.getTimeSpentNanos());
        earliestStart=Math.min(earliestStart, reader.getThreadStart() - timedRunnableStart);
        latestStart=Math.max(latestStart, reader.getThreadStart()-timedRunnableStart);
        totalStart+=latestStart=Math.max(latestStart, reader.getThreadStart()-timedRunnableStart);
      }catch(IOException e){
        if(excep == null){
          excep = e;
        }else{
          excep.addSuppressed(e);
        }
      }
    }

    if(logger.isInfoEnabled()){
      double avg = (sum/1000.0/1000.0)/(count*1.0d);
      double avgStart = (totalStart/1000.0)/(count*1.0d);

      logger.info(
          String.format("%s: Executed %d out of %d using %d threads. "
              + "Time: %dms total, %fms avg, %dms max.",
              activity, count, runnables.size(), parallelism, watch.elapsed(TimeUnit.MILLISECONDS), avg, max/1000/1000));
      logger.info(
              String.format("%s: Executed %d out of %d using %d threads. "
                              + "Earliest start: %f \u03BCs, Latest start: %f \u03BCs, Average start: %f \u03BCs .",
                      activity, count, runnables.size(), parallelism, earliestStart/1000.0, latestStart/1000.0, avgStart));
    }

    if(excep != null) {
      throw excep;
    }

    return values;

  }
}