testdriven / psi-probe

Advanced manager and monitor for Apache Tomcat, forked from Lambda Probe
8 stars 1 forks source link

Memory page error when using JRockit or IBM JDK #127

Closed padcom closed 10 years ago

padcom commented 10 years ago

From jenar...@gmail.com on June 15, 2010 10:59:25

What steps will reproduce the problem? 1. Run tomcat+probe on the JRockit Real Time JVM

  1. Go to the Memory Utilisation screen
  2. Error is shown What is the expected result? The page shows information about the memory utilisation in the JVM. What happens instead? An error is shown, see stacktrace below. What version of Probe are you using? On what server, browser, and OS? Probe 2.0.4 on tomcat 5.5.28, Firefox 3.5, Ubuntu 10.04 - 64 bits Please provide any additional information below. The stack trace is: nulljava.lang.ArrayIndexOutOfBoundsException at java.lang.String.getChars(String.java:726) at org.apache.jasper.runtime.BodyContentImpl.write(BodyContentImpl.java:143) at org.apache.jasper.runtime.BodyContentImpl.write(BodyContentImpl.java:156) at org.apache.jasper.runtime.BodyContentImpl.print(BodyContentImpl.java:316) at com.googlecode.psiprobe.tags.VisualScoreTag.doAfterBody(VisualScoreTag.java:63) at jsp.WEB_002dINF.jsp.ajax.memory_005fpools_jsp._jspx_meth_probe_score_0(jsp.WEB_002dINF.jsp.ajax.memory_005fpools_jsp:443) at jsp.WEB_002dINF.jsp.ajax.memory_005fpools_jsp._jspx_meth_display_column_2(jsp.WEB_002dINF.jsp.ajax.memory_005fpools_jsp:396) at jsp.WEB_002dINF.jsp.ajax.memory_005fpools_jsp._jspService(jsp.WEB_002dINF.jsp.ajax.memory_005fpools_jsp:126) at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:99) at javax.servlet.http.HttpServlet.service(HttpServlet.java:730) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188) at com.opensymphony.module.sitemesh.filter.PageFilter.doFilter(PageFilter.java:39) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188) at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:679) at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:461) at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:399) at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:301) at org.springframework.web.servlet.view.InternalResourceView.renderMergedOutputModel(InternalResourceView.java:112) at org.springframework.web.servlet.view.AbstractView.render(AbstractView.java:250) at org.springframework.web.servlet.DispatcherServlet.render(DispatcherServlet.java:1106) at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:841) at com.googlecode.psiprobe.ProbeServlet.doDispatch(ProbeServlet.java:49) at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:755) at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:396) at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:361) at javax.servlet.http.HttpServlet.service(HttpServlet.java:647) at javax.servlet.http.HttpServlet.service(HttpServlet.java:730) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188) at com.opensymphony.module.sitemesh.filter.PageFilter.doFilter(PageFilter.java:39) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:172) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:527) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:130) at com.googlecode.psiprobe.Tomcat55AgentValve.invoke(Tomcat55AgentValve.java:30) at org.jstripe.tomcat.probe.Tomcat55AgentValve.invoke(Tomcat55AgentValve.java:20) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:110) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:174) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:873) at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:665) at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:528) at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689) at java.lang.Thread.run(Thread.java:595)

Original issue: http://code.google.com/p/psi-probe/issues/detail?id=127

padcom commented 10 years ago

From MALfunct...@gmail.com on September 22, 2010 14:39:29

Sorry, but we don't have the resources to troubleshoot or support JRockit.

Summary: Memory page error when using JRockit
Status: WontFix

padcom commented 10 years ago

From MALfunct...@gmail.com on September 22, 2010 14:40:49

Does the Sun (Oracle) JVM not work for you? If not, perhaps someone from the community can help.

padcom commented 10 years ago

From jenar...@gmail.com on September 22, 2010 14:44:53

Yes, it does work but we use JRockit for development as it performs better.

padcom commented 10 years ago

From MALfunct...@gmail.com on September 23, 2010 15:26:41

The hand-off from PSI Probe's code to third-party code occurs on line 63 of the VisualScoreTag class, which is responsible for generating the horizontal progress bar graphs. All this line does is pass a string to the JspWriter.print() method. Nothing fancy.

