BatchingProgressMonitor: expose time spent per task

Display elapsed time per task if enabled via
ProgressMonitor#showDuration or if system property or environment
variable GIT_TRACE_PERFORMANCE is set to "true". If both the system
property and the environment variable are set the system property takes
precedence.

E.g. using jgit CLI:

$ GIT_TRACE_PERFORMANCE=true jgit clone https://foo.bar/foobar
Cloning into 'foobar'...
remote: Counting objects: 1 [0.002s]
remote: Finding sources: 100% (15531/15531) [0.006s]
Receiving objects:      100% (169737/169737) [13.045s]
Resolving deltas:       100% (67579/67579) [1.842s]

Change-Id: I4d624e7858b286aeddbe7d4e557589986d73659e

8 files changed, 175 insertions, 33 deletions

diff --git a/org.eclipse.jgit/src/org/eclipse/jgit/lib/BatchingProgressMonitor.java b/org.eclipse.jgit/src/org/eclipse/jgit/lib/BatchingProgressMonitor.java
index 49e295aed8..f826057370 100644
--- a/org.eclipse.jgit/src/org/eclipse/jgit/lib/BatchingProgressMonitor.java
+++ b/org.eclipse.jgit/src/org/eclipse/jgit/lib/BatchingProgressMonitor.java
@@ -10,21 +10,29 @@
 
 package org.eclipse.jgit.lib;
 
+import java.time.Duration;
+import java.time.Instant;
 import java.util.concurrent.Future;
 import java.util.concurrent.TimeUnit;
 
 import org.eclipse.jgit.lib.internal.WorkQueue;
