Gathering information from HotSpot garbage collection logs

What is below is a useful script to print actionable information from garbage collection logs. As shown by the CMS output below, this is built for the CMS collector. Anything with initial-mark or remark in the output is a “stop the world” operation. You can take the seconds in the last column to determine how often your application was stopped performing these operations for a tenured collection.

-bash-4.1$ awk '$0 ~ "CMS" {i=1;while(++i <= NF) {if ($i ~ "CMS") {gsub("\\[","",$i);component=$i} else if ($i ~ "real=") {split($i,t,"=");gsub(":","",$1);printf("%-40s %-8.2f %-8.2f %-8.2f\n",component,$1-t[2],$1,t[2])}}}' gc.log
CMS-initial-mark:                        1115.69  1116.06  0.37
CMS-concurrent-mark:                     1116.44  1162.68  46.24
CMS-concurrent-preclean:                 1162.68  1171.75  9.07
CMS-concurrent-abortable-preclean:       1171.75  1171.94  0.19
CMS-remark:                              1172.15  1172.50  0.35
CMS-concurrent-sweep:                    1172.85  1206.67  33.82
CMS-concurrent-reset:                    1206.67  1206.71  0.04
CMS-initial-mark:                        1990.37  1990.89  0.53
CMS-concurrent-mark:                     1991.44  2052.91  61.47
CMS-concurrent-preclean:                 2052.91  2056.52  3.61
CMS-concurrent-abortable-preclean:       2056.52  2059.38  2.86
CMS-remark:                              2058.34  2059.38  1.04
CMS-concurrent-sweep:                    2060.43  2161.88  101.45
CMS-concurrent-reset:                    2162.57  2163.41  0.84
CMS-initial-mark:                        2301.79  2302.06  0.27
CMS-concurrent-mark:                     2302.35  2394.26  91.91
CMS-concurrent-preclean:                 2394.26  2415.15  20.89
CMS-concurrent-abortable-preclean:       2415.15  2418.56  3.41
CMS-remark:                              2418.13  2418.56  0.43
CMS-concurrent-sweep:                    2419.01  2519.19  100.18
CMS-concurrent-reset:                    2519.19  2519.21  0.02
CMS-initial-mark:                        2559.49  2559.67  0.18
CMS-concurrent-mark:                     2559.86  2656.81  96.95
CMS-concurrent-preclean:                 2656.82  2675.72  18.90
CMS-concurrent-abortable-preclean:       2675.72  2678.90  3.18
CMS-remark:                              2678.00  2678.90  0.90
CMS-concurrent-sweep:                    2679.82  2763.69  83.87
CMS-concurrent-reset:                    2763.68  2763.72  0.04
CMS-initial-mark:                        3062.84  3062.99  0.15
CMS-concurrent-mark:                     3063.15  3166.53  103.38
CMS-concurrent-preclean:                 3166.56  3203.33  36.77
CMS-remark:                              3202.78  3203.34  0.56
CMS-concurrent-sweep:                    3203.92  3305.79  101.87
CMS-concurrent-reset:                    3305.78  3306.19  0.41
CMS-initial-mark:                        3307.88  3308.08  0.20
-bash-4.1$

Leave a Reply

Your email address will not be published. Required fields are marked *

This site uses Akismet to reduce spam. Learn how your comment data is processed.