I've traced through the Tomcat 5.5.28 code, and nothing seems out of place there either. Since it works fine on the Sun JDK, I suspect it's a bug in JRockit's implementation of String.getChars(), but I can't confirm that.

I have two questions:

  1. The datasource usage bar graphs on the main page also use the VisualScoreTag. Do they work correctly?
  2. What version of JRockit are you using?
padcom commented 10 years ago

From jenar...@gmail.com on September 24, 2010 04:15:29

Hi, thanks for looking into this, firstly answering your two questions:

  1. Yes they seem to work fine.
  2. The jvm is: Java(TM) 2 Runtime Environment, Standard Edition 1.5.0_22-b03 Oracle JRockit(R)) java.vm.version = R28 .0.0-679-130297-1.5.0_22-20100312-2121-linux-x86_64 uname -a = Linux 2.6.32-24-generic #43-Ubuntu SMP Thu Sep 16 14:58:24 UTC 2010 x86_64 GNU/Linux Also looking at probe.log I have found another exception thrown right before the exception above, the stacktrace is:

24 Sep 2010 12:03:15 [http-8080-Processor20] ERROR org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/probe].[probe] - Servlet.service() for servlet probe threw exception java.lang.OutOfMemoryError: allocLargeObjectOrArray: [C, larger than Java heap at org.apache.jasper.runtime.BodyContentImpl.reAllocBuff(BodyContentImpl.java:595) at org.apache.jasper.runtime.BodyContentImpl.write(BodyContentImpl.java:141) at org.apache.jasper.runtime.BodyContentImpl.write(BodyContentImpl.java:156) at org.apache.jasper.runtime.BodyContentImpl.print(BodyContentImpl.java:316) at com.googlecode.psiprobe.tags.VisualScoreTag.doAfterBody(VisualScoreTag.java:63) at jsp.WEB_002dINF.jsp.ajax.memory_005fpools_jsp._jspx_meth_probe_score_0(jsp.WEB_002dINF.jsp.ajax.memory_005fpools_jsp:443) at jsp.WEB_002dINF.jsp.ajax.memory_005fpools_jsp._jspx_meth_display_column_2(jsp.WEB_002dINF.jsp.ajax.memory_005fpools_jsp:396) at jsp.WEB_002dINF.jsp.ajax.memory_005fpools_jsp._jspService(jsp.WEB_002dINF.jsp.ajax.memory_005fpools_jsp:126) at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:98) at javax.servlet.http.HttpServlet.service(HttpServlet.java:729) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188) at com.opensymphony.module.sitemesh.filter.PageFilter.doFilter(PageFilter.java:39) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188) at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:679) at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:461) at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:399) at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:301) at org.springframework.web.servlet.view.InternalResourceView.renderMergedOutputModel(InternalResourceView.java:112) at org.springframework.web.servlet.view.AbstractView.render(AbstractView.java:249) at org.springframework.web.servlet.DispatcherServlet.render(DispatcherServlet.java:1105) at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:841) at com.googlecode.psiprobe.ProbeServlet.doDispatch(ProbeServlet.java:48) at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:755) at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:396) at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:360) at javax.servlet.http.HttpServlet.service(HttpServlet.java:647) at javax.servlet.http.HttpServlet.service(HttpServlet.java:729) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188) at com.opensymphony.module.sitemesh.filter.PageFilter.doFilter(PageFilter.java:39) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:172) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:525) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) at com.googlecode.psiprobe.Tomcat55AgentValve.invoke(Tomcat55AgentValve.java:30) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:174) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:873) at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:665) at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:528) at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689) at java.lang.Thread.run(Thread.java:595)

I am running tomcat with 1024m of RAM and while testing this no other application is being used.

Thanks a lot for the effort you are putting into this, it may be a problem with JRockit perhaps, in which case I will need to live with it.

Edu

padcom commented 10 years ago

From MALfunct...@gmail.com on September 24, 2010 06:54:11

The reAllocBuff() call happens right before the String.getChars() call. That line in the reAllocBuff() method (BodyContentImpl.java:595) is just creating a new character buffer. It seems like JRockit might not be garbage-collecting the old character buffer as aggressively as it needs to.

