GC Log Analysis for JVM

Jvm gc log initial experience
GC Parameters
-The verbose. GC switch displays the GC operation content. Open it to display the time when the busiest and idle collection behaviors occur, the memory size before and after collection, and the time required for collection. Turn on the-XX: + printgcdetails switch to learn more about GC changes. Turn on the-XX: + printgctimestamps switch to learn about the time of the garbage collection, measured in seconds after the JVM starts. Finally, you can use the-XX: + printheapatgc switch to learn more about the heap. To learn about the new domain, you can use the-XX: = printtenuringdistribution switch to get the object permission for the validity period.

 

 

 

After the WebLogic Server is started, logs are generated.
0.000: [full GC 0.000: [tenured: 0 k-> 4260 K (1023104 K), 0.1055162 secs] 30082 K-> 4260 K (1138240 K), 0.1057452 secs]
4.628: [full GC 4.628: [tenured: 4260 K-> 6546 K (1023104 K), 0.1354001 secs] 39901 K-> 6546 K (1138240 K), 0.1356303 secs]
6.176: [full GC 6.176: [tenured: 6546 K-> 7961 K (1023104 K), 0.1651181 secs] 21755 K-> 7961 K (1138240 K), 0.1653515 secs]
12.859: [full GC 12.859: [tenured: 7961 K-> 12270 K (1023104 K), 0.2777087 secs] 47887 K-> 12270 K (1138240 K), 0.2779328 secs]
17.641: [GC 17.641: [defnew: 102397 K-> 3032 K (115136 K), 0.0495016 secs] 114668 K-> 15303 K (1138240 K), 0.0497269 secs]
28.348: [full GC 28.348: [tenured: 12270 K-> 15435 K (1023104 K), 0.2675010 secs] 75659 K-> 15435 K (1138240 K), 0.2677256 secs]
40.499: [GC 40.499: [defnew: 102399 K-> 12736 K (115136 K), 0.3827322 secs] 117835 K-> 45861 K (1138240 K), 0.3831325 secs]
48.871: [GC 48.871: [defnew: 115136 K-> 12736 K (115136 K), 0.5656438 secs] 148261 K-> 85635 K (1138240 K), 0.5657204 secs]
56.585: [GC 56.585: [defnew: 115135 K-> 12736 K (115136 K), 0.4458067 secs] 188035 K-> 118444 K (1138240 K), 0.4458949 secs]
66.213: [GC 66.213: [defnew: 115135 K-> 12736 K (115136 K), 0.3692542 secs] 220844 K-> 144890 K (1138240 K), 0.3693315 secs]
76.251: [GC 76.251: [defnew: 115135 K-> 12735 K (115136 K), 0.2650355 secs] 247289 K-> 174145 K (1138240 K), 0.2651241 secs]
82.396: [GC 82.397: [defnew: 115135 K-> 12735 K (115136 K), 0.1989967 secs] 276545 K-> 217355 K (1138240 K), 0.1990755 secs]
89.504: [GC 89.504: [defnew: 115135 K-> 12735 K (115136 K), 0.2733299 secs] 319755 K-> 291353 K (1138240 K), 0.2734123 secs]
95.257: [GC 95.258: [defnew: 115135 K-> 12736 K (115136 K), 0.3487282 secs] 399385 K-> 340864 K (1138240 K), 0.3488096 secs]
98.271: [GC 98.271: [defnew: 115135 K-> 12735 K (115136 K), 0.4132144 secs] 443264 K-> 388184 K (1138240 K), 0.4132912 secs]
101.577: [GC 101.577: [defnew: 115135 K-> 12736 K (115136 K), 0.5328404 secs] 513112 K-> 470981 K (1138240 K), 0.5329206 secs]
105.371: [GC 105.371: [defnew: 115135 K-> 12736 K (115136 K), 0.6153580 secs] 573381 K-> 532211 K (1138240 K), 0.6154395 secs]
182.208: [GC 182.208: [defnew: 115136 K-> 12736 K (115136 K), 0.4843296 secs] 634611 K-> 564985 K (1138240 K), 0.4844138 secs]
191.752: [GC 191.752: [defnew: 115135 K-> 12735 K (115136 K), 0.5217968 secs] 667385 K-> 603813 K (1138240 K), 0.5218681 secs]
201.570: [GC 201.570: [defnew: 115135 K-> 12735 K (115136 K), 0.4042610 secs] 706213 K-> 638724 K (1138240 K), 0.4043473 secs]
211.013: [GC 211.013: [defnew: 115135 K-> 12736 K (115136 K), 0.3656211 secs] 741123 K-> 668281 K (1138240 K), 0.3656906 secs]
223.204: [GC 223.204: [defnew: 115136 K-> 12736 K (115136 K), 0.2736965 secs] 770681 K-> 690113 K (1138240 K), 0.2737970 secs]
228.496: [GC 228.496: [defnew: 115135 K-> 12735 K (115136 K), 0.2129989 secs] 792513 K-> 733502 K (1138240 K), 0.2130814 secs]
236.952: [GC 236.952: [defnew: 115134 K-> 12736 K (115136 K), 0.2766950 secs] 858428 K-> 814409 K (1138240 K), 0.2767798 secs]
After a large amount of data is queried, logs increase.
588.865: [GC 588.865: [defnew: 115135 K-> 12736 K (115136 K), 0.0928617 secs] 916809 K-> 824497 K (1138240 K), 0.0929371 secs]
725.903: [GC 725.903: [defnew: 115135 K-> 12736 K (115136 K), 0.1385650 secs] 926897 K-> 837837 K (1138240 K), 0.1386372 secs]
736.062: [GC 736.062: [defnew: 115136 K-> 12736 K (115136 K), 0.3076112 secs] 940237 K-> 860163 K (1138240 K), 0.3076883 secs]
750.298: [GC 750.298: [defnew: 115135 K-> 12736 K (115136 K), 0.2565046 secs] 962563 K-> 882354 K (1138240 K), 0.2565766 secs]
758.875: [GC 758.875: [defnew: 115135 K-> 12736 K (115136 K), 0.2601905 secs] 984754 K-> 904344 K (1138240 K), 0.2602707 secs]
764.257: [GC 764.258: [defnew: 115135 K-> 12736 K (115136 K), 0.2654858 secs] 1006744 K-> 926708 K (1138240 K), 0.2655555 secs]
769.393: [GC 769.393: [defnew: 115135 K-> 115135 K (115136 K), 0.0000126 secs] 769.393: [tenured: 913972 K-> 413259 K (1023104 K ), 2.8389837 secs] 1029108 K-> 413259 K (1138240 K), 2.8391320 secs]
Currently, defnew and tenured are not quite clear. Literally, tenured is used by the system, and defnew is dynamically increased.
Time Point [GC Start Time: [Dynamic Allocation: Initial Value-> allocation value (available value), consumption time] Initial Value-> occupied value (available value) after recycling, consumption time]
764.257: [GC 764.258: [defnew: 115135 K-> 12736 K (115136 K), 0.2654858 secs] 1006744 K-> 926708 K (1138240 K), 0.265555