Reporting of gc+stats

[Justinas Dabravolskas]

Hello Roman,


---- On Fri, 21 Feb 2020 15:24:24 +0200 Roman Kennke <rkennke at redhat.com> wrote ----

 > Hello Justinas, 
 >  
 > I apologize for the late reply. 
 >  
 > > hope this is the right place to ask  a few more questions. Sorry if answers were simply overlooked. 
 >  
 > Sure, here is perfect. We usually don't take so long to reply. :-) 
 >  
 > > 1. I can't find an option for periodic printing of pacer statistics.  (gc+stats prints just on exit?) 
 > > Pacers activity looks like the first indication of gc pressure. Don't you think it would be useful to get this information from gc log asap? 
 > > Maybe you can introduce ShenandoahPacerStatsPeriod flag for periodic printing of _delays histogram? 
 >  
 > That sounds like a good idea. We may actually want more more general 
 > periodic statistics, not only about pacing. I filed the following bug 
 > about it: 
 >  
 > https://bugs.openjdk.java.net/browse/JDK-8239786 

Thank you, additional statistics sounds great and it will help identify gc related issues.

 >  
 > > 1. How to interpret breakdown of roots scanning? 
 > > e.g.: "Scan Roots" took 327s, but I can't figure out what part exactly from breakdown. What I am missing? 
 >  
 > the individual parts 'S: *' are averages over all workers. That means if 
 > one tasks (here: CLDG Roots) is not very well parallelized, it will 
 > report a low average. Consider what will happen if it's perfectly 
 > serial, and we have 4 workers, 1 worker needs 320ms, but the others are 
 > basically idle or get almost no work. It will average to 80ms, but the 
 > total (reported in "Scan Roots") will add-up to 320+ms. We realize this 
 > is confusing and we should improve this. 
 >  
 > Does that answer your question? 

It does. Though it is not obvious how to estimate actual impact of sub-phases to pause time from current log format.


Regards,
Justinas

 >  
 > Thank you, 
 > Roman 
 >  
 >  
 > > [2020-01-21T07:33:24.757-0500][info ][gc,stats     ] Pause Init Mark (N)         =   338.46 s (a =    51057 us) (n =  6629) (lvls, us =     4023,    45508,    50781,    56641,    88198) 
 > > [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]   Accumulate Stats          =     1.42 s (a =      214 us) (n =  6629) (lvls, us =       33,      182,      209,      236,     3329) 
 > > [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]   Make Parsable             =     6.10 s (a =      920 us) (n =  6629) (lvls, us =       55,      732,      891,     1074,     6075) 
 > > [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]   Clear Liveness            =     1.29 s (a =      195 us) (n =  6629) (lvls, us =       91,      168,      189,      211,     3251) 
 > > [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]   Scan Roots                =   327.02 s (a =    49332 us) (n =  6629) (lvls, us =     3613,    43945,    49023,    54688,    86252) 
 > > [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]     S: Thread Roots         =     6.68 s (a =     1008 us) (n =  6629) (lvls, us =      137,      869,      994,     1113,     9622) 
 > > [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]     S: Universe Roots       =     0.08 s (a =       12 us) (n =  6629) (lvls, us =        2,        8,        9,       13,     4443) 
 > > [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]     S: JNI Roots            =     0.37 s (a =       55 us) (n =  6629) (lvls, us =        4,       37,       46,       59,     8601) 
 > > [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]     S: Synchronizer Roots   =     0.00 s (a =        1 us) (n =  6629) (lvls, us =        0,        0,        0,        1,       22) 
 > > [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]     S: Management Roots     =     0.06 s (a =        8 us) (n =  6629) (lvls, us =        1,        3,        8,       11,      102) 
 > > [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]     S: System Dict Roots    =     0.54 s (a =       81 us) (n =  6629) (lvls, us =       16,       61,       74,       89,     4439) 
 > > [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]     S: CLDG Roots           =    80.66 s (a =    12167 us) (n =  6629) (lvls, us =      811,     9004,    11133,    14453,    27327) 
 > > [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]     S: JVMTI Roots          =     0.50 s (a =       75 us) (n =  6629) (lvls, us =        7,       48,       62,       79,    12281) 
 > > [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]   Resize TLABs              =     0.95 s (a =      143 us) (n =  6629) (lvls, us =        7,      104,      133,      172,     1513) 
 > > 
 >  
 >