Nothing in JRockit's release notes suggest that anything related to this has been fixed in 28.0.1 or 28.0.2, but you might want to consider upgrading just in case. Sorry, there's not much else I can think to do, but please let me know if you find something that works.

padcom commented 10 years ago

From MALfunct...@gmail.com on January 14, 2011 08:39:25

Status: ExternalDependency
Labels: JVM-JRockit

padcom commented 10 years ago

From MALfunct...@gmail.com on January 14, 2011 10:48:03

Issue 118 has been merged into this issue.

padcom commented 10 years ago

From MALfunct...@gmail.com on January 14, 2011 10:55:01

We don't officially support JRockit, but at least 3 users have encountered this exception in JRockit when a page uses probe:score custom tag. This warrants closer examination. Issue 88 may significantly change how that tag works.

Status: Accepted
Labels: FoundIn-1.7b

padcom commented 10 years ago

From MALfunct...@gmail.com on April 25, 2011 13:41:05

Does this still occur in PSI Probe 2.2.1?

Status: NeedInfo

padcom commented 10 years ago

From MALfunct...@gmail.com on April 27, 2011 10:52:21

Labels: Stacktrace

padcom commented 10 years ago

From MALfunct...@gmail.com on May 03, 2011 16:03:41

Issue 216 has been merged into this issue.

padcom commented 10 years ago

From MALfunct...@gmail.com on May 03, 2011 16:05:55

The reporter of issue 216 encountered this problem on an IBM JDK.

Summary: Memory page error when using JRockit or IBM JDK
Labels: JVM-IBM

padcom commented 10 years ago

From MALfunct...@gmail.com on May 03, 2011 16:28:23

I found a related Tomcat bug (1), but it should be fixed in the versions of Tomcat where people are reporting this problem (5.5.28 and 6.0.32).

That bug and another site (2) mention some properties which may be related. Can someone try adding one or both of the following to your JVM command line options and see if it makes any difference? -Dorg.apache.jasper.runtime.BodyContentImpl.LIMIT_BUFFER=false -Dorg.apache.jasper.runtime.JspFactoryImpl.USE_POOL

(1) https://issues.apache.org/bugzilla/show_bug.cgi?id=46354 (2) http://www.datadisk.co.uk/html_docs/java_app/tomcat6/tomcat6_tuning.htm

padcom commented 10 years ago

From MALfunct...@gmail.com on May 03, 2011 16:31:41

Please try all permutations of true and false on those properties and let me know the results. Thanks.

Labels: HelpWanted

padcom commented 10 years ago

From coolman....@gmail.com on May 04, 2011 08:55:44

These tests is performed on AIX JVM. I stripped up to the variable for faster typing but they are correctly qualified in the start script.

LIMIT_BUFFER=FALSE and LIMIT_BUFFER=TRUE (used singly) No change.

USE_POOL No Change.

LIMIT_BUFFER=FALSE & USE_POOL No Change

LIMIT_BUFFER=TRUE & USE_POOL No Change

padcom commented 10 years ago

From coolman....@gmail.com on May 04, 2011 09:16:45

One more bit of information to help troubleshoot this issue.

Here is the start-up for this server.

-Xmn750MB -Xmx1024M -Djava.awt.headless=true -Dcom.sun.management.jmxremote=true -Dcom.sun.management.jmxremote.port=XXXXX -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Dorg.apache.jasper.runtime.JspFactoryImpl.USE_POOL -Dorg.apache.jasper.runtime.BodyContentImpl.LIMIT_BUFFER=false

So you will notice that we never reach 1024 but we bypass Eden (-Xmn) by quite a bit. Raising and lowering this value ultimately raises or lowers the amount and time it takes to error. But it will always error.

Attachment: jConsole.bmp

padcom commented 10 years ago

From MALfunct...@gmail.com on May 04, 2011 11:22:58

I guess there isn't much difference between USE_POOL and USE_POOL=true, but it may be worth trying that.

Does the IBM JDK support -XX:-HeapDumpOnOutOfMemoryError? I don't think attaching a ~600MB file here is feasible, but if you're comfortable looking through the resulting heap dump, there may be some clues.

