After the long email I just wrote stating that the failure had never
happened early in the day, the system just failed. When it failed, 226MB of
the 512MB heap and 60MB of the 384MB permGen space were being used (reported
by VisualJVM... I think this should be what was being used at the point of
failure.) top reports 4.1GB memory (no swap) being used (out of 8GB memory
available) while the system monitor report .76GN memory being used (both of
these are after the failure so probably aren't the same as immediately
before the failure.)
These were the last entries in catalina.out before the failure:
22470.989: [GC 22470.989: [ParNew: 38238K->4224K(38336K), 0.0516680 secs]
238609K->206157K(520064K) icms_dc=0 , 0.0517810 secs] [Times: user=0.08
sys=0.00, real=0.05 secs]
22472.212: [GC 22472.212: [ParNew: 38336K->4224K(38336K), 0.0311230 secs]
240269K->208988K(520064K) icms_dc=0 , 0.0312400 secs] [Times: user=0.05
sys=0.00, real=0.04 secs]
22473.335: [GC 22473.335: [ParNew: 38336K->4224K(38336K), 0.0231810 secs]
243100K->213822K(520064K) icms_dc=3 , 0.0232880 secs] [Times: user=0.04
sys=0.01, real=0.02 secs]
It was a clean kill as I could restart Tomcat with no port problem (from
catalina.out):
Feb 12, 2010 7:43:27 AM org.apache.catalina.core.AprLifecycleListener init
INFO: The APR based Apache Tomcat Native library which allows optimal
performance in production environments was not found on the
java.library.path:
/usr/local/jdk1.6.0_18/jre/lib/amd64/server:/usr/local/jdk1.6.0_18/jre/lib/amd64:/usr/local/jdk1.6.0_18/jre/../lib/amd64:/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
Feb 12, 2010 7:43:27 AM org.apache.coyote.http11.Http11Protocol init
INFO: Initializing Coyote HTTP/1.1 on http-8080
2.191: [GC 2.191: [ParNew: 34112K->3327K(38336K), 0.0370330 secs]
34112K->3327K(520064K), 0.0371230 secs] [Times: user=0.04 sys=0.00,
real=0.04 secs]
Feb 12, 2010 7:43:28 AM org.apache.coyote.http11.Http11Protocol init
INFO: Initializing Coyote HTTP/1.1 on http-8443
Feb 12, 2010 7:43:28 AM org.apache.coyote.http11.Http11Protocol init
INFO: Initializing Coyote HTTP/1.1 on http-443
Feb 12, 2010 7:43:28 AM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 2228 ms
Feb 12, 2010 7:43:28 AM org.apache.catalina.core.StandardService start
INFO: Starting service Catalina
Feb 12, 2010 7:43:28 AM org.apache.catalina.core.StandardEngine start
INFO: Starting Servlet Engine: Apache Tomcat/6.0.24
Feb 12, 2010 7:43:28 AM org.apache.catalina.startup.HostConfig
deployDescriptor
INFO: Deploying configuration descriptor paragon.xml
3.008: [GC [1 CMS-initial-mark: 0K(481728K)] 18842K(520064K), 0.0207640
secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
3.029: [CMS-concurrent-mark-start]
3.075: [CMS-concurrent-mark: 0.046/0.046 secs] [Times: user=0.03 sys=0.01,
real=0.05 secs]
3.075: [CMS-concurrent-preclean-start]
3.085: [CMS-concurrent-preclean: 0.008/0.010 secs] [Times: user=0.01
sys=0.00, real=0.01 secs]
3.085: [CMS-concurrent-abortable-preclean-start]
RequestFilter initialized
3.827: [GC 3.828: [ParNew: 37439K->3065K(38336K), 0.0433370 secs]
37439K->6381K(520064K), 0.0434070 secs] [Times: user=0.08 sys=0.01,
real=0.05 secs]
Feb 12, 2010 7:43:30 AM org.apache.catalina.startup.HostConfig
deployDescriptor
INFO: Deploying configuration descriptor livonia.xml
RequestFilter initialized
Feb 12, 2010 7:43:30 AM org.apache.catalina.startup.HostConfig
deployDescriptor
INFO: Deploying configuration descriptor host-manager.xml
Feb 12, 2010 7:43:30 AM org.apache.catalina.startup.HostConfig
deployDescriptor
INFO: Deploying configuration descriptor test.xml
4.679: [GC 4.679: [ParNew: 37177K->4223K(38336K), 0.0228850 secs]
40493K->7556K(520064K), 0.0229540 secs] [Times: user=0.05 sys=0.01,
real=0.02 secs]
RequestFilter initialized
Feb 12, 2010 7:43:31 AM org.apache.catalina.startup.HostConfig
deployDescriptor
INFO: Deploying configuration descriptor manager.xml
5.161: [CMS-concurrent-abortable-preclean: 0.046/2.076 secs] [Times:
user=3.41 sys=0.11, real=2.08 secs]
5.161: [GC[YG occupancy: 19763 K (38336 K)]5.161: [Rescan (parallel) ,
0.0181680 secs]5.180: [weak refs processing, 0.0000080 secs] [1 CMS-remark:
3332K(481728K)] 23096K(520064K), 0.0183060 secs] [Times: user=0.02 sys=0.00,
real=0.02 secs]
5.180: [CMS-concurrent-sweep-start]
5.180: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00,
real=0.00 secs]
5.180: [CMS-concurrent-reset-start]
5.186: [CMS-concurrent-reset: 0.006/0.006 secs] [Times: user=0.01 sys=0.00,
real=0.00 secs]
Feb 12, 2010 7:43:31 AM org.apache.catalina.startup.HostConfig
deployDescriptor
INFO: Deploying configuration descriptor default.xml
RequestFilter initialized
5.569: [GC 5.569: [ParNew: 38335K->4044K(38336K), 0.0276190 secs]
41668K->9019K(520064K) icms_dc=5 , 0.0277040 secs] [Times: user=0.03
sys=0.00, real=0.03 secs]
Feb 12, 2010 7:43:31 AM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory ROOT
Feb 12, 2010 7:43:31 AM org.apache.coyote.http11.Http11Protocol start
INFO: Starting Coyote HTTP/1.1 on http-8080
Feb 12, 2010 7:43:31 AM org.apache.coyote.http11.Http11Protocol start
INFO: Starting Coyote HTTP/1.1 on http-8443
Feb 12, 2010 7:43:31 AM org.apache.coyote.http11.Http11Protocol start
INFO: Starting Coyote HTTP/1.1 on http-443
Feb 12, 2010 7:43:31 AM org.apache.jk.common.ChannelSocket init
INFO: JK: ajp13 listening on /0.0.0.0:8009
Feb 12, 2010 7:43:32 AM org.apache.jk.server.JkMain start
INFO: Jk running ID=0 time=0/131 config=null
Feb 12, 2010 7:43:32 AM org.apache.catalina.startup.Catalina start
INFO: Server startup in 3617 ms
76.034: [GC [1 CMS-initial-mark: 4975K(481728K)] 25384K(520064K), 0.0183320
secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
76.057: [CMS-concurrent-mark-start]
76.117: [CMS-concurrent-mark: 0.053/0.059 secs] [Times: user=0.12 sys=0.00,
real=0.06 secs]
76.117: [CMS-concurrent-preclean-start]
76.124: [CMS-concurrent-preclean: 0.007/0.007 secs] [Times: user=0.02
sys=0.00, real=0.01 secs]
76.124: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 81.142: [CMS-concurrent-abortable-preclean:
0.266/5.018 secs] [Times: user=0.68 sys=0.01, real=5.02 secs]
81.142: [GC[YG occupancy: 21090 K (38336 K)]81.142: [Rescan (parallel) ,
0.0154810 secs]81.158: [weak refs processing, 0.0001730 secs] [1 CMS-remark:
4975K(481728K)] 26066K(520064K), 0.0157760 secs] [Times: user=0.02 sys=0.00,
real=0.02 secs]
81.158: [CMS-concurrent-sweep-start]
81.164: [CMS-concurrent-sweep: 0.005/0.005 secs] [Times: user=0.01 sys=0.00,
real=0.00 secs]
81.164: [CMS-concurrent-reset-start]
81.169: [CMS-concurrent-reset: 0.006/0.006 secs] [Times: user=0.00 sys=0.00,
real=0.01 secs]
Does anyone see anything in the above that looks odd (or maybe like a clue?)
Thanks,
Carl
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
