Examples with Stopwatch com.google.common.base.Stopwatch used on opensource projects

Example 91 with Stopwatch

use of com.google.common.base.Stopwatch in project drill by apache.

the class MongoRecordReader method next.

@Override
public int next() {
    if (cursor == null) {
        logger.info("Filters Applied : " + filters);
        logger.info("Fields Selected :" + fields);
        cursor = collection.find(filters).projection(fields).batchSize(100).iterator();
    }
    writer.allocate();
    writer.reset();
    int docCount = 0;
    Stopwatch watch = Stopwatch.createStarted();
    try {
        while (docCount < BaseValueVector.INITIAL_VALUE_ALLOCATION && cursor.hasNext()) {
            writer.setPosition(docCount);
            if (isBsonRecordReader) {
                BsonDocument bsonDocument = cursor.next();
                bsonReader.write(writer, new BsonDocumentReader(bsonDocument));
            } else {
                String doc = cursor.next().toJson();
                jsonReader.setSource(doc.getBytes(Charsets.UTF_8));
                jsonReader.write(writer);
            }
            docCount++;
        }
        if (isBsonRecordReader) {
            bsonReader.ensureAtLeastOneField(writer);
        } else {
            jsonReader.ensureAtLeastOneField(writer);
        }
        writer.setValueCount(docCount);
        logger.debug("Took {} ms to get {} records", watch.elapsed(TimeUnit.MILLISECONDS), docCount);
        return docCount;
    } catch (IOException e) {
        String msg = "Failure while reading document. - Parser was at record: " + (docCount + 1);
        logger.error(msg, e);
        throw new DrillRuntimeException(msg, e);
    }
}

Example 92 with Stopwatch

use of com.google.common.base.Stopwatch in project drill by apache.

the class TimedRunnable method run.