padcom commented 10 years ago

From coolman....@gmail.com on May 04, 2011 13:07:42

Yes and I have been generating heap dumps all day! Here is an analysis of the most recent. I will try the USE_POOL=true.

Interesting though, the JVM stays intact and my other webapps function fine.

Attachment: AnalysisReport.html

padcom commented 10 years ago

From MALfunct...@gmail.com on May 04, 2011 13:35:44

516 MB of char[]!?

Could you generate similar analysis reports for the various combinations of USE_POOL and LIMIT_BUFFER?

What's interesting to me is that it's only on this ajax memory pools page. Other places where the VisualScoreTag is used (e.g. datasources) don't cause this problem.

padcom commented 10 years ago

From coolman....@gmail.com on May 04, 2011 14:11:13

Not sure if this helps but the stats.xml file which is created in /work/probe for some reason is not able to be written to or read from. Not sure probe needs this file to offload some memory costs to the drive.

I will create the files as soon as possible.

padcom commented 10 years ago

From MALfunct...@gmail.com on May 04, 2011 14:22:24

Sounds like a permissions issue in the file system. It shouldn't affect this, though; that file just serializes the collected stats so they're preserved across server restarts.

Thanks for all your help!

padcom commented 10 years ago

From coolman....@gmail.com on May 05, 2011 08:50:47

Changing the format of the logs here. This one gives a chain and what they are attached to. To use it, just download it, unzip it and load index.html.

This log is for: -Xmx512M -Djava.awt.headless=true -Dcom.sun.management.jmxremote=true -Dcom.sun.management.jmxremote.port=9024 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.s un.management.jmxremote.ssl=false -Dorg.apache.jasper.runtime.JspFactoryImpl.USE_POOL=true -Dorg.apache.jasper.runtime.BodyContentImpl.LIMIT_BUFFER=true

Attachment: hd_1_Leak_Hunter.zip

padcom commented 10 years ago

From coolman....@gmail.com on May 05, 2011 08:59:54

This log is for: -Xmx512M -Djava.awt.headless=true -Dcom.sun.management.jmxremote=true -Dcom.sun.management.jmxremote.port= -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false

Attachment: hd_2_Leak_Hunter.zip

padcom commented 10 years ago

From coolman....@gmail.com on May 05, 2011 09:06:37

All other combinations of this issue result in the same output.

The problem falls squarely on probe TagSupport class and nothing to do with the actual .jsp. I cannot check out the code for some reason, maybe post the probe tag .java file?

padcom commented 10 years ago

From coolman....@gmail.com on May 05, 2011 09:44:49

Here is some more information.

When the first page is declared (memory.jsp) the new Ajax.PeriodicalUpdater line shows:

new Ajax.PeriodicalUpdater('memoryPools', '/probe/memory.ajax?null', {frequency: 5});

Not sure if that ?null is a problem.

padcom commented 10 years ago

From MALfunct...@gmail.com on May 05, 2011 14:14:06

Thanks for supplying this information.

I'm not sure we can assign blame just yet. The probe:score JSP tag (com.googlecode.psiprobe.tags.VisualScoreTag) is used in other pages without any problems. I'd rather not use up the attachment quota posting files that are in the repository. You can view the file here: https://code.google.com/p/psi-probe/source/browse/trunk/core/src/main/java/com/googlecode/psiprobe/tags/VisualScoreTag.java The "null" you're seeing is just the query string. It's only there so the row ordering of the memory pools table is preserved between refreshes.

Can you use jconsole to see how many memory pools your JVM returns? The oname is "java.lang:type=MemoryPool,*" As a point of comparison, mine has 5.

padcom commented 10 years ago

From coolman....@gmail.com on May 05, 2011 14:40:05

Looks like it is the same for IBM JVM

Attachment: MemoryPool.bmp

padcom commented 10 years ago

From MALfunct...@gmail.com on May 05, 2011 15:20:37

I have one idea I'd like to try. Can I email you a snapshot build to test when it's ready?

Status: Started
Owner: MALfunct...@gmail.com

padcom commented 10 years ago

From coolman....@gmail.com on May 05, 2011 16:58:03

Yes.

