Hi All Cisco CNAMS application runs on the following platform OS: Solaris 9 Webserver: Apache 1.3.27 JDK: JDK 1.4.2 build 28 Servlet Engine: tomcat 3.3.1a
We are noticing some weird GC behaviour when the tomcat does Minor GC. I am pasting some garbage collection logs below 231867.984: [GC 231867.985: [DefNew: 127232K->3840K(127232K), 0.1125831 secs] 288818K->170206K(350384K), 0.1128485 secs] 231946.970: [GC 231946.970: [DefNew: 127232K->3840K(127232K), 0.1348222 secs] 293598K->177196K(350384K), 0.1350464 secs] 231968.052: [GC 231968.052: [DefNew: 127232K->3840K(127232K), 0.1818662 secs] 300588K->182066K(350384K), 0.1821628 secs] 231969.314: [GC 231969.315: [DefNew: 127232K->3543K(127232K), 16.4172505 secs] 305458K->185389K(350384K), 16.4175191 secs] 231987.248: [GC 231987.248: [DefNew: 126935K->3840K(127232K), 10.7419554 secs] 308781K->189356K(350384K), 10.7422411 secs] 231999.225: [GC 231999.225: [DefNew: 127232K->3840K(127232K), 16.1320322 secs] 312748K->196413K(350384K), 16.1323798 secs] 232015.949: [GC 232015.950: [DefNew: 127232K->3840K(127232K), 42.2998381 secs] 319805K->201339K(350384K), 42.3001041 secs] 232058.781: [GC 232058.781: [DefNew: 127232K->3840K(127232K), 146.5896470 secs] 324731K->206361K(350384K), 146.5898922 secs] 232206.831: [GC 232206.832: [DefNew: 127232K->3840K(127232K), 110.7859999 secs] 329753K->211019K(350384K), 110.7862726 secs] 232318.209: [GC 232318.209: [DefNew: 127232K->3840K(127232K), 68.5541489 secs] 334411K->215994K(350384K), 68.5544029 secs] 232387.893: [GC 232387.893: [DefNew: 127232K->3840K(127232K), 126.8755081 secs] 339386K->221793K(350384K), 126.8757738 secs] 232515.276: [GC 232515.276: [DefNew: 127232K->3840K(127232K), 139.7813258 secs]232655.058: [Tenured: 223686K->154822K(223792K), 278.7132327 secs] 345201K->154822K(351024K), 418.4964431 secs] 232934.349: [GC 232934.349: [DefNew: 123392K->3840K(127232K), 164.3069723 secs] 278214K->163782K(385272K), 164.3072616 secs] 233099.848: [GC 233099.848: [DefNew: 127232K->3840K(127232K), 91.4000872 secs] 287174K->169894K(385272K), 91.4005897 secs] 233191.652: [GC 233191.652: [DefNew: 127232K->3840K(127232K), 204.1755072 secs] 293286K->176929K(385272K), 204.1757747 secs] 233396.272: [GC 233396.272: [DefNew: 127232K->3840K(127232K), 101.8621946 secs] 300321K->183426K(385272K), 101.8624498 secs] Note how the minor collection takes high GC times (highlighted in bold). It takes as high as 204 seconds. We are using the default GC algo both for the old generation and the young generation(which happens to be stop the world collector for young generation and mark - compact collector for the old generation). Our heap size when the tomcat starts is bounded by 256 MB on the lower side to 778 MB on the higher side. I am unable to understand what would cause tomcat to do GC for such a long time esp in the young generation. what is even more wierd is that the time between consecutive GC for young generation is almost equal to time for which the GC happened . what would cause the young generation to fill so quickly. Anyone has any ideas what is going on ? -Akash
