/**
* Start up the progress meter, printing initialization message and starting up the daemon thread
* for periodic printing.
*/
@Requires("progressMeterDaemon != null")
private synchronized void start() {
timer.start();
lastProgressPrintTime = timer.currentTime();
logger.info("[INITIALIZATION COMPLETE; STARTING PROCESSING]");
logger.info(
String.format(
"%15s processed.%s runtime per.1M.%s completed total.runtime remaining",
"Location", processingUnitName, processingUnitName));
progressMeterDaemon.start();
}
/** Should be called when processing is done */
public void notifyDone(final long nTotalRecordsProcessed) {
// print out the progress meter
this.nTotalRecordsProcessed = nTotalRecordsProcessed;
this.positionMessage = "done";
printProgress(true);
logger.info(
String.format(
"Total runtime %.2f secs, %.2f min, %.2f hours",
timer.getElapsedTime(), timer.getElapsedTime() / 60, timer.getElapsedTime() / 3600));
if (performanceLog != null) performanceLog.close();
// shutdown our daemon thread
progressMeterDaemon.done();
}
/**
* Creates a new ProgressData object recording a snapshot of our progress at this instant
*
* @param loc our current position. If null, assumes we are done traversing
* @param nTotalRecordsProcessed the total number of records we've processed
* @return
*/
private ProgressMeterData takeProgressSnapshot(
final GenomeLoc loc, final long nTotalRecordsProcessed) {
// null -> end of processing
final long bpProcessed =
loc == null ? targetSizeInBP : regionsBeingProcessed.sizeBeforeLoc(loc);
return new ProgressMeterData(timer.getElapsedTime(), nTotalRecordsProcessed, bpProcessed);
}
/**
* Actually try to print out progress
*
* <p>This function may print out if the progress print is due, but if not enough time has elapsed
* since the last print we will not print out information.
*
* @param mustPrint if true, progress will be printed regardless of the last time we printed
* progress
*/
protected synchronized void printProgress(final boolean mustPrint) {
final long curTime = timer.currentTime();
final boolean printProgress =
mustPrint
|| maxElapsedIntervalForPrinting(
curTime, lastProgressPrintTime, progressPrintFrequency);
final boolean printLog =
performanceLog != null
&& maxElapsedIntervalForPrinting(
curTime, lastPerformanceLogPrintTime, PERFORMANCE_LOG_PRINT_FREQUENCY);
if (printProgress || printLog) {
final ProgressMeterData progressData =
takeProgressSnapshot(maxGenomeLoc, nTotalRecordsProcessed);
final AutoFormattingTime elapsed = new AutoFormattingTime(progressData.getElapsedSeconds());
final AutoFormattingTime bpRate = new AutoFormattingTime(progressData.secondsPerMillionBP());
final AutoFormattingTime unitRate =
new AutoFormattingTime(progressData.secondsPerMillionElements());
final double fractionGenomeTargetCompleted =
progressData.calculateFractionGenomeTargetCompleted(targetSizeInBP);
final AutoFormattingTime estTotalRuntime =
new AutoFormattingTime(elapsed.getTimeInSeconds() / fractionGenomeTargetCompleted);
final AutoFormattingTime timeToCompletion =
new AutoFormattingTime(estTotalRuntime.getTimeInSeconds() - elapsed.getTimeInSeconds());
if (printProgress) {
lastProgressPrintTime = curTime;
updateLoggerPrintFrequency(estTotalRuntime.getTimeInSeconds());
logger.info(
String.format(
"%15s %5.2e %s %s %5.1f%% %s %s",
positionMessage,
progressData.getUnitsProcessed() * 1.0,
elapsed,
unitRate,
100 * fractionGenomeTargetCompleted,
estTotalRuntime,
timeToCompletion));
}
if (printLog) {
lastPerformanceLogPrintTime = curTime;
performanceLog.printf(
"%.2f\t%d\t%.2e\t%d\t%.2e\t%.2e\t%.2f\t%.2f%n",
elapsed.getTimeInSeconds(),
progressData.getUnitsProcessed(),
unitRate.getTimeInSeconds(),
progressData.getBpProcessed(),
bpRate.getTimeInSeconds(),
fractionGenomeTargetCompleted,
estTotalRuntime.getTimeInSeconds(),
timeToCompletion.getTimeInSeconds());
}
}
}
/** @return the current runtime in nanoseconds */
@Ensures("result >= 0")
public long getRuntimeInNanoseconds() {
return timer.getElapsedTimeNano();
}