JVM GC output for minboxing bug #188

bug188-gc.md

Bug: miniboxing/miniboxing-plugin#188

Below are the full outputs. But let's take a typical loop in the generic code:

restarting timing
[GC 631036K->45244K(2043392K), 0.0217070 secs]
[GC 636604K->50652K(2049024K), 0.0495480 secs]
[GC 649692K->40220K(2045952K), 0.0023550 secs]
805 ms for 100 iterations

and in the miniboxed code:

restarting timing
[GC 647294K->53662K(2054656K), 0.0600430 secs]
[GC 668062K->43102K(2055168K), 0.0294820 secs]
[GC 657502K->32350K(2058240K), 0.0020950 secs]
[GC 652382K->58782K(2045440K), 0.0822990 secs]
[GC 678814K->53822K(2055168K), 0.0630260 secs]
1026 ms for 100 iterations

Let's compute the overall GC time:

• generic: 73 ms - benchmark time minus GC: 732ms
• miniboxed: 236 ms- benchmark time minus GC: 790ms

Although still a bit slower, it looks like the miniboxed code is mostly slowed down by GC, not by boxing or megamorphic sites.

Also, the main reason the generic code is faster when reversing the list is because the boxed integer is not touched -- it's passed from one node to the other (in the reveresed list) as a reference -- its actual value is never extracted and a new box is never created. Passing a reference is faster than passing two values on the stack, namely the miniboxed value and the class tag (which keeps track of the original type encoded in the miniboxed value), so this should explain why the miniboxed code is slightly slower.

Also, the GC cycle count, that is consistently more in the miniboxed case occurs due to the fact that the boxed integer is shared among generic reversed lists, while it is encoded in each node for the miniboxed version of the code. See this drawing for an explanation:

As soon as we map a function over the list we should start seeing the benefits of miniboxing, since then the generic version needs to extract the value from the boxed integer and produce another value and box it, which is much more effort than passing the miniboxed value around. :)

Full output

Generic

$ mb-scalac gh-bug-188.scala -P:minibox:off
Picked up _JAVA_OPTIONS: -Xms2g -Xmx2g -Xss4m -XX:+CMSClassUnloadingEnabled -XX:MaxPermSize=512M -XX:ReservedCodeCacheSize=256m -XX:PermSize=256m -XX:+TieredCompilation -XX:+UseNUMA
Miniboxing plugin warning: Turning off all minboxing specialization!
Miniboxing plugin warning: Optimizing `MbArray` is disabled, thus `MbArray`-s will be generic and will box.