/**
   * 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 <V> List<V> run(final String activity, final Logger logger, final List<TimedRunnable<V>> 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<V> 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<V> 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<V> 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 μs, Latest start: %f μs, Average start: %f μs .", activity, count, runnables.size(), parallelism, earliestStart / 1000.0, latestStart / 1000.0, avgStart));
    }
    if (excep != null) {
        throw excep;
    }
    return values;
}

Example 93 with Stopwatch

use of com.google.common.base.Stopwatch in project drill by apache.

the class DirectBufInputStream method read.

public synchronized int read(DrillBuf buf, int off, int len) throws IOException {
    buf.clear();
    ByteBuffer directBuffer = buf.nioBuffer(0, len);
    int lengthLeftToRead = len;
    while (lengthLeftToRead > 0) {
        if (logger.isTraceEnabled()) {
            logger.trace("PERF: Disk read start. {}, StartOffset: {}, TotalByteSize: {}", this.streamId, this.startOffset, this.totalByteSize);
        }
        Stopwatch timer = Stopwatch.createStarted();
        int bytesRead = CompatibilityUtil.getBuf(getInputStream(), directBuffer, lengthLeftToRead);
        lengthLeftToRead -= bytesRead;
        if (logger.isTraceEnabled()) {
            logger.trace("PERF: Disk read complete. {}, StartOffset: {}, TotalByteSize: {}, BytesRead: {}, Time: {} ms", this.streamId, this.startOffset, this.totalByteSize, bytesRead, ((double) timer.elapsed(TimeUnit.MICROSECONDS)) / 1000);
        }
    }
    buf.writerIndex(len);
    return len;
}

Example 94 with Stopwatch

use of com.google.common.base.Stopwatch in project drill by apache.

the class JdbcTestQueryBase method testQuery.

protected static void testQuery(String sql) throws Exception {
    boolean success = false;
    try (Connection conn = connect("jdbc:drill:zk=local")) {
        for (int x = 0; x < 1; x++) {
            Stopwatch watch = Stopwatch.createStarted();
            Statement s = conn.createStatement();
            ResultSet r = s.executeQuery(sql);
            System.out.println(String.format("QueryId: %s", r.unwrap(DrillResultSet.class).getQueryId()));
            boolean first = true;
            while (r.next()) {
                ResultSetMetaData md = r.getMetaData();
                if (first == true) {
                    for (int i = 1; i <= md.getColumnCount(); i++) {
                        System.out.print(md.getColumnName(i));
                        System.out.print('\t');
                    }
                    System.out.println();
                    first = false;
                }
                for (int i = 1; i <= md.getColumnCount(); i++) {
                    System.out.print(r.getObject(i));
                    System.out.print('\t');
                }
                System.out.println();
            }
            System.out.println(String.format("Query completed in %d millis.", watch.elapsed(TimeUnit.MILLISECONDS)));
        }
        System.out.println("\n\n\n");
        success = true;
    } finally {
        if (!success) {
            Thread.sleep(2000);
        }
    }
}

Example 95 with Stopwatch

use of com.google.common.base.Stopwatch in project drill by apache.

the class FMPPMojo method execute.

@Override
public void execute() throws MojoExecutionException, MojoFailureException {
    if (project == null) {
        throw new MojoExecutionException("This plugin can only be used inside a project.");
    }
    String outputPath = output.getAbsolutePath();
    if ((!output.exists() && !output.mkdirs()) || !output.isDirectory()) {
        throw new MojoFailureException("can not write to output dir: " + outputPath);
    }
    String templatesPath = templates.getAbsolutePath();
    if (!templates.exists() || !templates.isDirectory()) {
        throw new MojoFailureException("templates not found in dir: " + outputPath);
    }
    // add the output directory path to the project source directories
    switch(scope) {
        case "compile":
            project.addCompileSourceRoot(outputPath);
            break;
        case "test":
            project.addTestCompileSourceRoot(outputPath);
            break;
        default:
            throw new MojoFailureException("scope must be compile or test");
    }
    final Stopwatch sw = Stopwatch.createStarted();
    try {
        getLog().info(format("Freemarker generation:\n scope: %s,\n config: %s,\n templates: %s", scope, config.getAbsolutePath(), templatesPath));
        final File tmp = Files.createTempDirectory("freemarker-tmp").toFile();
        String tmpPath = tmp.getAbsolutePath();
        final String tmpPathNormalized = tmpPath.endsWith(File.separator) ? tmpPath : tmpPath + File.separator;
        Settings settings = new Settings(new File("."));
        settings.set(Settings.NAME_SOURCE_ROOT, templatesPath);
        settings.set(Settings.NAME_OUTPUT_ROOT, tmp.getAbsolutePath());
        settings.load(config);
        settings.addProgressListener(new TerseConsoleProgressListener());
        settings.addProgressListener(new ProgressListener() {

            @Override
            public void notifyProgressEvent(Engine engine, int event, File src, int pMode, Throwable error, Object param) throws Exception {
                if (event == EVENT_END_PROCESSING_SESSION) {
                    getLog().info(format("Freemarker generation took %dms", sw.elapsed(TimeUnit.MILLISECONDS)));
                    sw.reset();
                    Report report = moveIfChanged(tmp, tmpPathNormalized);
                    if (!tmp.delete()) {
                        throw new MojoFailureException(format("can not delete %s", tmp));
                    }
                    getLog().info(format("Incremental output update took %dms", sw.elapsed(TimeUnit.MILLISECONDS)));
                    getLog().info(format("new: %d", report.newFiles));
                    getLog().info(format("changed: %d", report.changedFiles));
                    getLog().info(format("unchanged: %d", report.unchangedFiles));
                }
            }
        });
        if (addMavenDataLoader) {
            getLog().info("Adding maven data loader");
            settings.setEngineAttribute(MavenDataLoader.MAVEN_DATA_ATTRIBUTE, new MavenData(project));
            settings.add(Settings.NAME_DATA, format("maven: %s()", MavenDataLoader.class.getName()));
        }
        settings.execute();
    } catch (Exception e) {
        throw new MojoFailureException(MiscUtil.causeMessages(e), e);
    }
}