+import org.eclipse.jgit.util.SystemReader;
 
 /**
  * ProgressMonitor that batches update events.
  */
 public abstract class BatchingProgressMonitor implements ProgressMonitor {
+	private static boolean performanceTrace = SystemReader.getInstance()
+			.isPerformanceTraceEnabled();
+
 	private long delayStartTime;
 
 	private TimeUnit delayStartUnit = TimeUnit.MILLISECONDS;
 
 	private Task task;
 
+	private Boolean showDuration;
+
 	/**
 	 * Set an optional delay before the first output.
 	 *
@@ -76,6 +84,11 @@ public abstract class BatchingProgressMonitor implements ProgressMonitor {
 		return false;
 	}
 
+	@Override
+	public void showDuration(boolean enabled) {
+		showDuration = Boolean.valueOf(enabled);
+	}
+
 	/**
 	 * Update the progress monitor if the total work isn't known,
 	 *
@@ -83,8 +96,12 @@ public abstract class BatchingProgressMonitor implements ProgressMonitor {
 	 *            name of the task.
 	 * @param workCurr
 	 *            number of units already completed.
+	 * @param duration
+	 *            how long this task runs
+	 * @since 6.5
 	 */
-	protected abstract void onUpdate(String taskName, int workCurr);
+	protected abstract void onUpdate(String taskName, int workCurr,
+			Duration duration);
 
 	/**
 	 * Finish the progress monitor when the total wasn't known in advance.
@@ -93,8 +110,12 @@ public abstract class BatchingProgressMonitor implements ProgressMonitor {
 	 *            name of the task.
 	 * @param workCurr
 	 *            total number of units processed.
+	 * @param duration
+	 *            how long this task runs
+	 * @since 6.5
 	 */
-	protected abstract void onEndTask(String taskName, int workCurr);
+	protected abstract void onEndTask(String taskName, int workCurr,
+			Duration duration);
 
 	/**
 	 * Update the progress monitor when the total is known in advance.
@@ -107,9 +128,12 @@ public abstract class BatchingProgressMonitor implements ProgressMonitor {
 	 *            estimated number of units to process.
 	 * @param percentDone
 	 *            {@code workCurr * 100 / workTotal}.
+	 * @param duration
+	 *            how long this task runs
+	 * @since 6.5
 	 */
 	protected abstract void onUpdate(String taskName, int workCurr,
-			int workTotal, int percentDone);
+			int workTotal, int percentDone, Duration duration);
 
 	/**
 	 * Finish the progress monitor when the total is known in advance.
@@ -122,9 +146,58 @@ public abstract class BatchingProgressMonitor implements ProgressMonitor {
 	 *            estimated number of units to process.
 	 * @param percentDone
 	 *            {@code workCurr * 100 / workTotal}.
+	 * @param duration
+	 *            duration of the task
+	 * @since 6.5
 	 */
 	protected abstract void onEndTask(String taskName, int workCurr,
-			int workTotal, int percentDone);
+			int workTotal, int percentDone, Duration duration);
+
+	private boolean showDuration() {
+		return showDuration != null ? showDuration.booleanValue()
+				: performanceTrace;
+	}
+
+	/**
+	 * Append formatted duration if system property or environment variable
+	 * GIT_TRACE_PERFORMANCE is set to "true". If both are defined the system
+	 * property takes precedence.
+	 *
+	 * @param s
+	 *            StringBuilder to append the formatted duration to
+	 * @param duration
+	 *            duration to format
+	 * @since 6.5
+	 */
+	@SuppressWarnings({ "boxing", "nls" })
+	protected void appendDuration(StringBuilder s, Duration duration) {
+		if (!showDuration()) {
+			return;
+		}
+		long hours = duration.toHours();
+		int minutes = duration.toMinutesPart();
+		int seconds = duration.toSecondsPart();
+		s.append(" [");
+		if (hours > 0) {
+			s.append(hours).append(':');
+			s.append(String.format("%02d", minutes)).append(':');
+			s.append(String.format("%02d", seconds));
+		} else if (minutes > 0) {
+			s.append(minutes).append(':');
+			s.append(String.format("%02d", seconds));
+		} else {
+			s.append(seconds);
+		}
+		s.append('.').append(String.format("%03d", duration.toMillisPart()));
+		if (hours > 0) {
+			s.append('h');
+		} else if (minutes > 0) {
+			s.append('m');
+		} else {
+			s.append('s');
+		}
+		s.append(']');
+	}
 
 	private static class Task implements Runnable {
 		/** Title of the current task. */
@@ -148,10 +221,13 @@ public abstract class BatchingProgressMonitor implements ProgressMonitor {
 		/** Percentage of {@link #totalWork} that is done. */
 		private int lastPercent;
 
+		private final Instant startTime;
+
 		Task(String taskName, int totalWork) {
 			this.taskName = taskName;
 			this.totalWork = totalWork;
 			this.display = true;
+			this.startTime = Instant.now();
 		}
 
 		void delay(long time, TimeUnit unit) {
@@ -170,7 +246,7 @@ public abstract class BatchingProgressMonitor implements ProgressMonitor {
 			if (totalWork == UNKNOWN) {
 				// Only display once per second, as the alarm fires.
 				if (display) {
-					pm.onUpdate(taskName, lastWork);
+					pm.onUpdate(taskName, lastWork, elapsedTime());
 					output = true;
 					restartTimer();
 				}
@@ -178,12 +254,14 @@ public abstract class BatchingProgressMonitor implements ProgressMonitor {
 				// Display once per second or when 1% is done.
 				int currPercent = Math.round(lastWork * 100F / totalWork);
 				if (display) {
-					pm.onUpdate(taskName, lastWork, totalWork, currPercent);
+					pm.onUpdate(taskName, lastWork, totalWork, currPercent,
+							elapsedTime());
 					output = true;
 					restartTimer();
 					lastPercent = currPercent;
 				} else if (currPercent != lastPercent) {
-					pm.onUpdate(taskName, lastWork, totalWork, currPercent);
+					pm.onUpdate(taskName, lastWork, totalWork, currPercent,
+							elapsedTime());
 					output = true;
 					lastPercent = currPercent;
 				}
@@ -199,14 +277,18 @@ public abstract class BatchingProgressMonitor implements ProgressMonitor {
 		void end(BatchingProgressMonitor pm) {
 			if (output) {
 				if (totalWork == UNKNOWN) {
-					pm.onEndTask(taskName, lastWork);
+					pm.onEndTask(taskName, lastWork, elapsedTime());
 				} else {
 					int currPercent = Math.round(lastWork * 100F / totalWork);
-					pm.onEndTask(taskName, lastWork, totalWork, currPercent);
+					pm.onEndTask(taskName, lastWork, totalWork, currPercent, elapsedTime());
 				}
 			}
 			if (timerFuture != null)
 				timerFuture.cancel(false /* no interrupt */);
 		}
+
+		private Duration elapsedTime() {
+			return Duration.between(startTime, Instant.now());
+		}
 	}
 }
diff --git a/org.eclipse.jgit/src/org/eclipse/jgit/lib/EmptyProgressMonitor.java b/org.eclipse.jgit/src/org/eclipse/jgit/lib/EmptyProgressMonitor.java
index 6b201e6bcf..94d28eb345 100644
--- a/org.eclipse.jgit/src/org/eclipse/jgit/lib/EmptyProgressMonitor.java
+++ b/org.eclipse.jgit/src/org/eclipse/jgit/lib/EmptyProgressMonitor.java
@@ -48,4 +48,8 @@ public abstract class EmptyProgressMonitor implements ProgressMonitor {
 		return false;
 	}
 
+	@Override
+	public void showDuration(boolean enabled) {
+		// not implemented
+	}
 }
diff --git a/org.eclipse.jgit/src/org/eclipse/jgit/lib/NullProgressMonitor.java b/org.eclipse.jgit/src/org/eclipse/jgit/lib/NullProgressMonitor.java
index 10904b6955..127cca9d1b 100644
--- a/org.eclipse.jgit/src/org/eclipse/jgit/lib/NullProgressMonitor.java
+++ b/org.eclipse.jgit/src/org/eclipse/jgit/lib/NullProgressMonitor.java
@@ -52,4 +52,9 @@ public class NullProgressMonitor implements ProgressMonitor {
 	public void endTask() {
 		// Do not report.
 	}
+
+	@Override
+	public void showDuration(boolean enabled) {
+		// don't show
+	}
 }
diff --git a/org.eclipse.jgit/src/org/eclipse/jgit/lib/ProgressMonitor.java b/org.eclipse.jgit/src/org/eclipse/jgit/lib/ProgressMonitor.java
index 9ebb0a46b9..2ce73ace86 100644
--- a/org.eclipse.jgit/src/org/eclipse/jgit/lib/ProgressMonitor.java
+++ b/org.eclipse.jgit/src/org/eclipse/jgit/lib/ProgressMonitor.java
@@ -65,4 +65,13 @@ public interface ProgressMonitor {
 	 * @return true if the user asked the process to stop working.
 	 */
 	boolean isCancelled();
+
+	/**
+	 * Set whether the monitor should show elapsed time per task
+	 *
+	 * @param enabled
+	 *            whether to show elapsed time per task
+	 * @since 6.5
+	 */
+	void showDuration(boolean enabled);
 }
diff --git a/org.eclipse.jgit/src/org/eclipse/jgit/lib/TextProgressMonitor.java b/org.eclipse.jgit/src/org/eclipse/jgit/lib/TextProgressMonitor.java
index 03a78eb8ac..85aa0b6639 100644
--- a/org.eclipse.jgit/src/org/eclipse/jgit/lib/TextProgressMonitor.java
+++ b/org.eclipse.jgit/src/org/eclipse/jgit/lib/TextProgressMonitor.java
@@ -17,6 +17,7 @@ import java.io.IOException;
 import java.io.OutputStreamWriter;
 import java.io.PrintWriter;
 import java.io.Writer;
+import java.time.Duration;
 
 /**
  * A simple progress reporter printing on a stream.
@@ -46,49 +47,53 @@ public class TextProgressMonitor extends BatchingProgressMonitor {
 
 	/** {@inheritDoc} */
 	@Override
-	protected void onUpdate(String taskName, int workCurr) {
+	protected void onUpdate(String taskName, int workCurr, Duration duration) {
 		StringBuilder s = new StringBuilder();
-		format(s, taskName, workCurr);
+		format(s, taskName, workCurr, duration);
 		send(s);
 	}
 
 	/** {@inheritDoc} */
 	@Override
-	protected void onEndTask(String taskName, int workCurr) {
+	protected void onEndTask(String taskName, int workCurr, Duration duration) {
 		StringBuilder s = new StringBuilder();
-		format(s, taskName, workCurr);
+		format(s, taskName, workCurr, duration);
 		s.append("\n"); //$NON-NLS-1$
 		send(s);
 	}
 
-	private void format(StringBuilder s, String taskName, int workCurr) {
+	private void format(StringBuilder s, String taskName, int workCurr,
+			Duration duration) {
 		s.append("\r"); //$NON-NLS-1$
 		s.append(taskName);
 		s.append(": "); //$NON-NLS-1$
 		while (s.length() < 25)
 			s.append(' ');
 		s.append(workCurr);
+		appendDuration(s, duration);
 	}
 
 	/** {@inheritDoc} */
 	@Override
-	protected void onUpdate(String taskName, int cmp, int totalWork, int pcnt) {
+	protected void onUpdate(String taskName, int cmp, int totalWork, int pcnt,
+			Duration duration) {
 		StringBuilder s = new StringBuilder();
-		format(s, taskName, cmp, totalWork, pcnt);
+		format(s, taskName, cmp, totalWork, pcnt, duration);
 		send(s);
 	}
 
 	/** {@inheritDoc} */
 	@Override
-	protected void onEndTask(String taskName, int cmp, int totalWork, int pcnt) {
+	protected void onEndTask(String taskName, int cmp, int totalWork, int pcnt,
+			Duration duration) {
 		StringBuilder s = new StringBuilder();
-		format(s, taskName, cmp, totalWork, pcnt);
+		format(s, taskName, cmp, totalWork, pcnt, duration);
 		s.append("\n"); //$NON-NLS-1$
 		send(s);
 	}
 
 	private void format(StringBuilder s, String taskName, int cmp,
-			int totalWork, int pcnt) {
+			int totalWork, int pcnt, Duration duration) {
 		s.append("\r"); //$NON-NLS-1$
 		s.append(taskName);
 		s.append(": "); //$NON-NLS-1$
@@ -106,9 +111,10 @@ public class TextProgressMonitor extends BatchingProgressMonitor {
 		s.append(pcnt);
 		s.append("% ("); //$NON-NLS-1$
 		s.append(curStr);
-		s.append("/"); //$NON-NLS-1$
+		s.append('/');
 		s.append(endStr);
-		s.append(")"); //$NON-NLS-1$
+		s.append(')');
+		appendDuration(s, duration);
 	}
 
 	private void send(StringBuilder s) {
diff --git a/org.eclipse.jgit/src/org/eclipse/jgit/lib/ThreadSafeProgressMonitor.java b/org.eclipse.jgit/src/org/eclipse/jgit/lib/ThreadSafeProgressMonitor.java
index 180fbdc461..e553955560 100644
--- a/org.eclipse.jgit/src/org/eclipse/jgit/lib/ThreadSafeProgressMonitor.java
+++ b/org.eclipse.jgit/src/org/eclipse/jgit/lib/ThreadSafeProgressMonitor.java
@@ -158,6 +158,11 @@ public class ThreadSafeProgressMonitor implements ProgressMonitor {
 		pm.endTask();
 	}
 
+	@Override
+	public void showDuration(boolean enabled) {
+		pm.showDuration(enabled);
+	}
+
 	private boolean isMainThread() {
 		return Thread.currentThread() == mainThread;
 	}
diff --git a/org.eclipse.jgit/src/org/eclipse/jgit/transport/SideBandProgressMonitor.java b/org.eclipse.jgit/src/org/eclipse/jgit/transport/SideBandProgressMonitor.java
index 83e8bc291f..33308600d9 100644
--- a/org.eclipse.jgit/src/org/eclipse/jgit/transport/SideBandProgressMonitor.java
+++ b/org.eclipse.jgit/src/org/eclipse/jgit/transport/SideBandProgressMonitor.java
@@ -12,6 +12,7 @@ package org.eclipse.jgit.transport;
 
 import java.io.IOException;
 import java.io.OutputStream;
+import java.time.Duration;
 
 import org.eclipse.jgit.lib.BatchingProgressMonitor;
 import org.eclipse.jgit.lib.Constants;
@@ -29,48 +30,52 @@ class SideBandProgressMonitor extends BatchingProgressMonitor {
 
 	/** {@inheritDoc} */
 	@Override
-	protected void onUpdate(String taskName, int workCurr) {
+	protected void onUpdate(String taskName, int workCurr, Duration duration) {
 		StringBuilder s = new StringBuilder();
-		format(s, taskName, workCurr);
+		format(s, taskName, workCurr, duration);
 		s.append("   \r"); //$NON-NLS-1$
 		send(s);
 	}
 
 	/** {@inheritDoc} */
 	@Override
-	protected void onEndTask(String taskName, int workCurr) {
+	protected void onEndTask(String taskName, int workCurr, Duration duration) {
 		StringBuilder s = new StringBuilder();
-		format(s, taskName, workCurr);
+		format(s, taskName, workCurr, duration);
 		s.append(", done\n"); //$NON-NLS-1$
 		send(s);
 	}
 
-	private void format(StringBuilder s, String taskName, int workCurr) {
+	private void format(StringBuilder s, String taskName, int workCurr,
+			Duration duration) {
 		s.append(taskName);
 		s.append(": "); //$NON-NLS-1$
 		s.append(workCurr);
+		appendDuration(s, duration);
 	}
 
 	/** {@inheritDoc} */
 	@Override
-	protected void onUpdate(String taskName, int cmp, int totalWork, int pcnt) {
+	protected void onUpdate(String taskName, int cmp, int totalWork, int pcnt,
+			Duration duration) {
 		StringBuilder s = new StringBuilder();
-		format(s, taskName, cmp, totalWork, pcnt);
+		format(s, taskName, cmp, totalWork, pcnt, duration);
 		s.append("   \r"); //$NON-NLS-1$
 		send(s);
 	}
 
 	/** {@inheritDoc} */
 	@Override
-	protected void onEndTask(String taskName, int cmp, int totalWork, int pcnt) {
+	protected void onEndTask(String taskName, int cmp, int totalWork, int pcnt,
+			Duration duration) {
 		StringBuilder s = new StringBuilder();
-		format(s, taskName, cmp, totalWork, pcnt);
+		format(s, taskName, cmp, totalWork, pcnt, duration);
 		s.append("\n"); //$NON-NLS-1$
 		send(s);
 	}
 
 	private void format(StringBuilder s, String taskName, int cmp,
-			int totalWork, int pcnt) {
+			int totalWork, int pcnt, Duration duration) {
 		s.append(taskName);
 		s.append(": "); //$NON-NLS-1$
 		if (pcnt < 100)
@@ -80,9 +85,10 @@ class SideBandProgressMonitor extends BatchingProgressMonitor {
 		s.append(pcnt);
 		s.append("% ("); //$NON-NLS-1$
 		s.append(cmp);
-		s.append("/"); //$NON-NLS-1$
+		s.append('/');
 		s.append(totalWork);
-		s.append(")"); //$NON-NLS-1$
+		s.append(')');
+		appendDuration(s, duration);
 	}
 
 	private void send(StringBuilder s) {
diff --git a/org.eclipse.jgit/src/org/eclipse/jgit/util/SystemReader.java b/org.eclipse.jgit/src/org/eclipse/jgit/util/SystemReader.java
index 5ced0713e0..a8a77904a2 100644
--- a/org.eclipse.jgit/src/org/eclipse/jgit/util/SystemReader.java
+++ b/org.eclipse.jgit/src/org/eclipse/jgit/util/SystemReader.java
@@ -65,6 +65,21 @@ public abstract class SystemReader {
 
 	private static volatile Boolean isLinux;
 
+	private static final String GIT_TRACE_PERFORMANCE = "GIT_TRACE_PERFORMANCE"; //$NON-NLS-1$
+
+	private static final boolean performanceTrace = initPerformanceTrace();
+
+	private static boolean initPerformanceTrace() {
+		String val = System.getenv(GIT_TRACE_PERFORMANCE);
+		if (val == null) {
+			val = System.getenv(GIT_TRACE_PERFORMANCE);
+		}
+		if (val != null) {
+			return Boolean.valueOf(val).booleanValue();
+		}
+		return false;
+	}
+
 	static {
 		SystemReader r = new Default();
 		r.init();
@@ -560,6 +575,16 @@ public abstract class SystemReader {
 		return isLinux.booleanValue();
 	}
 
+	/**
+	 * Whether performance trace is enabled
+	 *
+	 * @return whether performance trace is enabled
+	 * @since 6.5
+	 */
+	public boolean isPerformanceTraceEnabled() {
+		return performanceTrace;
+	}
+
 	private String getOsName() {
 		return AccessController.doPrivileged(
 				(PrivilegedAction<String>) () -> getProperty("os.name") //$NON-NLS-1$