Skip to content

Commit 8d8d28e

Browse files
HubbitusHubbitus
committed
Version 1.1
* Add ProgressLogger.next(String) method. Especially useful for testing. * Introduce Spock tests
1 parent 4c8809e commit 8d8d28e

3 files changed

Lines changed: 185 additions & 24 deletions

File tree

‎build.gradle‎

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,7 @@
11
apply plugin: 'groovy'
22

33
group = 'info.hubbitus'
4-
version = '1.0'
4+
version = '1.1'
55

66
repositories {
77
mavenCentral()
@@ -12,6 +12,10 @@ dependencies {
1212

1313
compile 'org.slf4j:slf4j-api:1.7.12'
1414
compile 'ch.qos.logback:logback-classic:1.1.3' // dual EPL v.1.0 and LGPL 2.1
15+
16+
// mandatory dependencies for using Spock
17+
compile 'org.codehaus.groovy:groovy-all:2.4.7'
18+
testCompile 'org.spockframework:spock-core:1.0-groovy-2.4'
1519
}
1620

1721
task wrapper(type: Wrapper) {

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

Lines changed: 46 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -8,21 +8,22 @@ import groovy.text.Template
88
* It is intended for easy add possibility of logging progress of operations, for example:
99
* 1) in Groovy way it so simple as:
1010
* <code>
11-
* ProgressLogger.each([1, 2, 3, 4, 5]){
11+
* ProgressLogger.each([1, 2, 3, 4, 5]){
1212
* println it // Some long run operation
1313
* }
1414
* </code>
1515
* It will produce (by println) output like:
16-
* Process Integer #1 from 5 (20,00%). Spent (pack 1 elements) time: 0,041 (from start: 0,047)
16+
* Process [Integer] #1 from 5 (20,00%). Spent (pack 1 elements) time: 0,041 (from start: 0,047)
1717
* 1
18-
* Process Integer #2 from 5 (40,00%). Spent (pack 1 elements) time: 0,001 (from start: 0,278), Estimated items: 3, time: 0,417
18+
* Process [Integer] #2 from 5 (40,00%). Spent (pack 1 elements) time: 0,001 (from start: 0,278). Estimated items: 3, time: 0,417
1919
* 2
20-
* Process Integer #3 from 5 (60,00%). Spent (pack 1 elements) time: 0,012 (from start: 0,330), Estimated items: 2, time: 0,220
20+
* Process [Integer] #3 from 5 (60,00%). Spent (pack 1 elements) time: 0,012 (from start: 0,330). Estimated items: 2, time: 0,220
2121
* 3
22-
* Process Integer #4 from 5 (80,00%). Spent (pack 1 elements) time: 0,001 (from start: 0,340), Estimated items: 1, time: 0,085
22+
* Process [Integer] #4 from 5 (80,00%). Spent (pack 1 elements) time: 0,001 (from start: 0,340). Estimated items: 1, time: 0,085
2323
* 4
24-
* Process Integer #5 from 5 (100,00%). Spent (pack 1 elements) time: 0,001 (from start: 0,344)
24+
* Process [Integer] #5 from 5 (100,00%). Spent (pack 1 elements) time: 0,001 (from start: 0,344)
2525
* 5
26+
* Off course it will be helpful see there user defined class like Region, User or BlogPost.
2627
* 2) Often useful provide out method, for example to tie into current scope logger instead of global stdout, and add
2728
* some additional transform, it also simple:
2829
* ProgressLogger.each([1, 2, 3, 4, 5]){
@@ -32,12 +33,7 @@ import groovy.text.Template
3233
* ProgressLogger pl = new ProgressLogger(aisList, {log.info(it)});
3334
* for (Object aisObj in aisList){
3435
* pl.next();
35-
* try{
36-
* rowMapper(aisObj, di)
37-
* }
38-
* catch(AsaException ae){
39-
* commonErrorAdd(di, ae);
40-
* }
36+
* rowMapper(aisObj, di)
4137
* }
4238
* 4) Or measure one run:
4339
* ProgressLogger.measure({log.info(it)}, { /* long work * / }, 'Doing cool work')
@@ -49,10 +45,10 @@ import groovy.text.Template
4945
* pl.next();
5046
* }
5147
* Result will be something like:
52-
* Process item #1. Spent (pack 1 elements) time: 1,007 (from start: 1,007)
53-
* Process item #2. Spent (pack 1 elements) time: 1,000 (from start: 2,055)
54-
* Process item #3. Spent (pack 1 elements) time: 1,001 (from start: 3,058)
55-
* Process item #4. Spent (pack 1 elements) time: 1,001 (from start: 4,061)
48+
* Process [item] #1. Spent (pack 1 elements) time: 1,007 (from start: 1,007)
49+
* Process [item] #2. Spent (pack 1 elements) time: 1,000 (from start: 2,055)
50+
* Process [item] #3. Spent (pack 1 elements) time: 1,001 (from start: 3,058)
51+
* Process [item] #4. Spent (pack 1 elements) time: 1,001 (from start: 4,061)
5652
*
5753
* 6) Just for the simplicity it may be:
5854
* <code>
@@ -69,15 +65,20 @@ import groovy.text.Template
6965
* @created: 02.01.2012 22:01
7066
*/
7167
class ProgressLogger {
68+
/**
69+
* You may with configure prefix to start line from "Run", 'Testing', 'Run test' and so on
70+
*/
71+
String processName = 'Process';
72+
7273
/**
7374
* Format of messages. Allow to redefine, customize and i18n
7475
*/
7576
static Map FORMAT = [
7677
item: 'item'
77-
,progress: '''Process ${objectName} #${currentElementNo} from ${totalAmountOfElements} (${sprintf('%.2f', percentComplete)}%). Spent (pack ${packLogSize} elements) time: ${lastPackSpent} (from start: ${fromStartSpent})${( (totalAmountOfElements - currentElementNo && currentElementNo > 1) ? ', ' + _FORMAT.estimation.make(totalAmountOfElements: totalAmountOfElements, currentElementNo: currentElementNo, estimationTimeToFinish: estimationTimeToFinish) : '' )}'''
78-
,progress_total_unknown: '''Process ${objectName} #${currentElementNo}. Spent (pack ${packLogSize} elements) time: ${lastPackSpent} (from start: ${fromStartSpent})'''
78+
,progress: '''${processName} [${objectName}] #${currentElementNo} from ${totalAmountOfElements} (${sprintf('%.2f', percentComplete)}%). Spent (pack ${packLogSize} elements) time: ${lastPackSpent} (from start: ${fromStartSpent})${( (totalAmountOfElements - currentElementNo && currentElementNo > 1) ? '. ' + _FORMAT.estimation.make(totalAmountOfElements: totalAmountOfElements, currentElementNo: currentElementNo, estimationTimeToFinish: estimationTimeToFinish) : '' )}'''
79+
,progress_total_unknown: '''${processName} [${objectName}] #${currentElementNo}. Spent (pack ${packLogSize} elements) time: ${lastPackSpent} (from start: ${fromStartSpent})'''
7980
,estimation: 'Estimated items: ${totalAmountOfElements - currentElementNo}, time: ${estimationTimeToFinish}'
80-
,stop: 'Stop processing ${objectName} (Total processed ${totalItems}). Spent: ${spent}.${additionalResultInformation ? " " + additionalResultInformation : "" }'
81+
,stop: 'Stop processing [${objectName}] (Total processed ${totalItems}). Spent: ${spent}.${additionalResultInformation ? " " + additionalResultInformation : "" }'
8182
];
8283

8384
// Just cache created template as it used many times - and do not use @Lazy transformation to on the fly create items, and do not define it each time format added
@@ -90,7 +91,7 @@ class ProgressLogger {
9091

9192
private long start;
9293
private long last;
93-
private long totalAmountOfElements;
94+
private long totalAmountOfElements = -1;
9495
int packLogSize;
9596
String objName;
9697
private long current = 1;
@@ -112,7 +113,6 @@ class ProgressLogger {
112113
*/
113114
public ProgressLogger(long totalAmountOfElements = -1, Closure outMethod = {println it}, Integer packLogSize = null, String objName = null){
114115
this.totalAmountOfElements = totalAmountOfElements;
115-
this.last = this.start = System.nanoTime();
116116
this.objName = (objName ?: FORMAT.item);
117117
this.outMethod = outMethod;
118118
if (!packLogSize){
@@ -122,6 +122,7 @@ class ProgressLogger {
122122
else{
123123
this.packLogSize = packLogSize;;
124124
}
125+
reset()
125126
}
126127

127128
/**
@@ -190,15 +191,16 @@ class ProgressLogger {
190191
*
191192
* @param currentElementNo
192193
*/
193-
private void logProgress(long currentElementNo){
194+
private void logProgress(long currentElementNo, String iterationName = null){
194195
lastPackSpentNs = System.nanoTime() - last;
195196
spentFromStartNs = System.nanoTime() - start;
196197
leaved = this.totalAmountOfElements - currentElementNo;
197198

198199
if ( ! (currentElementNo % packLogSize) || currentElementNo == this.totalAmountOfElements || 1 == currentElementNo){ // First, last and by pack of 'packLogSize' amount of elements
199200
outMethod(
200201
(-1 == totalAmountOfElements ? _FORMAT.progress_total_unknown : _FORMAT.progress).make(
201-
objectName: objName
202+
processName: processName
203+
,objectName: iterationName ?: objName
202204
,currentElementNo: currentElementNo
203205
,totalAmountOfElements: this.totalAmountOfElements
204206
,percentComplete: currentElementNo / this.totalAmountOfElements * 100
@@ -258,6 +260,27 @@ class ProgressLogger {
258260
logProgress(current++);
259261
}
260262

263+
/**
264+
* Method to tick like:
265+
*
266+
* def pl = new ProgressLogger()
267+
* ['one', 'two', 'three', 'four'].each{
268+
* pl.next it
269+
* }
270+
*
271+
* Output will be something like:
272+
* Process [one] #1. Spent (pack 1 elements) time: 1,007 (from start: 1,007)
273+
* Process [two] #1. Spent (pack 1 elements) time: 1,007 (from start: 1,007)
274+
* Process [three] #1. Spent (pack 1 elements) time: 1,007 (from start: 1,007)
275+
* Process [four] #1. Spent (pack 1 elements) time: 1,007 (from start: 1,007)
276+
*
277+
*
278+
* @param iterationName
279+
*/
280+
void next(String iterationName){
281+
logProgress(current++, iterationName);
282+
}
283+
261284
/**
262285
* Adjust elements batch size automatically to do not SPAM log
263286
*/

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

Lines changed: 134 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,134 @@
1+
package info.hubbitus.utils.bench
2+
3+
import spock.lang.Specification
4+
5+
/**
6+
* @author Pavel Alexeev.
7+
* @created 2016-11-12 13:24.
8+
*/
9+
class ProgressLoggerTest extends Specification {
10+
List digitsList = [1, 2, 3, 4, 5]
11+
12+
List objectsList = ['one', 'two', 'three', 'four']
13+
14+
StringBuffer sb = new StringBuffer()
15+
16+
Closure bufferWrite = {sb.append(it).append('\n')}
17+
18+
public static String digitsListResultRegexp = /Process \[Integer\] #1 from 5 \(20,00%\)\. Spent \(pack 1 elements\) time: \d+,\d{3} \(from start: \d+,\d{3}\)
19+
Process \[Integer\] #2 from 5 \(40,00%\)\. Spent \(pack 1 elements\) time: \d+,\d{3} \(from start: \d+,\d{3}\). Estimated items: 3, time: \d+,\d{3}
20+
Process \[Integer\] #3 from 5 \(60,00%\)\. Spent \(pack 1 elements\) time: \d+,\d{3} \(from start: \d+,\d{3}\). Estimated items: 2, time: \d+,\d{3}
21+
Process \[Integer\] #4 from 5 \(80,00%\)\. Spent \(pack 1 elements\) time: \d+,\d{3} \(from start: \d+,\d{3}\). Estimated items: 1, time: \d+,\d{3}
22+
Process \[Integer\] #5 from 5 \(100,00%\)\. Spent \(pack 1 elements\) time: \d+,\d{3} \(from start: \d+,\d{3}\)
23+
/
24+
25+
/**
26+
* Stream opposite to list does not known amount of elements on start
27+
*/
28+
public static String digitsStreamResultRegexp = /Process \[item\] #1\. Spent \(pack 1 elements\) time: \d+,\d{3} \(from start: \d+,\d{3}\)
29+
Process \[item\] #2\. Spent \(pack 1 elements\) time: \d+,\d{3} \(from start: \d+,\d{3}\)
30+
Process \[item\] #3\. Spent \(pack 1 elements\) time: \d+,\d{3} \(from start: \d+,\d{3}\)
31+
Process \[item\] #4\. Spent \(pack 1 elements\) time: \d+,\d{3} \(from start: \d+,\d{3}\)
32+
Process \[item\] #5\. Spent \(pack 1 elements\) time: \d+,\d{3} \(from start: \d+,\d{3}\)
33+
/
34+
35+
public static String objectsStreamResultRegexp = /Process \[one\] #1\. Spent \(pack 1 elements\) time: \d+,\d{3} \(from start: \d+,\d{3}\)
36+
Process \[two\] #2\. Spent \(pack 1 elements\) time: \d+,\d{3} \(from start: \d+,\d{3}\)
37+
Process \[three\] #3\. Spent \(pack 1 elements\) time: \d+,\d{3} \(from start: \d+,\d{3}\)
38+
Process \[four\] #4\. Spent \(pack 1 elements\) time: \d+,\d{3} \(from start: \d+,\d{3}\)
39+
/
40+
41+
def "each: static simple call"() {
42+
when:
43+
ProgressLogger.each(digitsList){
44+
println it // Some long run operation
45+
}{
46+
sb.append(it).append('\n')
47+
}
48+
then:
49+
sb.length() > 0
50+
sb ==~ digitsListResultRegexp
51+
}
52+
53+
def "next: default variant. Java-style loop"() {
54+
given:
55+
ProgressLogger pl = new ProgressLogger(digitsList, bufferWrite);
56+
57+
when:
58+
for (Object obj in digitsList){
59+
pl.next()
60+
};
61+
then:
62+
sb ==~ digitsListResultRegexp
63+
}
64+
65+
def "next: unknown amount of elements"() {
66+
given:
67+
ProgressLogger pl = new ProgressLogger(-1, bufferWrite);
68+
69+
when:
70+
digitsList.each{
71+
sleep new Random().nextInt(100)
72+
pl.next()
73+
};
74+
then:
75+
sb ==~ digitsStreamResultRegexp
76+
}
77+
78+
def "next: unknown amount of elements, call next with Closure argument"() {
79+
given:
80+
ProgressLogger pl = new ProgressLogger(-1, bufferWrite);
81+
82+
when:
83+
digitsList.each{
84+
pl.next { sleep new Random().nextInt(100) }
85+
};
86+
then:
87+
sb ==~ digitsStreamResultRegexp
88+
}
89+
90+
def "next: unknown amount of elements, call next with Closure argument, Groovy Map-stype constructor"() {
91+
given:
92+
ProgressLogger pl = new ProgressLogger(outMethod: bufferWrite);
93+
94+
when:
95+
digitsList.each{
96+
pl.next { sleep new Random().nextInt(100) }
97+
};
98+
then:
99+
sb ==~ digitsStreamResultRegexp
100+
}
101+
102+
def "next: unknown amount of elements, call next with String argument"() {
103+
given:
104+
ProgressLogger pl = new ProgressLogger(-1, bufferWrite);
105+
106+
when:
107+
objectsList.each{
108+
pl.next it
109+
};
110+
then:
111+
sb ==~ objectsStreamResultRegexp
112+
}
113+
114+
def "next: unknown amount of elements, call next with Closure argument, Groovy Map-stype constructor, alternative processName (string prefix)"() {
115+
given:
116+
ProgressLogger pl = new ProgressLogger(outMethod: bufferWrite, processName: 'Run test');
117+
118+
when:
119+
objectsList.each{
120+
pl.next it
121+
sleep new Random().nextInt(100)
122+
};
123+
then:
124+
sb ==~ objectsStreamResultRegexp.replaceAll('Process ', 'Run test ')
125+
}
126+
127+
def "measure: simple test"() {
128+
when:
129+
ProgressLogger.measure(bufferWrite, { println 'Some heavy work' }, 'Doing cool work!')
130+
then:
131+
sb.length() > 0
132+
sb ==~ /Stop processing \[Doing cool work!\] \(Total processed 1\)\. Spent: 0,\d{3}\.\n/
133+
}
134+
}

0 commit comments

Comments
 (0)