No way to filter warmup iterations in CSV output

[stefanodoni]

Hi,

Thanks a lot for this great suite!

I like very much the warmup capability you included, it's very handy. However, when reporting results to CSV, all iterations are shown and there's no way to figure out the warmup ones to exclude them.

$ time java -jar renaissance-gpl-0.9.0.jar --policy fixed-warmup -w 5 -t 10 --csv scrabble-results.csv scrabble
====== scrabble (jdk-streams), warmup iteration 0 started ======
====== scrabble (jdk-streams), warmup iteration 0 completed (2298.169 ms) ======
====== scrabble (jdk-streams), warmup iteration 1 started ======
====== scrabble (jdk-streams), warmup iteration 1 completed (1090.806 ms) ======
====== scrabble (jdk-streams), warmup iteration 2 started ======
====== scrabble (jdk-streams), warmup iteration 2 completed (1022.4 ms) ======
====== scrabble (jdk-streams), warmup iteration 3 started ======
====== scrabble (jdk-streams), warmup iteration 3 completed (873.914 ms) ======
====== scrabble (jdk-streams), iteration 0 started ======
====== scrabble (jdk-streams), iteration 0 completed (894.408 ms) ======
====== scrabble (jdk-streams), iteration 1 started ======
====== scrabble (jdk-streams), iteration 1 completed (858.716 ms) ======
====== scrabble (jdk-streams), iteration 2 started ======
====== scrabble (jdk-streams), iteration 2 completed (844.588 ms) ======
====== scrabble (jdk-streams), iteration 3 started ======
====== scrabble (jdk-streams), iteration 3 completed (794.758 ms) ======
====== scrabble (jdk-streams), iteration 4 started ======
====== scrabble (jdk-streams), iteration 4 completed (817.903 ms) ======
====== scrabble (jdk-streams), iteration 5 started ======
====== scrabble (jdk-streams), iteration 5 completed (793.681 ms) ======
====== scrabble (jdk-streams), iteration 6 started ======
====== scrabble (jdk-streams), iteration 6 completed (765.215 ms) ======
====== scrabble (jdk-streams), iteration 7 started ======
====== scrabble (jdk-streams), iteration 7 completed (762.98 ms) ======
====== scrabble (jdk-streams), iteration 8 started ======
====== scrabble (jdk-streams), iteration 8 completed (863.989 ms) ======
====== scrabble (jdk-streams), iteration 9 started ======
====== scrabble (jdk-streams), iteration 9 completed (768.095 ms) ======
====== scrabble (jdk-streams), iteration 10 started ======
====== scrabble (jdk-streams), iteration 10 completed (814.056 ms) ======
====== scrabble (jdk-streams), iteration 11 started ======
====== scrabble (jdk-streams), iteration 11 completed (773.084 ms) ======
====== scrabble (jdk-streams), iteration 12 started ======
====== scrabble (jdk-streams), iteration 12 completed (834.222 ms) ======

real 0m17,026s
user 0m54,189s
sys 0m1,157s

$ cat scrabble-results.csv
benchmark,nanos,unixts.after,unixts.before
scrabble,2298169682,1581519536244,1581519533946
scrabble,1090806936,1581519537338,1581519536247
scrabble,1022400184,1581519538361,1581519537339
scrabble,873914643,1581519539235,1581519538362
scrabble,894408976,1581519540130,1581519539236
scrabble,858716447,1581519540989,1581519540131
scrabble,844588372,1581519541834,1581519540990
scrabble,794758079,1581519542629,1581519541835
scrabble,817903416,1581519543448,1581519542630
scrabble,793681113,1581519544242,1581519543448
scrabble,765215438,1581519545008,1581519544242
scrabble,762980104,1581519545771,1581519545008
scrabble,863989686,1581519546635,1581519545771
scrabble,768095741,1581519547404,1581519546636
scrabble,814056603,1581519548218,1581519547404
scrabble,773084915,1581519548992,1581519548219
scrabble,834222124,1581519549826,1581519548992

$ wc -l scrabble-results.csv
18 scrabble-results.csv

[ceresek]

Hi Stefano,

actually, we've removed the fixed warmup policy, fearing it might be misleading. What exactly are you after - do you just need to label a certain number of initial iterations, or are you after some actual warmup detection ?

Petr

[stefanodoni]

Hi Petr,

Thanks for the quick answer.

I'm looking for a way to measure renaissance benchmarks under various conditions. I need a way to measure the benchmark metric (i.e. duration) when the JVM has stabilized so that it's repeatable.

Automatic detection of warmup I guess would be the ultimate feature, however, I feel it's not easy to do due to JVM behavior.

The simplest option would be to play manually with the warmup period and then output the duration of the post-warmup iterations. A label would work great I think!

May you elaborate more on the fixed warmup policy removal and if is there are any other feature planned to deal with warmup issues?

[ceresek]

Hi Stefano,

starting with 0785c1e (actually a bit earlier but there were fixes later), the output contains the uptime_ns field, which should give an accurate time from the start of the JVM to the start of the given repetition. This field can be used to drop results from repetitions before whatever warmup limit you choose. This may be a bit more practical than a boolean flag, because you can choose the limit to filter on post hoc.

You are right, automated warmup detection is difficult, in part because it is difficult to define what exactly is warmup. In some of our experiments, we look for the JIT compilation activity to subside. If this would help, you can use the jmx-timers plugin, it will extend the output with fields giving the number and duration of JIT compilation events as reported by the CompilationMXBean class. Looking for certain number of iterations (or time) with minimum JIT activity (but not zero, in some situations JIT compilation may never stop entirely) in the output is then relatively easy. Obviously, there may be other warmup mechanisms besides JIT that this would not catch.

Personally, I would say too much sophistication in warmup detection is not a good thing. It is much safer to set a fixed limit after which warmup should realistically be over, and then filter accordingly.

Hope this helps, Petr