$ mb-scala brique.Test -J-verbose:gc
Picked up _JAVA_OPTIONS: -Xms2g -Xmx2g -Xss4m -XX:+CMSClassUnloadingEnabled -XX:MaxPermSize=512M -XX:ReservedCodeCacheSize=256m -XX:PermSize=256m -XX:+TieredCompilation -XX:+UseNUMA
[GC 525312K->41992K(2010624K), 0.3673340 secs]
[GC 567304K->46288K(2010624K), 0.2882960 secs]
[GC 571600K->55920K(2010624K), 0.2037140 secs]
[GC 581232K->42160K(2010624K), 0.3471210 secs]
2146 ms for 100 iterations
not timed:
[GC 399631K->39856K(2010624K), 0.3815340 secs]
[Full GC 39856K->39695K(2010624K), 0.3530280 secs]
restarting timing
[GC 565007K->45999K(2032640K), 0.0268690 secs]
[GC 593327K->54255K(2010624K), 0.0587080 secs]
[GC 601583K->62575K(2032128K), 0.1054220 secs]
[GC 629871K->43951K(1970176K), 0.0199340 secs]
954 ms for 100 iterations
not timed:
[GC 214220K->39703K(2027008K), 0.0005950 secs]
[Full GC 39703K->39676K(2027008K), 0.4080120 secs]
restarting timing
[GC 600828K->61948K(2028544K), 0.0997110 secs]
[GC 623100K->60540K(2034688K), 0.0871240 secs]
[GC 630908K->44956K(2031616K), 0.0212170 secs]
[GC 615324K->52828K(2036736K), 0.0509450 secs]
984 ms for 100 iterations
not timed:
[GC 144949K->39676K(2034688K), 0.0006590 secs]
[Full GC 39676K->39676K(2034688K), 0.2416170 secs]
restarting timing
[GC 615164K->52796K(2038784K), 0.0578400 secs]
[GC 631868K->45916K(2036224K), 0.0300660 secs]
[GC 624988K->62524K(2042880K), 0.1087770 secs]
[GC 649788K->40284K(2040320K), 0.0028480 secs]
937 ms for 100 iterations
not timed:
[GC 63785K->39676K(2043904K), 0.0025090 secs]
[Full GC 39676K->39676K(2043904K), 0.2379750 secs]
restarting timing
[GC 631036K->45244K(2043392K), 0.0217070 secs]
[GC 636604K->50652K(2049024K), 0.0495480 secs]
[GC 649692K->40220K(2045952K), 0.0023550 secs]
805 ms for 100 iterations
not timed:
[GC 603582K->39676K(2051584K), 0.0010800 secs]
[Full GC 39676K->39676K(2051584K), 0.2413990 secs]
restarting timing
[GC 645372K->59548K(2050048K), 0.0944640 secs]
[GC 665244K->55932K(2053632K), 0.0805920 secs]
[GC 665212K->55772K(2051584K), 0.0633230 secs]
970 ms for 100 iterations
not timed:
[GC 579913K->39676K(2056192K), 0.0006880 secs]
[Full GC 39676K->39676K(2056192K), 0.2423920 secs]
restarting timing
[GC 655612K->46428K(2055680K), 0.0222980 secs]
[GC 662364K->52924K(2060288K), 0.0433860 secs]
[GC 675516K->42684K(2058240K), 0.0143510 secs]
823 ms for 100 iterations
not timed:
[GC 540856K->39676K(2062336K), 0.0006280 secs]
[Full GC 39676K->39676K(2062336K), 0.2441470 secs]
restarting timing
[GC 667388K->58172K(2061312K), 0.0886530 secs]
[GC 685884K->53084K(2062848K), 0.0635810 secs]
[GC 681308K->48476K(2061312K), 0.0423520 secs]
930 ms for 100 iterations
not timed:
[GC 513421K->39676K(2065408K), 0.0006370 secs]
[Full GC 39676K->39676K(2065408K), 0.2590800 secs]
restarting timing
[GC 674044K->41340K(2064896K), 0.0060540 secs]
[GC 675708K->42940K(2067456K), 0.0134130 secs]
[GC 680892K->48028K(2066432K), 0.0342960 secs]
787 ms for 100 iterations
not timed:
[GC 494631K->39676K(2070016K), 0.0006770 secs]
[Full GC 39676K->39676K(2070016K), 0.2371530 secs]
restarting timing
[GC 683260K->50556K(2069504K), 0.0423740 secs]
[GC 694140K->61372K(2063872K), 0.0960250 secs]
[GC 700348K->44124K(2067456K), 0.0170660 secs]
911 ms for 100 iterations
not timed:
[GC 465871K->39676K(2069504K), 0.0274410 secs]
[Full GC 39676K->39676K(2069504K), 0.2777770 secs]
restarting timing
[GC 682236K->49532K(2068992K), 0.0438550 secs]
[GC 692092K->59292K(2066432K), 0.0810840 secs]
[GC 700316K->44060K(2068480K), 0.0160900 secs]
911 ms for 100 iterations
not timed:
[GC 467150K->39676K(2070016K), 0.0006360 secs]
[Full GC 39676K->39676K(2070016K), 0.2416630 secs]
restarting timing
[GC 683260K->50588K(2069504K), 0.0451200 secs]
[GC 694172K->61308K(2064384K), 0.0953350 secs]
[GC 700284K->44124K(2067456K), 0.0175040 secs]
893 ms for 100 iterations
not timed:
[GC 465857K->39676K(2068992K), 0.0006160 secs]
[Full GC 39676K->39676K(2068992K), 0.2862980 secs]
restarting timing
[GC 681724K->49052K(2068992K), 0.0420360 secs]
[GC 691100K->58300K(2066432K), 0.0791670 secs]
[GC 699324K->43068K(2068480K), 0.0163040 secs]
875 ms for 100 iterations
not timed:
[GC 466150K->39676K(2070016K), 0.0008600 secs]
[Full GC 39676K->39676K(2070016K), 0.2412090 secs]
restarting timing
[GC 683260K->50556K(2069504K), 0.0473190 secs]
[GC 694140K->61340K(2064896K), 0.1000210 secs]
[GC 701340K->45084K(2067968K), 0.0240410 secs]
917 ms for 100 iterations
not timed:
[GC 467488K->39676K(2069504K), 0.0009300 secs]
[Full GC 39676K->39676K(2069504K), 0.2421750 secs]
restarting timing
[GC 682236K->49564K(2068992K), 0.0457390 secs]
[GC 692124K->59324K(2065920K), 0.0820170 secs]
[GC 700348K->44092K(2068480K), 0.0217140 secs]
889 ms for 100 iterations
not timed:
[GC 467170K->39676K(2070016K), 0.0008080 secs]
[Full GC 39676K->39676K(2070016K), 0.2375010 secs]
restarting timing
[GC 683260K->50620K(2069504K), 0.0424870 secs]
[GC 694204K->61340K(2064384K), 0.1035480 secs]
[GC 700316K->44124K(2067456K), 0.0152600 secs]
896 ms for 100 iterations
not timed:
[GC 465849K->39676K(2068992K), 0.0007660 secs]
[Full GC 39676K->39676K(2068992K), 0.2499200 secs]
restarting timing
[GC 681724K->49052K(2068992K), 0.0443510 secs]
[GC 691100K->58300K(2067456K), 0.0855200 secs]
[GC 700348K->44092K(2068992K), 0.0147260 secs]
894 ms for 100 iterations
not timed:
[GC 467844K->39676K(2070016K), 0.0007930 secs]
[Full GC 39676K->39676K(2070016K), 0.2398630 secs]
restarting timing
[GC 683772K->51100K(2070016K), 0.0487530 secs]
[GC 695196K->62364K(2063872K), 0.1014920 secs]
[GC 701340K->45052K(2067456K), 0.0236120 secs]
916 ms for 100 iterations
not timed:
[GC 466776K->39676K(2068992K), 0.0006090 secs]
[Full GC 39676K->39676K(2068992K), 0.2363330 secs]
restarting timing
[GC 681212K->48540K(2068480K), 0.0341510 secs]
[GC 690076K->57276K(2067968K), 0.0759590 secs]
[GC 700348K->44060K(2069504K), 0.0172760 secs]
911 ms for 100 iterations
not timed:
[GC 471458K->39676K(2070528K), 0.0009000 secs]
[Full GC 39676K->39676K(2070528K), 0.2398930 secs]
restarting timing
[GC 684796K->52124K(2070528K), 0.0604530 secs]
[GC 697244K->40956K(2071552K), 0.0048450 secs]
[GC 687612K->54844K(2060288K), 0.0587040 secs]
861 ms for 100 iterations
not timed:
[GC 470587K->39676K(2071040K), 0.0006040 secs]
[Full GC 39676K->39676K(2071040K), 0.2483600 secs]
restarting timing
[GC 685308K->52636K(2070528K), 0.0591590 secs]
[GC 698268K->42044K(2071552K), 0.0104910 secs]
[GC 688700K->55868K(2061312K), 0.0754380 secs]
888 ms for 100 iterations
not timed:
[GC 470951K->39676K(2070528K), 0.0006990 secs]
[Full GC 39676K->39676K(2070528K), 0.2413770 secs]
restarting timing
[GC 684796K->52092K(2070528K), 0.0555850 secs]
[GC 697212K->40924K(2071552K), 0.0045720 secs]
[GC 687580K->54876K(2060288K), 0.0671600 secs]
882 ms for 100 iterations
not timed:
[GC 469531K->39676K(2071040K), 0.0007810 secs]
[Full GC 39676K->39676K(2071040K), 0.2477450 secs]
restarting timing
[GC 685308K->46084K(2070528K), 0.0299420 secs]
[GC 691716K->58956K(2067456K), 0.0823640 secs]
[GC 703052K->46732K(2070016K), 0.0347800 secs]
881 ms for 100 iterations
not timed:
[GC 472366K->39692K(2072064K), 0.0006910 secs]
[Full GC 39692K->39676K(2072064K), 0.2404140 secs]
restarting timing
[GC 687356K->54684K(2061312K), 0.0620570 secs]
[GC 702364K->46108K(2072576K), 0.0258600 secs]
[GC 693788K->60988K(2067456K), 0.0978380 secs]
921 ms for 100 iterations
not timed:
[GC 462875K->39676K(2069504K), 0.0007570 secs]
[Full GC 39676K->39676K(2069504K), 0.2380860 secs]
restarting timing
[GC 682748K->50044K(2069504K), 0.0398900 secs]
[GC 693116K->60380K(2064896K), 0.0828290 secs]
[GC 700380K->44060K(2067968K), 0.0164680 secs]
872 ms for 100 iterations
not timed:
[GC 466682K->39676K(2069504K), 0.0009240 secs]
[Full GC 39676K->39676K(2069504K), 0.2522670 secs]
restarting timing
[GC 682236K->49564K(2068992K), 0.0444880 secs]
[GC 692124K->59260K(2065920K), 0.0964710 secs]
[GC 700284K->44060K(2068480K), 0.0178870 secs]
894 ms for 100 iterations
not timed:
[GC 467280K->39676K(2070016K), 0.0037070 secs]
[Full GC 39676K->39676K(2070016K), 0.2278750 secs]
restarting timing
[GC 683260K->50556K(2069504K), 0.0463790 secs]
[GC 694140K->61372K(2064896K), 0.0969930 secs]
[GC 701372K->45084K(2067968K), 0.0223660 secs]
903 ms for 100 iterations
not timed:
[GC 467578K->39676K(2069504K), 0.0007130 secs]
[Full GC 39676K->39676K(2069504K), 0.2471680 secs]
restarting timing
[GC 682236K->49564K(2068992K), 0.0474070 secs]
[GC 692124K->59292K(2066432K), 0.0859880 secs]
[GC 700316K->44028K(2068480K), 0.0171790 secs]
905 ms for 100 iterations
not timed:
[GC 467165K->39676K(2070016K), 0.0008390 secs]
[Full GC 39676K->39676K(2070016K), 0.2752720 secs]
restarting timing
[GC 683260K->50556K(2069504K), 0.0467180 secs]
[GC 694140K->61340K(2064384K), 0.0921340 secs]
[GC 700316K->44092K(2067456K), 0.0151990 secs]
882 ms for 100 iterations
not timed:
[GC 465855K->39676K(2068992K), 0.0010680 secs]
[Full GC 39676K->39676K(2068992K), 0.2446560 secs]
restarting timing
[GC 681724K->49052K(2068992K), 0.0363090 secs]
[GC 691100K->58300K(2067456K), 0.0826680 secs]
[GC 700348K->44092K(2068992K), 0.0173900 secs]
870 ms for 100 iterations
not timed:
[GC 467869K->39676K(2070016K), 0.0005420 secs]
[Full GC 39676K->39676K(2070016K), 0.2522820 secs]
restarting timing
done

