#39 After glassbox Deploy CommonsLoggingOutput OutOfMemoryError
I just tried out Glassbox 2.0.
#Glassbox Build Information
#Sat Jun 21 01:56:46 CDT 2008
build.time=01\:56\:46
build.number=2.0.442-BETA
build.date=Saturday Jun 21, 2008
build.timestamp=2008-06-21T01\:56\:46
Firefox 3.0.4
When using glassbox to monitor our application on Tomcat 6.0.18, I encountered the OutOfMemory error below. It had only been running the application for a a couple of minutes. I had logged in to our application and clicked a few of our menu options. I had also accessed the glassbox web application in a separate browser and was trying to sort by the Execution column. I had encountered one slow method in the ACEGI. Then the application froze with the OutOfMemory error.
This application does not run out of memory unless I monitor it with glassbox.
90645 [http-8080-1] WARN uk.ltd.getahead.dwr.util.CommonsLoggingOutput - Method execution failed:
java.lang.OutOfMemoryError: Java heap space
at java.util.Arrays.copyOf(Arrays.java:2882) [na:1.6.0_07]
at java.lang.AbstractStringBuilder.expandCapacity(AbstractStringBuilder.java:100) [na:1.6.0_07]
at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:390) [na:1.6.0_07]
at java.lang.StringBuffer.append(StringBuffer.java:224) [na:1.6.0_07]
at uk.ltd.getahead.dwr.convert.CollectionConverter.convertOutbound(CollectionConverter.java:198) [dwr.jar:na]
at uk.ltd.getahead.dwr.impl.DefaultConverterManager.convertOutbound(DefaultConverterManager.java:203) [dwr.jar:na]
at uk.ltd.getahead.dwr.impl.ExecuteQuery.execute(ExecuteQuery.java:241) [dwr.jar:na]
at uk.ltd.getahead.dwr.impl.DefaultExecProcessor.handle(DefaultExecProcessor.java:48) [dwr.jar:na]
at uk.ltd.getahead.dwr.impl.DefaultProcessor.handle(DefaultProcessor.java:81) [dwr.jar:na]
at uk.ltd.getahead.dwr.AbstractDWRServlet.doPost(AbstractDWRServlet.java:162) [dwr.jar:na]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) [servlet-api.jar:na]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) [servlet-api.jar:na]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) [catalina.jar:na]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:na]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) [catalina.jar:na]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) [catalina.jar:na]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) [catalina.jar:na]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [catalina.jar:na]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [catalina.jar:na]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) [catalina.jar:na]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) [tomcat-coyote.jar:na]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) [tomcat-coyote.jar:na]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) [tomcat-coyote.jar:na]
at java.lang.Thread.run(Thread.java:619) [na:1.6.0_07]
91237 [http-8080-5] INFO uk.ltd.getahead.dwr.util.CommonsLoggingOutput - Exec[0]: ColumnHelper.setColumnSorter()
90940 [http-8080-3] INFO uk.ltd.getahead.dwr.util.CommonsLoggingOutput - Exec[0]: OperationHelper.getOperations()
93275 [http-8080-1] WARN uk.ltd.getahead.dwr.util.CommonsLoggingOutput - Erroring: id[5909_1229247442418] message[uk.ltd.getahead.dwr.OutboundVariable@67bd23]
98675 [Thread-11] INFO com.ncr.enterprisereporting.schedulereport.ReportScheduleManagerThread - enters the while
xception in thread "pool-1-thread-3" java.lang.OutOfMemoryError: Java heap space
09491 [Timer-5] WARN glassbox.util.org.sl4j.CommonsLoggingAdapter - Unable to reconfigure using properties file c:\apache-tomcat-6.0.18\lib\glassbox\runtime.properties, using defaults
ava.lang.OutOfMemoryError: Java heap space
10100 [Thread-11] INFO com.ncr.enterprisereporting.schedulereport.ReportScheduleManagerThread - Stale and Fresh ReportSchedules are equal
17702 [http-8080-5] ERROR glassbox.util.org.sl4j.CommonsLoggingAdapter - failure Java heap space:
ava.lang.OutOfMemoryError: Java heap space
ec 14, 2008 4:37:55 AM org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler process
EVERE: Error reading request, ignored
ava.lang.OutOfMemoryError: Java heap space
xception in thread "http-8080-7" java.lang.NullPointerException
ec 14, 2008 4:37:55 AM org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor processChildren
EVERE: Exception invoking periodic operation:
ava.lang.OutOfMemoryError: Java heap space
20543 [http-8080-3] WARN uk.ltd.getahead.dwr.util.CommonsLoggingOutput - Method execution failed:
ava.lang.OutOfMemoryError: Java heap space
at java.util.concurrent.ConcurrentLinkedQueue.offer(ConcurrentLinkedQueue.java:190)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler$1.offer(Http11Protocol.java:532)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler$1.offer(Http11Protocol.java:549)
ec 14, 2008 4:37:55 AM org.aspectj.weaver.tools.Jdk14Trace error
EVERE: org/apache/jsp/WEB_002dINF/jsp/userprofile_jsp
ava.lang.OutOfMemoryError: Java heap space
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:613)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
at java.lang.Thread.run(Thread.java:619)
ec 14, 2008 4:37:56 AM org.aspectj.weaver.tools.Jdk14Trace info
NFO: Dumping to C:\apache-tomcat-6.0.18\bin\.\ajcore.20081214.043756.164.txt
20261 [http-8080-1] ERROR glassbox.util.org.sl4j.CommonsLoggingAdapter - failure Java heap space:
ava.lang.OutOfMemoryError: Java heap space
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:161) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
at glassbox.track.api.TreeTimeStatsImpl$TreeStats.recordSample(TreeTimeStatsImpl.java:169) [agent.jar:na]
20888 [http-8080-9] INFO uk.ltd.getahead.dwr.util.CommonsLoggingOutput - Exec[0]: OperationHelper.getOperations()
20888 [http-8080-8] INFO uk.ltd.getahead.dwr.util.CommonsLoggingOutput - Exec[0]: OperationHelper.getOperations()
20570 [http-8080-3] WARN uk.ltd.getahead.dwr.util.CommonsLoggingOutput - Erroring: id[6999_1229247445830] message[uk.ltd.getahead.dwr.OutboundVariable@157fc7a]
22265 [Thread-11] INFO com.ncr.enterprisereporting.schedulereport.ReportScheduleManagerThread - enters the while
22888 [Thread-11] INFO com.ncr.enterprisereporting.schedulereport.ReportScheduleManagerThread - Stale and Fresh ReportSchedules are equal
23784 [http-8080-8] INFO uk.ltd.getahead.dwr.util.CommonsLoggingOutput - Exec[0]: OperationHelper.getOperations()
The problem may be that the default startup_with_glassbox.bat uses the default maximum heap of 64MB. I think we typically run the application with 256MB.
Below is the data from copied from the jconsole VM Summary tab of the environment running our application with glassbox monitoring.
VM Summary
Sunday, December 14, 2008 5:19:42 AM EST
Connection name:
pid: 7272 org.apache.catalina.startup.Bootstrap start
Virtual Machine:
Java HotSpot(TM) Client VM version 10.0-b23
Vendor:
Sun Microsystems Inc.
Name:
7272@moses
Uptime:
2 minutes
Process CPU time:
40.076 seconds
JIT compiler:
HotSpot Client Compiler
Total compile time:
3.088 seconds
Live threads:
85
Peak:
87
Daemon threads:
67
Total threads started:
112
Current classes loaded:
11,528
Total classes loaded:
11,591
Total classes unloaded:
63
Current heap size:
59,878 kbytes
Maximum heap size:
65,088 kbytes
Committed memory:
65,088 kbytes
Pending finalization:
0 objects
Garbage collector:
Name = 'Copy', Collections = 710, Total time spent = 1.601 seconds
Garbage collector:
Name = 'MarkSweepCompact', Collections = 60, Total time spent = 13.511 seconds
Operating System:
Windows Vista 6.0
Architecture:
x86
Number of processors:
4
Committed virtual memory:
175,208 kbytes
Total physical memory:
2,094,924 kbytes
Free physical memory:
855,392 kbytes
Total swap space:
4,194,303 kbytes
Free swap space:
1,780,848 kbytes
VM arguments:
-javaagent:c:\apache-tomcat-6.0.18\lib\aspectjweaver.jar -Daj.weaving.verbose=false -Dglassbox.install.dir=c:\apache-tomcat-6.0.18\lib\glassbox -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djava.util.logging.config.file=c:\apache-tomcat-6.0.18\conf\logging.properties -Djava.endorsed.dirs=c:\apache-tomcat-6.0.18\endorsed -Dcatalina.base=c:\apache-tomcat-6.0.18 -Dcatalina.home=c:\apache-tomcat-6.0.18 -Djava.io.tmpdir=c:\apache-tomcat-6.0.18\temp
Class path:
c:\Java\jdk1.6.0_07\lib\tools.jar;c:\apache-tomcat-6.0.18\bin\bootstrap.jar;c:\apache-tomcat-6.0.18\lib\aspectjweaver.jar
Library path:
c:\Java\jdk1.6.0_07\bin;.;C:\Windows\Sun\Java\bin;C:\Windows\system32;C:\Windows;c:\ruby\bin;d:\tools\apache-ant-1.7.1\bin;c:\Java\jdk1.6.0_07\bin;C:\Python25\Scripts;C:\Python25\;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Program Files\TortoiseSVN\bin;C:\Program Files\QuickTime\QTSystem\;C:\Program Files\IDM Computer Solutions\UltraEdit-32;C:\Program Files\IDM Computer Solutions\UltraEdit\
Boot class path:
c:\Java\jdk1.6.0_07\jre\lib\resources.jar;c:\Java\jdk1.6.0_07\jre\lib\rt.jar;c:\Java\jdk1.6.0_07\jre\lib\sunrsasign.jar;c:\Java\jdk1.6.0_07\jre\lib\jsse.jar;c:\Java\jdk1.6.0_07\jre\lib\jce.jar;c:\Java\jdk1.6.0_07\jre\lib\charsets.jar;c:\Java\jdk1.6.0_07\jre\classes
After updating the JAVA_OPTS line in startup_with_glassbox.bat with "-Xmx256m"
set JAVA_OPTS=%JAVA_OPTS% "-Xmx256m" "-javaagent:%GLASSBOX_LIB_DIR%\aspectjweaver.jar" -Daj.weaving.verbose=false "-Dglassbox.install.dir=%GLASSBOX_HOME%"
things seems to be working better.
Maybe the glassbox install should be changed to set the maximum heap to 256m by default.