Please include installation instructions if it will be different than currently. In addition, any instructions on how clean up from the older version.

Thanks,

padcom commented 10 years ago

From MALfunct...@gmail.com on May 06, 2011 10:15:00

This issue was updated by revision r529 .

Buffering content before printing it to the JspWriter, which avoids multiple calls to JspWriter.print().

padcom commented 10 years ago

From MALfunct...@gmail.com on May 06, 2011 10:31:23

@coolman, I've emailed a snapshot build to you.

padcom commented 10 years ago

From coolman....@gmail.com on May 06, 2011 13:48:24

With the snapshot I received:

There was an error

Application encountered an unexpected error. We will greatly appreciate it if you share the information below with us. Sharing this information through our issue tracker or our discussion board will help us find and correct this problem as soon as possible! nulljava.lang.OutOfMemoryError at java.lang.StringBuffer.ensureCapacityImpl(StringBuffer.java:335) at java.lang.StringBuffer.append(StringBuffer.java:201) at com.googlecode.psiprobe.tags.VisualScoreTag.doAfterBody(VisualScoreTag.java:63) at jsp.WEB_002dINF.jsp.ajax.memory_005fpools_jsp._jspx_meth_probe_score_0(jsp.WEB_002dINF.jsp.ajax.memory_005fpools_jsp:443) at jsp.WEB_002dINF.jsp.ajax.memory_005fpools_jsp._jspx_meth_display_column_2(jsp.WEB_002dINF.jsp.ajax.memory_005fpools_jsp:396) at jsp.WEB_002dINF.jsp.ajax.memory_005fpools_jsp._jspService(jsp.WEB_002dINF.jsp.ajax.memory_005fpools_jsp:126) at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at com.opensymphony.module.sitemesh.filter.PageFilter.doFilter(PageFilter.java:39) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:646) at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:436) at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:374) at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:302) at org.springframework.web.servlet.view.InternalResourceView.renderMergedOutputModel(InternalResourceView.java:236) at org.springframework.web.servlet.view.AbstractView.render(AbstractView.java:257) at org.springframework.web.servlet.DispatcherServlet.render(DispatcherServlet.java:1183) at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:902) at com.googlecode.psiprobe.ProbeServlet.doDispatch(ProbeServlet.java:50) at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:807) at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:571) at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:511) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at com.opensymphony.module.sitemesh.filter.PageFilter.doFilter(PageFilter.java:39) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:563) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) at com.googlecode.psiprobe.Tomcat60AgentValve.invoke(Tomcat60AgentValve.java:30) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298) at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:190) at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:291) at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:776) at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:705) at org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:898) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690) at java.lang.Thread.run(Thread.java:736)

Attachment: hd_3_Leak_Hunter.zip

padcom commented 10 years ago

From coolman....@gmail.com on May 06, 2011 14:01:00

I guess I don't understand this code. This is line 63 of the VisualScoreTag file:

// Full red blocks String fullRedBody = MessageFormat.format(body, new Object[]{partialBlocks + "+0"}); for (int i = 0; i < fullRedBlockCount; i++) { buf.append(fullRedBody); }

So, this for loop writes fullRedBody X # of times to the buf. If fullRedBody is huge wouldn't that actually fill up the heap? Seems like these segments are missing something or are they supposed to write to the buf the same thing over and over?

And there is still more appends to go!

padcom commented 10 years ago

From MALfunct...@gmail.com on May 06, 2011 14:48:27

The usage bar is comprised of multiple images. There are 2 images on each end for the beveled tips and 10 images in the middle, each of which represents 10% of the total value. If a memory pool is 50% full, its usage bar will have 5 full red blocks and 5 empty blocks. There are also partially-filled blocks, since each pixel represents 2%. Those are the loops further down that you see.

Each iteration of the loop above appends a single formatted tag representing a single block, one of 10 possible ("fullRedBlockCount" should never exceed 10, which would be 100%). The entire string that is appended would look like this:

+

We're narrowing it down. It's possible that fullRedBlockCount is way too high, and it's possible the body text is way too big. I'll send another snapshot with some debugging output.

padcom commented 10 years ago

From MALfunct...@gmail.com on May 06, 2011 15:31:59

