/* * Copyright 2012 Google Inc. * * Licensed 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 com.google.gwt.dev.javac; import com.google.gwt.core.ext.TreeLogger; import java.util.concurrent.TimeUnit; /** * Logs progress of an operation, attempting to calculate an estimated time remaining (ETR) for * the entire operation for each log entry, assuming that progress is approximately linear. */ class ProgressLogger { /** * An interface for retrieving nanosecond times, useable ONLY for deltas. */ interface NanoSource { /** * Returns a number of nanoseconds. Subtracting the results of two invocations of this method * yields the approximate number of nanoseconds between the invocations. */ long getNanos(); } // Constant for dividing nanosecond time intervals by to get second time intervals. It is a double // in order to allow fractional seconds. private static final long NANOSECONDS_IN_SECOND = TimeUnit.SECONDS.toNanos(1); // The minimum amount of progress that must be made before an ETR is calculated (where 1.0 is // 100%). If this is too low, then early, inaccurate estimates will be shown. private static final double ETR_ACCURACY_THRESHOLD = 0.05; // The number of seconds before which no log is shown. This reduces log spam for things with // fast progress. private static final int LOG_BLACKOUT_PERIOD = 5; // The number of nanoseconds before which no log is shown. private static final long LOG_BLACKOUT_PERIOD_NANOS = LOG_BLACKOUT_PERIOD * NANOSECONDS_IN_SECOND; private final TreeLogger logger; private final TreeLogger.Type logLevel; private final int maxProgressUnits; private final int percentageIncrement; private final NanoSource nanoSource; private long startNanos = 0; private boolean timerStarted = false; private long nextPercentage = 0; /** * Creates a ProgressLogger that logs messages with log level {@code logLevel} to {@code logger}. * It will log only every {@code percentageIncrement} percent of progress, where progress is * measured from 0 to {@code maxProgressUnits}. Gets nano time offsets for ETR calculations from * {@link System#nanoTime()}. */ ProgressLogger(TreeLogger logger, TreeLogger.Type logLevel, int maxProgressUnits, int percentageIncrement) { this.logger = logger; this.logLevel = logLevel; this.maxProgressUnits = maxProgressUnits; this.percentageIncrement = percentageIncrement; this.nanoSource = new NanoSource() { @Override public long getNanos() { return System.nanoTime(); } }; } /** * Returns true if {@link #startTimer()} has been called, and false otherwise. */ boolean isTimerStarted() { return timerStarted; } /** * Sets the start time against which ETR calculations are made. */ void startTimer() { startNanos = nanoSource.getNanos(); timerStarted = true; } /** * Notifies the ProgressLogger that progress has reached {@code progressUnits}. This may cause * (depending on the ProgressLogger's settings) the emission of a log message in the form * "[PERCENT]% complete (ETR: [ESTIMATED TIME REMAINING] seconds)" in most cases, or * "[PERCENT]% complete (ETR: ?)" if not enough progress has been made to make a good estimate of * remaining time. * * Successive calls to this method should provide monotonically increasing values of * {@code progressUnits}. It does not support backwards progress. */ void updateProgress(int progressUnits) { // Only do the percentage calculation if the result would be logged. if (!logger.isLoggable(logLevel)) { return; } if (!timerStarted) { throw new IllegalStateException("#updateProgress() called before #startTimer()."); } double progress = progressUnits / (double) maxProgressUnits; double currentPercentage = 100 * progress; long elapsedNanos = nanoSource.getNanos() - startNanos; // Display the percent complete if progress has reached the // next percentage increment, or if progress is 100%. if (currentPercentage < nextPercentage && progressUnits != maxProgressUnits) { return; } // Don't log anything if < LOG_BLACKOUT_PERIOD_NANOS nanoseconds have elapsed. if (elapsedNanos < LOG_BLACKOUT_PERIOD_NANOS) { return; } // Show the largest integer multiple of the percentage increment that is less than the // actual percentage. long displayedPercentage = percentageIncrement * Math.round(Math.floor(currentPercentage / percentageIncrement)); // If progress is 100%, just show 100%. if (progressUnits == maxProgressUnits) { displayedPercentage = 100; } // Only attempt to estimate a time remaining if we have a reasonable amount of data to go // on. Otherwise the estimates are wildly misleading. if (progress >= ETR_ACCURACY_THRESHOLD) { // Do linear extrapolation to estimate the amount of time remaining. double estimatedTotalNanos = elapsedNanos / progress; double estimatedNanosRemaining = estimatedTotalNanos - elapsedNanos; // Convert nanos to seconds. double estimatedSecondsRemaining = estimatedNanosRemaining / (double) NANOSECONDS_IN_SECOND; logger.log(logLevel, String.format("%d%% complete (ETR: %d seconds)", displayedPercentage, Math.round(estimatedSecondsRemaining))); } else { // Not enough information to estimate time remaining. logger.log(logLevel, String.format("%d%% complete (ETR: ?)", displayedPercentage)); } nextPercentage += percentageIncrement; } }