src.it.unimi.dsi.logging.ProgressLogger Maven / Gradle / Ivy
Show all versions of dsiutils Show documentation
package it.unimi.dsi.logging;
/*
* DSI utilities
*
* Copyright (C) 2005-2016 Sebastiano Vigna
*
* This library is free software; you can redistribute it and/or modify it
* under the terms of the GNU Lesser General Public License as published by the Free
* Software Foundation; either version 3 of the License, or (at your option)
* any later version.
*
* This library is distributed in the hope that it will be useful, but
* WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY
* or FITNESS FOR A PARTICULAR PURPOSE. See the GNU Lesser General Public License
* for more details.
*
* You should have received a copy of the GNU Lesser General Public License
* along with this program; if not, see This class provides a simple way to log progress information about long-lasting activities. While originally
* based on Log4J 1.2, it is currently based on SLF4J.
*
*
To use this class, you first create a new instance by passing an
* {@linkplain #ProgressLogger(Logger,long,TimeUnit,String) SLF4J logger, a time interval and a name for the items that are being logged}.
* Information will be logged about the current state of affairs no more often than the given
* time interval. Note that the {@linkplain #itemsName name of the logged items} can be changed at any time.
*
*
To log the progress of an activity, you call {@link #start(CharSequence)} at the beginning, which will
* display the given string. Then, each time you want to mark progress, you call usually {@link #update()} or {@link #lightUpdate()}.
* The latter methods increase the item counter, and will log progress information if enough time
* has passed since the last log (and if the counter is a multiple of {@link #LIGHT_UPDATE_MASK} + 1, in the case of {@link #lightUpdate()}).
* Other update methods (e.g., {@link #update(long)}, {@link #updateAndDisplay()}, …) make the update and display process very flexible.
*
* When the activity is over, you call {@link #stop()}. At that point, the method {@link #toString()} returns
* information about the internal state of the logger (elapsed time, number of items per second) that
* can be printed or otherwise processed. If {@link #update()} has never been called, you will just
* get the elapsed time. By calling {@link #done()} instead of stop, this information will be logged for you.
*
*
Additionally:
*
* - by setting the {@linkplain #expectedUpdates expected amount of updates} before
* calling {@link #start()} you can get some estimations on the completion time;
*
- by setting {@link #displayFreeMemory} you can display information about the
* memory usage;
*
- by setting {@link #displayLocalSpeed} you can display, beside the average speed since
* the start of the activity, the speed since the last log;
*
- by setting {@link #info} you can display arbitrary additional information.
*
- by setting {@link #speedTimeUnit} and {@link #itemTimeUnit} you can fix the time unit
* used to measure the speed and the time per item.
*
*
* After you finished a run of the progress logger,
* you can change its attributes and call {@link #start()} again
* to measure another activity.
*
*
A typical call sequence to a progress logger is as follows:
*
* ProgressLogger pl = new ProgressLogger( logger, 1, TimeUnit.MINUTES );
* pl.start( "Smashing pumpkins..." );
* ... activity on pumpkins that calls update() on each pumpkin ...
* pl.done();
*
*
* A more flexible behaviour can be obtained at the end of the
* process by calling {@link #stop()}:
*
* ProgressLogger pl = new ProgressLogger( logger, 1, TimeUnit.MINUTES, "pumpkins" );
* pl.start( "Smashing pumpkins..." );
* ... activity on pumpkins that calls update() on each pumpkin ...
* pl.stop( "Really done!" );
* pl.logger.info( pl.toString() );
*
*
* An instance of this class can also be used as a handy timer:
*
* ProgressLogger pl = new ProgressLogger();
* pl.start( "Smashing pumpkins..." );
* ... activity on pumpkins (no update() calls) ...
* pl.done( howManyPumpkins );
*
*
* Should you need to display additional information, you can set the field {@link #info} to any
* object: it will be printed just after the timing (and possibly memory) information.
*
* @author Sebastiano Vigna
* @since 0.9.3
*/
public final class ProgressLogger {
public final static long ONE_SECOND = 1000;
public final static long TEN_SECONDS = 10 * ONE_SECOND;
public final static long ONE_MINUTE = ONE_SECOND * 60;
public final static long TEN_MINUTES = ONE_MINUTE * 10;
public final static long ONE_HOUR = ONE_MINUTE * 60;
public final static long DEFAULT_LOG_INTERVAL = TEN_SECONDS;
/** An array of pattern defining rules that turn plural into singular (the corresponding replacement string is in the same position in {@link #SINGULAR}).
* More specific rules are at the end of the array (and should be tested first). */
private static final Pattern[] PLURAL = {
Pattern.compile( "s$" ),
Pattern.compile( "(s|si|u)s$" ),
Pattern.compile( "(n)ews$" ),
Pattern.compile( "([ti])a$" ),
Pattern.compile( "((a)naly|(b)a|(d)iagno|(p)arenthe|(p)rogno|(s)ynop|(t)he)ses$" ),
Pattern.compile( "(^analy)ses$" ),
Pattern.compile( "(^analy)sis$" ),
Pattern.compile( "([^f])ves$" ),
Pattern.compile( "(hive)s$" ),
Pattern.compile( "(tive)s$" ),
Pattern.compile( "([lr])ves$" ),
Pattern.compile( "([^aeiouy]|qu)ies$" ),
Pattern.compile( "(s)eries$" ),
Pattern.compile( "(m)ovies$" ),
Pattern.compile( "(x|ch|ss|sh)es$" ),
Pattern.compile( "([m|l])ice$" ),
Pattern.compile( "(bus)es$" ),
Pattern.compile( "(o)es$" ),
Pattern.compile( "(shoe)s$" ),
Pattern.compile( "(cris|ax|test)is$" ),
Pattern.compile( "(cris|ax|test)es$" ),
Pattern.compile( "(octop|vir)i$" ),
Pattern.compile( "(octop|vir)us$" ),
Pattern.compile( "(alias|status)es$" ),
Pattern.compile( "(alias|status)$" ),
Pattern.compile( "^(ox)en" ),
Pattern.compile( "(vert|ind)ices$" ),
Pattern.compile( "(matr)ices$" ),
Pattern.compile( "(quiz)zes$" ),
Pattern.compile( "^people$" ),
Pattern.compile( "^men$" ),
Pattern.compile( "^women$" ),
Pattern.compile( "^children$" ),
Pattern.compile( "^sexes$" ),
Pattern.compile( "^moves$" ),
Pattern.compile( "^stadiums$" )
};
/** Replacement strings for {@link #PLURAL}'s patterns. */
private static final String[] SINGULAR = {
"",
"$1s",
"$1ews",
"$1um",
"$1$2sis",
"$1sis",
"$1sis",
"$1fe",
"$1",
"$1",
"$1f",
"$1y",
"$1eries",
"$1ovie",
"$1",
"$1ouse",
"$1",
"$1",
"$1",
"$1is",
"$1is",
"$1us",
"$1us",
"$1",
"$1",
"$1",
"$1ex",
"$1ix",
"$1",
"person",
"man",
"woman",
"child",
"sex",
"move",
"stadium"
};
/** Calls to {@link #lightUpdate()} will cause a call to
* {@link System#currentTimeMillis()} only if the current value of {@link #count}
* is a multiple of this mask plus one. */
public final int LIGHT_UPDATE_MASK = ( 1 << 10 ) - 1;
/** The SLF4J logger used by this progress logger. */
public final Logger logger;
/** The time interval for a new log in milliseconds. Can be set at any time (e.g., using {@link TimeUnit#toMillis(long)}). */
public long logInterval;
/** If non-{@code null}, this object will be printed after the timing information. */
public Object info;
/** The number of calls to {@link #update()} since the last {@link #start()} (but it be changed also with {@link #update(long)} and {@link #set(long)}). */
public long count;
/** The value of {@link #count} at the last call to {@link #updateInternal(long)} (i.e., at the last output). */
private long lastCount;
/** The number of expected calls to {@link #update()} (used to compute the percentages, ignored if negative). */
public long expectedUpdates;
/** The name of several counted items. */
public String itemsName;
/** Whether to display the free memory at each progress log (default: false). */
public boolean displayFreeMemory;
/** Whether to display additionally the local speed, that is, the detected speed between two consecutive logs, as opposed to the average speed since {@link #start()} (default: false). */
public boolean displayLocalSpeed;
/** A fixed time unit for printing the speed. If {@code null}, {@link ProgressLogger} will choose a time unit that
* is easy to understand. In some cases (e.g., machine-parsed logs) you might want to have always the speed in
* items per {@linkplain TimeUnit#SECONDS seconds}, {@linkplain TimeUnit#MINUTES minues}, {@linkplain TimeUnit#HOURS hours} or {@linkplain TimeUnit#DAYS days}. */
public TimeUnit speedTimeUnit;
/** A fixed time unit for printing the timing of an item. If {@code null}, {@link ProgressLogger} chooses a unit that
* is easy to understand. In some cases (e.g., machine-parsed logs) you might want to have always have the time for
* an item in {@linkplain TimeUnit#NANOSECONDS nanoseconds}, {@linkplain TimeUnit#MICROSECONDS milliseconds}, {@linkplain TimeUnit#MILLISECONDS milliseconds}, {@linkplain TimeUnit#SECONDS seconds}, {@linkplain TimeUnit#MINUTES minutes} or {@linkplain TimeUnit#HOURS hours}. */
public TimeUnit itemTimeUnit;
/** The name of a single counted item, computed by {@link #singularize()} on {@link #referenceItemsName} and cached (we want to avoid a costly scan of
* {@link #SINGULAR}'s patterns at every output). */
private String itemName;
/** The value of {@link #itemsName} for which {@link #itemName} is valid. */
private String referenceItemsName;
/** The time at the last call to {@link #start()}. */
private long startTime;
/** The time at the last call to {@link #stop()}. */
private long stopTime;
/** The time of the last log. */
private long lastLogTime;
/** Creates a new progress logger using items as items name and logging every
* {@value #DEFAULT_LOG_INTERVAL} milliseconds
* to the {@linkplain Logger#ROOT_LOGGER_NAME root logger}.
*/
public ProgressLogger() {
this( LoggerFactory.getLogger( Logger.ROOT_LOGGER_NAME ) );
}
/** Creates a new progress logger logging every {@value #DEFAULT_LOG_INTERVAL} milliseconds
* to the {@linkplain Logger#ROOT_LOGGER_NAME root logger}.
*
* @param itemsName a plural name denoting the counted items.
*/
public ProgressLogger( final String itemsName ) {
this( LoggerFactory.getLogger( Logger.ROOT_LOGGER_NAME ), itemsName );
}
/** Creates a new progress logger using items as items name and logging every {@value #DEFAULT_LOG_INTERVAL} milliseconds.
*
* @param logger the logger to which messages will be sent.
*/
public ProgressLogger( final Logger logger ) {
this( logger, DEFAULT_LOG_INTERVAL, TimeUnit.MILLISECONDS );
}
/** Creates a new progress logger logging every {@value #DEFAULT_LOG_INTERVAL} milliseconds.
*
* @param logger the logger to which messages will be sent.
* @param itemsName a plural name denoting the counted items.
*/
public ProgressLogger( final Logger logger, final String itemsName ) {
this( logger, DEFAULT_LOG_INTERVAL, TimeUnit.MILLISECONDS, itemsName );
}
/** Creates a new progress logger using items as items name.
*
* @param logger the logger to which messages will be sent.
* @param logInterval the logging interval.
* @param timeUnit the unit of time of {@code logInterval}.
*/
public ProgressLogger( final Logger logger, final long logInterval, final TimeUnit timeUnit ) {
this( logger, logInterval, timeUnit, "items" );
}
/** Creates a new progress logger.
*
* @param logger the logger to which messages will be sent.
* @param logInterval the logging interval.
* @param timeUnit the unit of time of {@code logInterval}.
* @param itemsName a plural name denoting the counted items.
*/
public ProgressLogger( final Logger logger, final long logInterval, final TimeUnit timeUnit, final String itemsName ) {
this.logger = logger;
this.logInterval = timeUnit.toMillis( logInterval );
this.itemsName = itemsName;
this.expectedUpdates = -1;
}
/** The SLF4J logger
* used by this progress logger; it just returns the content of the field {@link #logger}. */
public Logger logger() {
return logger;
}
private final String itemName() {
if ( referenceItemsName == itemsName ) return itemName;
referenceItemsName = itemsName;
for( int i = PLURAL.length; i-- != 0; ) {
final Matcher matcher = PLURAL[ i ].matcher( itemsName );
if ( matcher.find() ) return itemName = matcher.replaceFirst( SINGULAR[ i ] );
}
return itemName = itemsName;
}
/** Updates the internal count of this progress logger by adding one; if enough time has passed since the
* last log, information will be logged.
*
*
This method is kept intentionally short (it delegates most of the work to an internal
* private method) so to suggest inlining. However, it performs a call to {@link System#currentTimeMillis()}
* that takes microseconds (not nanoseconds). If you plan on calling this method more than a
* few thousands times per second, you should use {@link #lightUpdate()}.
*/
public void update() {
update( 1 );
}
/** Updates the internal count of this progress logger by adding a specified value; if enough time has passed since the
* last log, information will be logged.
*
* @see #update()
*/
public void update( final long count ) {
this.count += count;
final long time = System.currentTimeMillis();
if ( time - lastLogTime >= logInterval ) updateInternal( time );
}
/** Updates the internal count of this progress logger by adding one, forcing a display.
*
* @see #update()
*/
public void updateAndDisplay() {
updateAndDisplay( 1 );
}
/** Sets the internal count of this progress logger to a specified value; if enough time has passed since the
* last log, information will be logged.
*
* @see #update()
*/
public void set( final long count ) {
this.count = count;
final long time = System.currentTimeMillis();
if ( time - lastLogTime >= logInterval ) updateInternal( time );
}
/** Sets the internal count of this progress logger to a specified value, forcing a display.
*
* @see #update()
*/
public void setAndDisplay( final long count ) {
this.count = count;
updateInternal( System.currentTimeMillis() );
}
/** Updates the internal count of this progress logger by adding a specified value, forcing a display.
*
* @see #update()
*/
public void updateAndDisplay( final long count ) {
this.count += count;
updateInternal( System.currentTimeMillis() );
}
private String freeMemory() {
return ( displayFreeMemory ? "; used/avail/free/total/max mem: "
+ Util.formatSize( RUNTIME.totalMemory() - RUNTIME.freeMemory() ) + "/"
+ Util.formatSize( RUNTIME.freeMemory() + ( RUNTIME.maxMemory() - RUNTIME.totalMemory() ) ) + "/"
+ Util.formatSize( RUNTIME.freeMemory() ) + "/"
+ Util.formatSize( RUNTIME.totalMemory() ) + "/"
+ Util.formatSize( RUNTIME.maxMemory() ) : "" );
}
private String itemsPerTimeInterval( long startCount, final long currentTime, long baseTime ) {
final double secondsPerItem = ( ( count - startCount ) * 1000.0 ) / ( currentTime - baseTime );
if ( speedTimeUnit == TimeUnit.SECONDS || speedTimeUnit == null && secondsPerItem >= 1 ) return Util.format( secondsPerItem ) + " " + itemsName + "/s";
if ( speedTimeUnit == TimeUnit.MINUTES || speedTimeUnit == null && secondsPerItem * 60 >= 1 ) return Util.format( secondsPerItem * 60 ) + " " + itemsName + "/m";
if ( speedTimeUnit == TimeUnit.HOURS || speedTimeUnit == null && secondsPerItem * 3600 >= 1 ) return Util.format( secondsPerItem * 3600 ) + " " + itemsName + "/h";
return Util.format( secondsPerItem * 86400 ) + " " + itemsName + "/d";
}
private String timePerItem( long startCount, final long currentTime, long baseTime ) {
final double secondsPerItem = ( currentTime - baseTime ) / ( ( count - startCount ) * 1000.0 );
if ( itemTimeUnit == null && secondsPerItem >= 86400 ) return Util.format( secondsPerItem / 86400 ) + " d/" + itemName();
if ( itemTimeUnit == TimeUnit.HOURS || itemTimeUnit == null && secondsPerItem >= 3600 ) return Util.format( secondsPerItem / 3600 ) + " h/" + itemName();
if ( itemTimeUnit == TimeUnit.MINUTES || itemTimeUnit == null && secondsPerItem >= 60 ) return Util.format( secondsPerItem / 60 ) + " m/" + itemName();
if ( itemTimeUnit == TimeUnit.SECONDS || itemTimeUnit == null && secondsPerItem >= 1 ) return Util.format( secondsPerItem ) + " s/" + itemName();
if ( itemTimeUnit == TimeUnit.MILLISECONDS || itemTimeUnit == null && secondsPerItem >= 1E-3 ) return Util.format( secondsPerItem * 1E3 ) + " ms/" + itemName();
if ( itemTimeUnit == TimeUnit.MICROSECONDS || itemTimeUnit == null && secondsPerItem >= 1E-6 ) return Util.format( secondsPerItem * 1E6 ) + " \u00b5s/" + itemName();
return Util.format( secondsPerItem * 1E9 ) + " ns/" + itemName();
}
private void updateInternal( final long currentTime ) {
final long millisToEnd = Math.round( ( expectedUpdates - count ) * ( ( currentTime - startTime ) / ( count + 1.0 ) ) );
// Formatting is expensive, so we check for actual logging.
if ( logger().isInfoEnabled() )
logger().info( Util.format( count ) + " " + itemsName + ", " +
millis2hms( millis() ) + ", " + itemsPerTimeInterval( 0, currentTime, startTime ) + ", " + timePerItem( 0, currentTime, startTime ) +
( displayLocalSpeed ? " [" + itemsPerTimeInterval( lastCount, currentTime, lastLogTime ) + ", " + timePerItem( lastCount, currentTime, lastLogTime ) + "]" : "" ) +
( expectedUpdates > 0 ? "; " + Util.format( ( 100 * count ) / expectedUpdates ) + "% done, " +
millis2hms( millisToEnd ) + " to end" : "" ) + freeMemory() + ( info != null ? "; " + info : "" ) );
lastLogTime = currentTime;
lastCount = count;
return;
}
/** Updates the internal count of this progress logger by adding one in a lightweight fashion.
*
*
This call updates the progress logger internal counter as {@link #update()}. However,
* it will actually call {@link System#currentTimeMillis()} only if the new {@link #count}
* is a multiple of {@link #LIGHT_UPDATE_MASK} + 1. This mechanism makes it possible to reduce the number of
* calls to {@link System#currentTimeMillis()} significantly.
*
*
This method is useful when the operations being counted take less than a few microseconds.
*
* @see #update()
*/
public final void lightUpdate() {
if ( ( ++count & LIGHT_UPDATE_MASK ) == 0 ) {
final long time = System.currentTimeMillis();
if ( time - lastLogTime >= logInterval ) updateInternal( time );
}
}
/** Starts the progress logger, resetting the count.*/
public void start() {
start( null, 0 );
}
/** Starts the progress logger, displaying a message and resetting the count.
*
* @param message the message to display.
*/
public void start( final CharSequence message ) {
start( message, 0 );
}
/** Starts the progress logger, resetting the count and assuming that a given amount of time has already passed.
*
* @param alreadyElapsed the number of milliseconds already elapsed.
* @see #start(CharSequence, long)
*/
public void start( final long alreadyElapsed ) {
start( null, alreadyElapsed );
}
/** Starts the progress logger, displaying a message, resetting the count and assuming that a given amount of time has already passed.
*
*
The effect of the {@code alreadyElapsed} parameter is that the start time of this {@link ProgressLogger} will be
* set to {@link System#currentTimeMillis()} minus {@code alreadyElapsed}.
*
* @param message the message to display.
* @param alreadyElapsed the number of milliseconds already elapsed.
*/
public void start( final CharSequence message, final long alreadyElapsed ) {
if ( message != null ) logger().info( message.toString() );
startTime = ( lastLogTime = System.currentTimeMillis() ) - alreadyElapsed;
lastCount = count = 0;
stopTime = -1;
}
/** Stops the progress logger, displaying a message.
*
*
This method will also mark {@link #expectedUpdates} as invalid,
* to avoid erroneous reuses of previous values.
*
* @param message the message to display.
*/
public void stop( final CharSequence message ) {
if ( stopTime != -1 ) return;
if ( message != null ) logger().info( message.toString() );
stopTime = System.currentTimeMillis();
expectedUpdates = -1;
}
/** Stops the progress logger. */
public void stop() { stop( null ); }
/** Completes a run of this progress logger, logging “Completed.” and the logger itself. */
public void done() {
stop( "Completed." );
logger().info( toString() );
}
/** Completes a run of this progress logger and sets the internal counter, logging “Completed.” and the logger itself.
*
*
This method is particularly useful in two circumstances:
*
* - you have updated the logger with some approximate values (e.g., in a multicore computation) but before
* printing the final statistics you want the internal counter to contain an exact value;
*
- you have used the logger as a handy timer, calling just {@link #start()} and this method.
*
*
* @param count will replace the internal counter value.
*/
public void done( long count ) {
this.count = count;
stop( "Completed." );
logger().info( toString() );
}
/** Returns the number of milliseconds between present time and the last call to {@link #start()}, if
* this progress logger is running, or between the last call to {@link #stop()} and the last call to {@link #start()}, if this
* progress logger is stopped.
*
* @return the number of milliseconds between present time and the last call to {@link #start()}, if
* this progress logger is running, or between the last call to {@link #stop()} and the last call to {@link #start()}, if this
* progress logger is stopped.
*/
public long millis() {
if ( stopTime != -1 ) return stopTime - startTime;
else return System.currentTimeMillis() - startTime;
}
private String millis2hms( final long t ) {
if ( t < 1000 ) return t + "ms";
final long s = ( t / 1000 ) % 60;
final long m = ( ( t / 1000 ) / 60 ) % 60;
final long h = t / ( 3600 * 1000 );
if ( h == 0 && m == 0 ) return s + "s";
if ( h == 0 ) return m + "m " + s + "s";
return h + "h " + m + "m " + s + "s";
}
/** Converts the data currently stored in this progress logger to a string.
*
* If this progress logger has been {@linkplain #stop() stopped}, statistics
* are computed using the stop time. Otherwise, they are computed using the current time (i.e., the method call time).
*
* @return the current data in this progress logger in a printable form.
*/
public String toString() {
final long t = ( stopTime != -1 ? stopTime : System.currentTimeMillis() ) - startTime + 1 ;
if ( t <= 0 ) return "Illegal progress logger state";
return "Elapsed: " + millis2hms( t ) + ( count != 0 ? " [" + Util.format( count ) + " " + itemsName + ", " + itemsPerTimeInterval( 0, stopTime, startTime ) + ", " + timePerItem( 0, stopTime, startTime ) + "]" : "" ) + freeMemory();
}
}