Version 1.6

Author: Hubbitus

README.md

@@ -55,6 +55,14 @@ for (Object aisObj in aisList){
 ```groovy
 ProgressLogger.measure({log.info(it)}, { /* long work  * / }, 'Doing cool work')
 ```
+Or:
+```groovy
+def result = ProgressLogger.measureAndLogTime({spent-> log.debug('Operation took: ' + spent) }){
+	println 'test' // Some long measured work
+	return 42
+}
+assert 42 == result
+```
 6. When amount of elements or iterations is not known (f.e. stream processing or recursive calls like tree traversal)
 totalAmountOfElements set to -1 and simpler statistic returned:
 ```groovy
@@ -163,6 +171,9 @@ Then you may just do in script *without any initialization*:
 Please note, file must include config{} closure on top level which will be stripped automatically.
 
 # Changelog
+## version 1.6 2018-04-26 16:14
+* Add method `ProgressLogger.measureAndLogTime`
+
 ## version 1.5 2018-04-19 19:35
 * Add class `GlobalConfig` for easy access configuration from resources.
 * Update gradlew version to 4.7.

build.gradle

@@ -5,7 +5,7 @@ apply plugin: 'idea'
 apply plugin: 'signing'
 
 group = 'info.hubbitus'
-version = '1.5'
+version = '1.6'
 
 repositories {
 	mavenCentral()

src/main/groovy/info/hubbitus/utils/bench/ProgressLogger.groovy

@@ -184,12 +184,34 @@ class ProgressLogger {
 	 */
 	static Spent measure(Consumer outMethod, Supplier execute, String objName = '', String beginMessage = null, String additionalEndMessage = ''){
 		if (beginMessage) outMethod.accept(beginMessage)
-		ProgressLogger pl = new ProgressLogger(1, outMethod, -1, '')
-		if (objName) pl.objName = objName;
-		def execRes = execute.get();
-		Spent spent = pl.stop(additionalEndMessage ?: execRes.toString());
-		spent.info = (additionalEndMessage ?: execRes);
-		return spent;
+		ProgressLogger pl = new ProgressLogger(1, outMethod, -1, (objName?:''))
+		def execRes = execute.get()
+		Spent spent = pl.stop(additionalEndMessage ?: execRes.toString())
+		spent.info = (additionalEndMessage ?: execRes)
+		return spent
+	}
+
+	/**
+	 * Method to measure single invocation, log spent time and return process result of actual work
+	 * In most cases we want just execute single statement and log spent time result. It is easy with that method like:
+	 * def result = ProgressLogger.measureAndLogTime({spentTime-> bufferWrite('Operation took: ' + spentTime) } ){
+	 * 		println 'test' // Some long measured work
+	 * 		return 42
+	 * 	}
+	 * assert 42 == result
+	 *
+	 * @param spentTimeLogger
+	 * @param execute
+	 * @return
+	 */
+	static def measureAndLogTime(Consumer<Spent> spentTimeLogger, Supplier execute){
+		ProgressLogger pl = new ProgressLogger(1, {}, -1, '')
+		def execRes = execute.get()
+		Spent spent = pl.stop()
+		spent.info = execRes
+		spentTimeLogger.accept(spent)
+
+		return execRes
 	}
 
 	/**
@@ -198,9 +220,9 @@ class ProgressLogger {
 	 * @param currentElementNo
 	 */
 	private void logProgress(long currentElementNo, String iterationName = null){
-		lastPackSpentNs = System.nanoTime() - last;
-		spentFromStartNs = System.nanoTime() - start;
-		leaved = this.totalAmountOfElements - currentElementNo;
+		lastPackSpentNs = System.nanoTime() - last
+		spentFromStartNs = System.nanoTime() - start
+		leaved = this.totalAmountOfElements - currentElementNo
 
 		if ( ! (currentElementNo % packLogSize) || currentElementNo == this.totalAmountOfElements || 1 == currentElementNo){ // First, last and by pack of 'packLogSize' amount of elements
 			outMethod.accept(
@@ -217,8 +239,8 @@ class ProgressLogger {
 					,_FORMAT: _FORMAT // For Estimation online add
 				).toString() // .toString for compatibility with Java methods, passed by ref
 			);
-			last = System.nanoTime();
-			autoAdjust();
+			last = System.nanoTime()
+			autoAdjust()
 		}
 	}
 
@@ -301,28 +323,27 @@ class ProgressLogger {
 	 * @param iterationName
 	 */
 	void next(String iterationName){
-		logProgress(current.incrementAndGet(), iterationName);
+		logProgress(current.incrementAndGet(), iterationName)
 	}
 
 	/**
 	 * Adjust elements batch size automatically to do not SPAM log
 	 */
-	synchronized void autoAdjust(){
+	synchronized private void autoAdjust(){
 		if (autoAdjust && current.get() > 2 && lastPackSpentNs / (10 ** 9) < 1){
-			this.autoAdjustFactor = 10;
-			autoAdjustEach();
+			this.autoAdjustFactor = 10
+			autoAdjustEach()
 		}
 	}
 
 	synchronized private void autoAdjustEach(){
 		this.packLogSize = this.totalAmountOfElements / autoAdjustFactor;
 			if (packLogSize in [0, 1]){
-				packLogSize = 1;
-				return;
+				packLogSize = 1
+				return
 			}
-		int roundFactor = 10 ** (Math.ceil(Math.log10(packLogSize)) - 1);
-//		println "Adjusting: ${autoAdjust}; autoAdjustFactor=${autoAdjustFactor}; current=${current}; lastPackSpentNs(sec)=${lastPackSpentNs / (10 ** 9)}; packLogSize=${packLogSize}; roundFactor=${roundFactor}";
+		int roundFactor = 10 ** (Math.ceil(Math.log10(packLogSize)) - 1)
 		// Round up to 10 ** N - 1. F.e. 15 will be rounded to 20, 234 to 300, 5678 to 5000
-		this.packLogSize = ( Math.ceil(packLogSize / roundFactor) * roundFactor ?: 1 );
+		this.packLogSize = ( Math.ceil(packLogSize / roundFactor) * roundFactor ?: 1 )
 	}
 }

src/main/groovy/info/hubbitus/utils/bench/Spent.groovy

@@ -1,6 +1,7 @@
 package info.hubbitus.utils.bench
 
 import groovy.transform.CompileStatic
+import groovy.transform.ToString
 
 import java.math.RoundingMode
 
@@ -20,24 +21,24 @@ import java.math.RoundingMode
  */
 @CompileStatic
 public class Spent implements Comparable<Spent>{
-	long spent; // Nanoseconds
-	def info;
+	long spent // Nanoseconds
+	def info
 
 	@Lazy private String spentStr = formatTimeElapsedSinceNanosecond(spent);
 
 	/**
 	 * Do not format anything if it less than 1 minute by default
 	 * Nanoseconds.
 	 */
-	static long MINIMUM_SPENT_FOR_FORMATTING = 60000;
+	static long MINIMUM_SPENT_FOR_FORMATTING = 60000
 
 	/**
 	 * Constructor from amount of nanoseconds
 	 *
 	 * @param spent
 	 */
 	public Spent(long spent){
-		this.spent = spent;
+		this.spent = spent
 	}
 
 	/**
@@ -51,31 +52,31 @@ public class Spent implements Comparable<Spent>{
 
 		if(nanosDiff / (10 ** 6) <= MINIMUM_SPENT_FOR_FORMATTING){ return sprintf('%.3f', (nanosDiff / (10 ** 9)).setScale(3, RoundingMode.HALF_UP)) }
 
-		String formattedTime = '';
-		long secondInNanos = (long)(10 ** 9); // Explicit casting only for @CompileStatic
-		long minuteInNanos = secondInNanos * 60;
-		long hourInNanos = minuteInNanos * 60;
-		long dayInNanos = hourInNanos * 24;
-		long weekInNanos = dayInNanos * 7;
-		long monthInNanos = dayInNanos * 30;
+		String formattedTime = ''
+		long secondInNanos = (long)(10 ** 9) // Explicit casting only for @CompileStatic
+		long minuteInNanos = secondInNanos * 60
+		long hourInNanos = minuteInNanos * 60
+		long dayInNanos = hourInNanos * 24
+		long weekInNanos = dayInNanos * 7
+		long monthInNanos = dayInNanos * 30
 
-		List timeElapsed = [];
+		List timeElapsed = []
 		// Define time units - plural cases are handled inside loop
 		List timeElapsedText = [
 			'secs', 'mins', 'hours', 'days', 'weeks', 'months' // @TODO add formatting and/or internationalization support
-		];
+		]
 
-		timeElapsed[5] = (int) (nanosDiff / monthInNanos);	// months
+		timeElapsed[5] = (int) (nanosDiff / monthInNanos)	// months
 		nanosDiff %= monthInNanos;
-		timeElapsed[4] = (int) (nanosDiff / weekInNanos);	// weeks
-		nanosDiff %= weekInNanos;
-		timeElapsed[3] = (int) (nanosDiff / dayInNanos);	// days
-		nanosDiff %= dayInNanos;
-		timeElapsed[2] = (int) (nanosDiff / hourInNanos);	// hours
-		nanosDiff %= hourInNanos;
-		timeElapsed[1] = (int) (nanosDiff / minuteInNanos);	// minutes
-		nanosDiff %= minuteInNanos;
-		timeElapsed[0] = sprintf('%.3f', (nanosDiff / secondInNanos).setScale(3, RoundingMode.HALF_UP));	// seconds
+		timeElapsed[4] = (int) (nanosDiff / weekInNanos)	// weeks
+		nanosDiff %= weekInNanos
+		timeElapsed[3] = (int) (nanosDiff / dayInNanos)	// days
+		nanosDiff %= dayInNanos
+		timeElapsed[2] = (int) (nanosDiff / hourInNanos)	// hours
+		nanosDiff %= hourInNanos
+		timeElapsed[1] = (int) (nanosDiff / minuteInNanos)	// minutes
+		nanosDiff %= minuteInNanos
+		timeElapsed[0] = sprintf('%.3f', (nanosDiff / secondInNanos).setScale(3, RoundingMode.HALF_UP))	// seconds
 
 		// Only adds 3 significant high valued units
 		int i = (timeElapsed.size()-1);
@@ -84,25 +85,25 @@ public class Spent implements Comparable<Spent>{
 			if(timeElapsed[i] != 0){
 				formattedTime += ((j>0)? ", " :"") \
 					+ timeElapsed[i] \
-					+ " " + timeElapsedText[i];
-				++j;
+					+ " " + timeElapsedText[i]
+				++j
 			}
 		} // end for - build string
 
-		return formattedTime;
+		return formattedTime
 	}
 
 	public Spent plus(Spent other){
-		this.spent += other.spent;
-		return this;
+		this.spent += other.spent
+		return this
 	}
 
 	public String toString(){
-		return spentStr + (info ? "\n$info" : '');
+		return spentStr + (info ? "\n$info" : '')
 	}
 
 	@Override
 	int compareTo(Spent other) {
-		(other.spent <=> this.spent);
+		(other.spent <=> this.spent)
 	}
 }

src/test/groovy/info/hubbitus/utils/bench/ProgressLoggerJavaTest.java

@@ -16,57 +16,69 @@
  */
 @Slf4j
 public class ProgressLoggerJavaTest extends Assert {
-    private final StringBuffer sb = new StringBuffer();
-    private Consumer bufferWrite = (it) -> sb.append(it).append('\n');
+	private final StringBuffer sb = new StringBuffer();
+	private Consumer bufferWrite = (it) -> sb.append(it).append('\n');
 
-    @Test
-    public void testWithImplicitCreateConsumer(){
-        List list = Arrays.asList(1, 2, 3, 4, 5, 6, 7, 8, 9, 10);
-        ProgressLogger pl = new ProgressLogger(
-            list
-            ,new Consumer() {
-                @Override
-                public void accept(Object it) {
-                    System.out.println(it);
-                    bufferWrite.accept(it);
-                }
-            }
-        );
-        list.forEach( (t) -> pl.next() );
+	@Test
+	public void testWithImplicitCreateConsumer(){
+		List list = Arrays.asList(1, 2, 3, 4, 5, 6, 7, 8, 9, 10);
+		ProgressLogger pl = new ProgressLogger(
+			list
+			,new Consumer() {
+				@Override
+				public void accept(Object it) {
+					System.out.println(it);
+					bufferWrite.accept(it);
+				}
+			}
+		);
+		list.forEach( (t) -> pl.next() );
 
-        assertThat(sb.toString(), matchesPattern("(?ms)^Process \\[Integer\\] #1 from 10 \\(10[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\n" +
-            "Process \\[Integer\\] #2 from 10 \\(20[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 8, time: \\d+[,.]\\d{3}\n" +
-            "Process \\[Integer\\] #3 from 10 \\(30[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 7, time: \\d+[,.]\\d{3}\n" +
-            "Process \\[Integer\\] #4 from 10 \\(40[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 6, time: \\d+[,.]\\d{3}\n" +
-            "Process \\[Integer\\] #5 from 10 \\(50[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 5, time: \\d+[,.]\\d{3}\n" +
-            "Process \\[Integer\\] #6 from 10 \\(60[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 4, time: \\d+[,.]\\d{3}\n" +
-            "Process \\[Integer\\] #7 from 10 \\(70[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 3, time: \\d+[,.]\\d{3}\n" +
-            "Process \\[Integer\\] #8 from 10 \\(80[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 2, time: \\d+[,.]\\d{3}\n" +
-            "Process \\[Integer\\] #9 from 10 \\(90[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 1, time: \\d+[,.]\\d{3}\n" +
-            "Process \\[Integer\\] #10 from 10 \\(100[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\n")
-        );
-    }
+		assertThat(sb.toString(), matchesPattern("(?ms)^Process \\[Integer\\] #1 from 10 \\(10[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\n" +
+			"Process \\[Integer\\] #2 from 10 \\(20[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 8, time: \\d+[,.]\\d{3}\n" +
+			"Process \\[Integer\\] #3 from 10 \\(30[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 7, time: \\d+[,.]\\d{3}\n" +
+			"Process \\[Integer\\] #4 from 10 \\(40[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 6, time: \\d+[,.]\\d{3}\n" +
+			"Process \\[Integer\\] #5 from 10 \\(50[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 5, time: \\d+[,.]\\d{3}\n" +
+			"Process \\[Integer\\] #6 from 10 \\(60[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 4, time: \\d+[,.]\\d{3}\n" +
+			"Process \\[Integer\\] #7 from 10 \\(70[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 3, time: \\d+[,.]\\d{3}\n" +
+			"Process \\[Integer\\] #8 from 10 \\(80[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 2, time: \\d+[,.]\\d{3}\n" +
+			"Process \\[Integer\\] #9 from 10 \\(90[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 1, time: \\d+[,.]\\d{3}\n" +
+			"Process \\[Integer\\] #10 from 10 \\(100[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\n")
+		);
+	}
 
-    @Test
-    public void testWithLambda(){
-        List list = Arrays.asList(1, 2, 3, 4, 5, 6, 7, 8, 9, 10);
-        ProgressLogger pl = new ProgressLogger(
-            list
-            , it -> bufferWrite.accept(it)
-        );
-        list.forEach( (t) -> pl.next() );
+	@Test
+	public void testWithLambda(){
+		List list = Arrays.asList(1, 2, 3, 4, 5, 6, 7, 8, 9, 10);
+		ProgressLogger pl = new ProgressLogger(
+			list
+			, it -> bufferWrite.accept(it)
+		);
+		list.forEach( (t) -> pl.next() );
 
-        assertThat(sb.toString(), matchesPattern("(?ms)^Process \\[Integer\\] #1 from 10 \\(10[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\n" +
-            "Process \\[Integer\\] #2 from 10 \\(20[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 8, time: \\d+[,.]\\d{3}\n" +
-            "Process \\[Integer\\] #3 from 10 \\(30[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 7, time: \\d+[,.]\\d{3}\n" +
-            "Process \\[Integer\\] #4 from 10 \\(40[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 6, time: \\d+[,.]\\d{3}\n" +
-            "Process \\[Integer\\] #5 from 10 \\(50[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 5, time: \\d+[,.]\\d{3}\n" +
-            "Process \\[Integer\\] #6 from 10 \\(60[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 4, time: \\d+[,.]\\d{3}\n" +
-            "Process \\[Integer\\] #7 from 10 \\(70[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 3, time: \\d+[,.]\\d{3}\n" +
-            "Process \\[Integer\\] #8 from 10 \\(80[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 2, time: \\d+[,.]\\d{3}\n" +
-            "Process \\[Integer\\] #9 from 10 \\(90[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 1, time: \\d+[,.]\\d{3}\n" +
-            "Process \\[Integer\\] #10 from 10 \\(100[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\n")
-        );
-    }
+		assertThat(sb.toString(), matchesPattern("(?ms)^Process \\[Integer\\] #1 from 10 \\(10[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\n" +
+			"Process \\[Integer\\] #2 from 10 \\(20[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 8, time: \\d+[,.]\\d{3}\n" +
+			"Process \\[Integer\\] #3 from 10 \\(30[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 7, time: \\d+[,.]\\d{3}\n" +
+			"Process \\[Integer\\] #4 from 10 \\(40[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 6, time: \\d+[,.]\\d{3}\n" +
+			"Process \\[Integer\\] #5 from 10 \\(50[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 5, time: \\d+[,.]\\d{3}\n" +
+			"Process \\[Integer\\] #6 from 10 \\(60[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 4, time: \\d+[,.]\\d{3}\n" +
+			"Process \\[Integer\\] #7 from 10 \\(70[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 3, time: \\d+[,.]\\d{3}\n" +
+			"Process \\[Integer\\] #8 from 10 \\(80[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 2, time: \\d+[,.]\\d{3}\n" +
+			"Process \\[Integer\\] #9 from 10 \\(90[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\\. Estimated items: 1, time: \\d+[,.]\\d{3}\n" +
+			"Process \\[Integer\\] #10 from 10 \\(100[,.]00%\\)\\. Spent \\(pack by 1\\) time: \\d+[,.]\\d{3} \\(from start: \\d+[,.]\\d{3}\\)\n")
+		);
+	}
 
+	@Test
+	public void measureAndLogTimeTest(){
+		long result = (long)ProgressLogger.measureAndLogTime(
+			spentTime-> bufferWrite.accept("Operation took: " + spentTime),
+			() -> {
+				System.out.println ("test"); // Some long measured work
+				return 42L;
+			}
+		);
+		assertEquals(42, result);
+		assertThat(sb.toString(), matchesPattern("Operation took: 0[,.]\\d{3}\n42\n"));
+	}
 }

src/test/groovy/info/hubbitus/utils/bench/ProgressLoggerTest.groovy

@@ -3,6 +3,7 @@ package info.hubbitus.utils.bench
 import groovyx.gpars.GParsPool
 import spock.lang.Specification
 
+import java.util.function.Consumer
 import java.util.function.Supplier
 
 /**
@@ -223,4 +224,15 @@ Process \[four\] #4 from 4 \(100[,.]00%\)\. Spent \(pack by 1\) time: \d+[,.]\d{
 				}
 			}
 	}
+
+	def measureAndLogTimeTest(){
+		when:
+			def result = ProgressLogger.measureAndLogTime({spent-> bufferWrite('Operation took: ' + spent) }){
+				println 'test' // Some long measured work
+				return 42
+			}
+		then:
+			42 == result
+			sb ==~ /Operation took: 0[,.]\d{3}\n42\n/
+	}
 }