@coolman, I've sent another snapshot build with debugging output. It prints the usage value, the numbers of all blocks, and the unformatted body text that is being appended. Hopefully the logging output will shed some light on what's going on.

padcom commented 10 years ago

From coolman....@gmail.com on May 09, 2011 08:05:11

I tried to get to this over the weekend but I ran out of time...

Here is the log.

Attachment: probe.log

padcom commented 10 years ago

From coolman....@gmail.com on May 09, 2011 08:09:12

Looking at the log an your previous post entry stating that fullRedBlockCount should never be > 10, I see in the log:

value:1.346314096E9; fullRedBlockCount:134631409; partialRedBlockIndex:3; ...

Looks like a math error and fullRedBlockCount removed the ".". Was it supposed to round there?

Looks like a fullRedBlockCount that high would cause quite the delay!

padcom commented 10 years ago

From MALfunct...@gmail.com on May 09, 2011 08:59:01

Since each red block represents 10% of the total value, fullRedBlockCount is going to be the total value divided by 10. That's why the decimal disappeared. The value is no longer large enough to present in scientific notation.

Do you mind attaching more screenshots from jconsole? I'd like to see the JMX attributes of each of your memory pools for a running server. Hopefully it will help us find out why Probe is reporting a usage score of more than a billion percent!

In the meantime, I will ensure that minValue and maxValue are enforced by the JSP tag.

padcom commented 10 years ago

From MALfunct...@gmail.com on May 09, 2011 09:09:31

This issue was updated by revision r532 .

Ensuring that value and value2 are never outside of the range defined by minValue and maxValue.

padcom commented 10 years ago

From coolman....@gmail.com on May 09, 2011 11:01:42

Here are the screen shots.

padcom commented 10 years ago

From MALfunct...@gmail.com on May 09, 2011 11:34:33

Sorry, what I really need are the contents of the "Usage" attribute of each pool. Its type is javax.management.openmbean.CompositeDataSupport. You can expand an attribute's row to see its contents by double-clicking it in jconsole.

I've attached an example.

Attachment: PS Eden Usage.png

padcom commented 10 years ago

From coolman....@gmail.com on May 09, 2011 12:27:08

Here again:

Attachment: MP_CLASS.bmp MP_HEAP.bmp MP_JIT1.bmp MP_JIT2.bmp MP_MISC.bmp

padcom commented 10 years ago

From MALfunct...@gmail.com on May 09, 2011 13:08:38

Why do most of them have a max of -1? The only one that has a max is the Heap, and its max is the same as its committed.

Does the IBM JDK allow those memory pools to grow indefinitely?

padcom commented 10 years ago

From MALfunct...@gmail.com on May 09, 2011 14:03:58

Apparently -1 means the max is undefined. This can happen in the Sun JVM as well. "Max: the maximum amount of memory that can be used for memory management. Its value may change or be undefined" (1).

In those cases, I'm going to calculate the usage score based on "used/committed" instead of the "used/max". That should address the issue.

(1) http://download.oracle.com/javase/6/docs/technotes/guides/management/jconsole.html#gddzq

Labels: -JVM-JRockit -JVM-IBM -HelpWanted

padcom commented 10 years ago

From MALfunct...@gmail.com on May 09, 2011 14:07:49

This issue was updated by revision r533 .

Calculating memory pool usage based on committed memory in the case where the maximum is undefined.

Status: Fixed

padcom commented 10 years ago

From MALfunct...@gmail.com on May 09, 2011 14:08:22

Labels: -Milestone-TBD Milestone-2.3.0

padcom commented 10 years ago

From coolman....@gmail.com on May 09, 2011 14:32:40

I am not sure those values are obtainable via JMX on the IBM JVM. We don't specify a max class storage, etc NON_HEAP size and let the JVM create those on its own.

padcom commented 10 years ago

From MALfunct...@gmail.com on May 09, 2011 14:49:52

Verified by coolman.callaghan.

Status: FixVerified

padcom commented 10 years ago

From MALfunct...@gmail.com on May 09, 2011 14:53:42

This seems worthy of a patch release. (I'm not really sure why I removed those labels.)

Labels: -Milestone-2.3.0 Milestone-2.2.2 JVM-IBM JVM-JRockit