Miniboxed

$ mb-scalac gh-bug-188.scala 
Picked up _JAVA_OPTIONS: -Xms2g -Xmx2g -Xss4m -XX:+CMSClassUnloadingEnabled -XX:MaxPermSize=512M -XX:ReservedCodeCacheSize=256m -XX:PermSize=256m -XX:+TieredCompilation -XX:+UseNUMA

$ mb-scala brique.Test -J-verbose:gc
Picked up _JAVA_OPTIONS: -Xms2g -Xmx2g -Xss4m -XX:+CMSClassUnloadingEnabled -XX:MaxPermSize=512M -XX:ReservedCodeCacheSize=256m -XX:PermSize=256m -XX:+TieredCompilation -XX:+UseNUMA
[GC 525312K->57448K(2010624K), 0.0999900 secs]
[GC 582760K->46000K(2010624K), 0.0730490 secs]
[GC 571312K->40096K(2010624K), 0.0846690 secs]
[GC 565408K->34144K(2010624K), 0.1014480 secs]
[GC 559456K->59520K(2010624K), 0.1009350 secs]
[GC 584832K->53536K(2028544K), 0.0833280 secs]
1350 ms for 100 iterations
not timed:
[GC 132154K->32184K(1959936K), 0.1229250 secs]
[Full GC 32184K->31889K(1959936K), 0.5743770 secs]
restarting timing
[GC 593041K->58161K(2021888K), 0.0874550 secs]
[GC 604977K->42513K(1955840K), 0.0397710 secs]
[GC 589329K->58073K(2022912K), 0.0825540 secs]
[GC 605401K->42905K(2020352K), 0.0335810 secs]
[GC 590233K->58969K(2025472K), 0.0890790 secs]
1104 ms for 100 iterations
not timed:
[GC 445605K->31897K(2022400K), 0.0006760 secs]
[Full GC 31897K->31870K(2022400K), 0.3400890 secs]
restarting timing
[GC 583806K->52702K(2027008K), 0.0688530 secs]
[GC 607710K->45182K(2023936K), 0.0357920 secs]
[GC 600190K->37694K(2029056K), 0.0170040 secs]
[GC 599358K->36798K(2028544K), 0.0126280 secs]
[GC 598462K->36062K(2031616K), 0.0141200 secs]
930 ms for 100 iterations
not timed:
[GC 386999K->31870K(2030080K), 0.0006690 secs]
[Full GC 31870K->31870K(2030080K), 0.2395210 secs]
restarting timing
[GC 597630K->35230K(2034176K), 0.0116500 secs]
[GC 606110K->43678K(2032640K), 0.0369600 secs]
[GC 614558K->52062K(2040832K), 0.0548300 secs]
[GC 635230K->41502K(2038272K), 0.0387080 secs]
[GC 624670K->62142K(2040832K), 0.1015960 secs]
1042 ms for 100 iterations
not timed:
[GC 321293K->31870K(2042368K), 0.0005350 secs]
[Full GC 31870K->31870K(2042368K), 0.2483360 secs]
restarting timing
[GC 620670K->58302K(2042880K), 0.0901120 secs]
[GC 648126K->54366K(2042880K), 0.0710700 secs]
[GC 644190K->50430K(2048000K), 0.0626140 secs]
[GC 647422K->53726K(2044928K), 0.0643370 secs]
[GC 650718K->56926K(2050048K), 0.0767760 secs]
1142 ms for 100 iterations
not timed:
[GC 225999K->31870K(2049536K), 0.0005160 secs]
[Full GC 31870K->31870K(2049536K), 0.2386490 secs]
restarting timing
[GC 635518K->41886K(2051584K), 0.0372470 secs]
[GC 647070K->53374K(2049536K), 0.0727720 secs]
[GC 658558K->33502K(2052608K), 0.0054560 secs]
[GC 642782K->49054K(2052608K), 0.0570790 secs]
[GC 658334K->33214K(2055168K), 0.0049390 secs]
967 ms for 100 iterations
not timed:
[GC 131548K->31870K(2055168K), 0.0050450 secs]
[Full GC 31870K->31870K(2055168K), 0.2398460 secs]
restarting timing
[GC 646270K->52638K(2055680K), 0.0703370 secs]
[GC 668062K->43070K(2055680K), 0.0305350 secs]
[GC 658494K->33438K(2058752K), 0.0056560 secs]
[GC 654494K->60798K(2048512K), 0.0984270 secs]
[GC 681854K->56830K(2052096K), 0.0863430 secs]
1081 ms for 100 iterations
not timed:
[GC 105751K->31870K(2053632K), 0.0006740 secs]
[Full GC 31870K->31870K(2053632K), 0.2382080 secs]
restarting timing
[GC 643198K->49598K(2055680K), 0.0598840 secs]
[GC 663486K->38462K(2054144K), 0.0190910 secs]
[GC 652350K->58622K(2052096K), 0.0913460 secs]
[GC 671998K->47006K(2054656K), 0.0496680 secs]
[GC 660382K->35390K(2058240K), 0.0114670 secs]
1018 ms for 100 iterations
not timed:
[GC 97361K->31870K(2057216K), 0.0006900 secs]
[Full GC 31870K->31870K(2057216K), 0.2373730 secs]
restarting timing
[GC 651390K->57822K(2053120K), 0.0815740 secs]
[GC 673246K->48190K(2055680K), 0.0437280 secs]
[GC 663614K->38526K(2059264K), 0.0163260 secs]
[GC 659582K->34590K(2057728K), 0.0067290 secs]
[GC 655646K->61982K(2051584K), 0.1024350 secs]
1048 ms for 100 iterations
not timed:
[GC 98919K->31870K(2055680K), 0.0008520 secs]
[Full GC 31870K->31870K(2055680K), 0.2378350 secs]
restarting timing
[GC 647294K->53726K(2055168K), 0.0666850 secs]
[GC 669150K->44094K(2055680K), 0.0360760 secs]
[GC 659518K->34494K(2058752K), 0.0090490 secs]
[GC 655550K->61854K(2049536K), 0.0922250 secs]
[GC 682910K->57918K(2052096K), 0.0839210 secs]
1079 ms for 100 iterations
not timed:
[GC 94609K->31870K(2053632K), 0.0006380 secs]
[Full GC 31870K->31870K(2053632K), 0.2541030 secs]
restarting timing
[GC 643198K->49598K(2055168K), 0.0548770 secs]
[GC 662462K->37438K(2053632K), 0.0150090 secs]
[GC 650302K->56542K(2053632K), 0.0772730 secs]
[GC 670942K->45982K(2055168K), 0.0405810 secs]
[GC 660382K->35294K(2058752K), 0.0085250 secs]
990 ms for 100 iterations
not timed:
[GC 97367K->31870K(2057728K), 0.0006990 secs]
[Full GC 31870K->31870K(2057728K), 0.2423090 secs]
restarting timing
[GC 652414K->58814K(2052608K), 0.0833060 secs]
[GC 674238K->49246K(2055680K), 0.0527030 secs]
[GC 664670K->39710K(2058752K), 0.0269590 secs]
[GC 659742K->34622K(2057216K), 0.0076720 secs]
[GC 654654K->60958K(2052608K), 0.0884520 secs]
1052 ms for 100 iterations
not timed:
[GC 97956K->31870K(2056192K), 0.0006800 secs]
[Full GC 31870K->31870K(2056192K), 0.2362050 secs]
restarting timing
[GC 648318K->54718K(2054144K), 0.0626070 secs]
[GC 669118K->44094K(2055168K), 0.0395980 secs]
[GC 658494K->33438K(2058752K), 0.0040400 secs]
[GC 654494K->60830K(2048512K), 0.0940370 secs]
[GC 681886K->56894K(2052096K), 0.0815800 secs]
1083 ms for 100 iterations
not timed:
[GC 105815K->31870K(2053632K), 0.0007720 secs]
[Full GC 31870K->31870K(2053632K), 0.2344670 secs]
restarting timing
[GC 643198K->49566K(2055680K), 0.0609220 secs]
[GC 663454K->38462K(2054144K), 0.0185660 secs]
[GC 652350K->58654K(2052096K), 0.0861280 secs]
[GC 672030K->47038K(2054656K), 0.0491990 secs]
[GC 660414K->35358K(2058240K), 0.0100860 secs]
1029 ms for 100 iterations
not timed:
[GC 97329K->31870K(2057216K), 0.0007320 secs]
[Full GC 31870K->31870K(2057216K), 0.2354320 secs]
restarting timing
[GC 651390K->57790K(2053120K), 0.0828920 secs]
[GC 673214K->48190K(2055680K), 0.0541210 secs]
[GC 663614K->38622K(2059264K), 0.0213300 secs]
[GC 659678K->34590K(2057728K), 0.0071770 secs]
[GC 655646K->62014K(2051584K), 0.0832920 secs]
1040 ms for 100 iterations
not timed:
[GC 98951K->31870K(2055680K), 0.0008570 secs]
[Full GC 31870K->31870K(2055680K), 0.2351210 secs]
restarting timing
[GC 647294K->53662K(2055168K), 0.0689110 secs]
[GC 669086K->44094K(2055680K), 0.0404860 secs]
[GC 659518K->34526K(2058752K), 0.0091180 secs]
[GC 655582K->61854K(2049536K), 0.0976190 secs]
[GC 682910K->57886K(2052096K), 0.0864060 secs]
1094 ms for 100 iterations
not timed:
[GC 94577K->31870K(2053632K), 0.0007440 secs]
[Full GC 31870K->31870K(2053632K), 0.2343330 secs]
restarting timing
[GC 643198K->49630K(2055168K), 0.0479110 secs]
[GC 662494K->37438K(2053632K), 0.0150830 secs]
[GC 650302K->56574K(2053632K), 0.0807150 secs]
[GC 670974K->45982K(2055168K), 0.0466600 secs]
[GC 660382K->35326K(2058752K), 0.0095810 secs]
988 ms for 100 iterations
not timed:
[GC 97399K->31870K(2057728K), 0.0006500 secs]
[Full GC 31870K->31870K(2057728K), 0.2386960 secs]
restarting timing
[GC 652414K->58846K(2052608K), 0.0807000 secs]
[GC 674270K->49214K(2055680K), 0.0598660 secs]
[GC 664638K->39678K(2058752K), 0.0227370 secs]
[GC 659710K->34590K(2057216K), 0.0072280 secs]
[GC 654622K->60990K(2051584K), 0.0981180 secs]
1068 ms for 100 iterations
not timed:
[GC 97927K->31870K(2055680K), 0.0007620 secs]
[Full GC 31870K->31870K(2055680K), 0.2422490 secs]
restarting timing
[GC 647294K->53662K(2055168K), 0.0688610 secs]
[GC 669086K->44094K(2055680K), 0.0417290 secs]
[GC 659518K->34430K(2059264K), 0.0064060 secs]
[GC 655998K->62334K(2050560K), 0.1064080 secs]
[GC 683902K->58910K(2051072K), 0.0900090 secs]
1115 ms for 100 iterations
not timed:
[GC 95539K->31870K(2053120K), 0.0047320 secs]
[Full GC 31870K->31870K(2053120K), 0.2360270 secs]
restarting timing
[GC 642174K->48542K(2055168K), 0.0512130 secs]
[GC 660894K->35902K(2053120K), 0.0125080 secs]
[GC 648254K->54526K(2055168K), 0.0728480 secs]
[GC 669950K->44926K(2055680K), 0.0371570 secs]
[GC 660350K->35262K(2058752K), 0.0082830 secs]
971 ms for 100 iterations
not timed:
[GC 97386K->31870K(2058240K), 0.0007410 secs]
[Full GC 31870K->31870K(2058240K), 0.2333260 secs]
restarting timing
[GC 652926K->59358K(2053120K), 0.0848720 secs]
[GC 675806K->50750K(2056192K), 0.0556500 secs]
[GC 667198K->42206K(2058752K), 0.0269600 secs]
[GC 661726K->36670K(2056704K), 0.0148280 secs]
[GC 656190K->62494K(2051584K), 0.1039790 secs]
1107 ms for 100 iterations
not timed:
[GC 99431K->31870K(2055680K), 0.0006070 secs]
[Full GC 31870K->31870K(2055680K), 0.2269640 secs]
restarting timing
[GC 647294K->53694K(2055168K), 0.0727020 secs]
[GC 669118K->44126K(2055680K), 0.0345750 secs]
[GC 659550K->34526K(2058752K), 0.0088960 secs]
[GC 655582K->61790K(2049536K), 0.0919630 secs]
[GC 682846K->57854K(2052096K), 0.0873330 secs]
1090 ms for 100 iterations
not timed:
[GC 94545K->31870K(2053632K), 0.0006940 secs]
[Full GC 31870K->31870K(2053632K), 0.2392900 secs]
restarting timing
[GC 643198K->43358K(2056192K), 0.0388700 secs]
[GC 657246K->32166K(2053632K), 0.0012790 secs]
[GC 646054K->52422K(2056704K), 0.0645920 secs]
[GC 669894K->44870K(2056704K), 0.0431610 secs]
[GC 662342K->37254K(2060288K), 0.0147690 secs]
972 ms for 100 iterations
not timed:
[GC 99634K->31878K(2059264K), 0.0006490 secs]
[Full GC 31878K->31870K(2059264K), 0.2403090 secs]
restarting timing
[GC 655486K->61950K(2051584K), 0.0945320 secs]
[GC 678398K->53342K(2056192K), 0.0726460 secs]
[GC 669790K->44734K(2058752K), 0.0359310 secs]
[GC 663742K->38750K(2056192K), 0.0161720 secs]
[GC 657758K->32702K(2060288K), 0.0028500 secs]
1038 ms for 100 iterations
not timed:
[GC 70161K->31870K(2059776K), 0.0032700 secs]
[Full GC 31870K->31870K(2059776K), 0.2387120 secs]
restarting timing
[GC 655998K->62462K(2051584K), 0.0986320 secs]
[GC 678910K->53854K(2036736K), 0.0739470 secs]
[GC 670302K->45310K(2058240K), 0.0339440 secs]
[GC 663294K->38302K(2055680K), 0.0187390 secs]
[GC 656286K->62526K(2051584K), 0.0989140 secs]
1116 ms for 100 iterations
not timed:
[GC 99463K->31870K(2055680K), 0.0013160 secs]
[Full GC 31870K->31870K(2055680K), 0.2382000 secs]
restarting timing
[GC 647294K->53662K(2054656K), 0.0600430 secs]
[GC 668062K->43102K(2055168K), 0.0294820 secs]
[GC 657502K->32350K(2058240K), 0.0020950 secs]
[GC 652382K->58782K(2045440K), 0.0822990 secs]
[GC 678814K->53822K(2055168K), 0.0630260 secs]
1026 ms for 100 iterations
not timed:
[GC 102989K->31870K(2055168K), 0.0008570 secs]
[Full GC 31870K->31870K(2055168K), 0.2346500 secs]
restarting timing
[GC 646270K->52734K(2055680K), 0.0689780 secs]
[GC 668158K->43038K(2055680K), 0.0362600 secs]
[GC 658462K->33406K(2058240K), 0.0039370 secs]
[GC 653438K->59806K(2046464K), 0.0968230 secs]
[GC 679838K->54814K(2054144K), 0.0632010 secs]
1056 ms for 100 iterations
not timed:
[GC 103899K->31870K(2054656K), 0.0005540 secs]
[Full GC 31870K->31870K(2054656K), 0.2345830 secs]
restarting timing
[GC 645246K->51646K(2055680K), 0.0694380 secs]
[GC 666558K->41566K(2055168K), 0.0334910 secs]
[GC 656478K->62718K(2049536K), 0.1106600 secs]
[GC 674046K->49054K(2053632K), 0.0404600 secs]
[GC 660382K->35262K(2056704K), 0.0082250 secs]
1062 ms for 100 iterations
not timed:
[GC 96977K->31870K(2056192K), 0.0006950 secs]
[Full GC 31870K->31870K(2056192K), 0.2318160 secs]
restarting timing
[GC 648830K->55198K(2054656K), 0.0713070 secs]
[GC 670622K->45630K(2055680K), 0.0487430 secs]
[GC 661054K->36030K(2059264K), 0.0152570 secs]
[GC 657598K->32542K(2058240K), 0.0020090 secs]
[GC 654110K->60414K(2052608K), 0.0881860 secs]
1033 ms for 100 iterations
not timed:
[GC 97412K->31870K(2056192K), 0.0006570 secs]
[Full GC 31870K->31870K(2056192K), 0.2349530 secs]
restarting timing
[GC 648318K->54686K(2054656K), 0.0676010 secs]
[GC 670110K->45118K(2055680K), 0.0355160 secs]
[GC 660542K->35518K(2059264K), 0.0128190 secs]
[GC 657086K->32030K(2058240K), 0.0010190 secs]
[GC 653598K->59966K(2052608K), 0.0880530 secs]
999 ms for 100 iterations
not timed:
[GC 96964K->31870K(2056192K), 0.0007830 secs]
[Full GC 31870K->31870K(2056192K), 0.2373040 secs]
restarting timing
done