Re: Tomcat 100% CPU usage after moving from Java 5 to 6
I'm also attempting to track down a cpu usage problem in tomcat. Can someone tell me how to generate thread dumps that includes the "cpu=" information like the ones Jesse attached? "ajp-8009-18" Id=187 in RUNNABLE cpu=242046 ms usr=242015 ms blocked 315 for -1 ms waited 256 for -1 ms When I create a tomcat thread dump using "ctrl-break", it does not contain any cpu info: "RMI TCP Accept-" daemon prio=6 tid=0x26eeda60 nid=0xd58 runnable [0x2712f00 0..0x2712fd68] at java.net.PlainSocketImpl.socketAccept(Native Method) Jesse Klaasse wrote: > > I am running a production environment for a website (over half a million > hits per day), using Tomcat 5.5.20 (I'm stuck to that version due to > support restrictions) behind IIS 6 using JK connector 1.2.28, > tcnative-1.dll (1.1.19) on Windows Server 2003 R2 Enterprise x64 SP2 > (with 16 GB RAM). Until last week, I have been using Sun Java 5. Last > week I have upgraded the JDK to Sun Java 6. > The system uses a MS SQL Server 2005 database, which resides on another > server. > > That's when things went wrong. At first, all seemed fine (average CPU > usage seems lower than when using Java 5), but after an hour or so (30 > minutes - 1,5 hour max) after a Tomcat restart, Tomcat's CPU usage jumps > to 100% (average CPU usage using Java 5 is around 30-40%, peaks around > 60%). I can't really figure out what is causing this. I have retried > about 6 restarts (including a complete system reboot), but without any > success. When I move back to Java 5, the problems are gone. > > My Tomcat Java arguments: > -Dcatalina.base=D:\tomcat -Dcatalina.home=D:\tomcat > -Djava.endorsed.dirs=D:\tomcat\common\endorsed > -Djava.io.tmpdir=D:\tomcat\temp > -Djavax.sql.DataSource.Factory=org.apache.commons.dbcp.BasicDataSourceFa > ctory -Dcom.sun.management.jmxremote -XX:MaxPermSize=512m > -Xloggc:D:\logs\gc\tomcat-gc.log -XX:+PrintGCDetails -XX:+UseParNewGC > -XX:+UseConcMarkSweepGC -XX:+UseTLAB -XX:+CMSClassUnloadingEnabled > -XX:+CMSPermGenSweepingEnabled -Xms4096m -Xmx10240m > > Some further information which could be important: > - I have tried to reproduce the problems on my development environment > (using jMeter for generating server load), but without success; > - I have created some thread dumps during the 100% CPU periods (attached > as a zip file); > > I would really like to make the move to Java 6, since Java 5's is EOL. > Any ideas, anyone? > > > > > > - > To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org > For additional commands, e-mail: users-h...@tomcat.apache.org > -- View this message in context: http://old.nabble.com/Tomcat-100--CPU-usage-after-moving-from-Java-5-to-6-tp27305110p28527724.html Sent from the Tomcat - User mailing list archive at Nabble.com. - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
RE: Tomcat 100% CPU usage after moving from Java 5 to 6
> From: Christopher Schultz [mailto:ch...@christopherschultz.net] > Subject: Re: Tomcat 100% CPU usage after moving from Java 5 to 6 > > It's interesting that there's no timing data for that last statement. > It /is/ possible this is where the JVM went down. (Did it go down?) That's very suspicious. I'm wondering if the OS killed the process just because it asked for timing information in a bad way? (E.g., have some counters overflowed?) > Both of these GC runs seem to be collecting a /lot/ of garbage: > 3272635K->747297K Completely understandable given the large heap size. Note that the term "garbage collection" is somewhat of a misnomer these days; it's the live objects that are collected and moved - the dead ones are simply ignored. > I don't believe the GC will do "serial" collections unless explicitly > told to do that. The days of "stop the world" garbage collection are > long gone. Not true; "stop the world" is still the default, but the pause time is a lot shorter than it used to be. (I'd avoid the use of the word "serial" here, since the GC default is parallel, but not concurrent.) Regardless, I would try removing the concurrent GC settings and see if the problem disappears. > > And also the +DisableExplicitGC? > > That only causes the JVM to ignore calls to System.gc(), which aren't > guaranteed to do anything, anyway. Unless you are deploying unknown > webapps, this probably isn't doing anything at all. There is some Sun-provided RMI code that still insists on calling System.gc() for no particular reason, so disabling the explicit calls is a good idea. > If the GC were running like crazy, I suspect you'd see more > CPU usage. Definitely. This does not have the feel of a GC problem, but rather something broken in JVM native calls to the OS causing abrupt process termination. Since your CPU utilization doesn't seem to be a problem, is there any detailed OS logging you can enable to trace the calls to the kernel? - Chuck THIS COMMUNICATION MAY CONTAIN CONFIDENTIAL AND/OR OTHERWISE PROPRIETARY MATERIAL and is thus for use only by the intended recipient. If you received this in error, please contact the sender and delete the e-mail and its attachments from all computers.
Re: Tomcat 100% CPU usage after moving from Java 5 to 6
-BEGIN PGP SIGNED MESSAGE- Hash: SHA1 Jesse, On 2/2/2010 3:23 AM, Jesse Klaasse wrote: > Christopher Schultz-2 wrote: >> >> Can you give us a timestamp for when the trouble started? Reading GC >> output is pretty tedious. >> > > I believe the trouble started around 15 - 20 minutes before the end of the > gc log, so that would be from ~61h36m. That's 221760 minutes, and you only have two GC log lines near or after that time: 222745.754: [GC 222745.754: [ParNew: 2566632K->34378K(2831168K), 0.1180327 secs] 3272635K->747297K(7025472K), 0.1187242 secs] [Times: user=0.44 sys=0.02, real=0.13 secs] 223001.755: [GC 223001.756: [ParNew: 2550986K->55967K(2831168K), 0.1662147 secs] 3263905K->775682K(7025472K), 0.1667915 secs] It's interesting that there's no timing data for that last statement. It /is/ possible this is where the JVM went down. (Did it go down?) Both of these GC runs seem to be collecting a /lot/ of garbage: 3272635K->747297K That's a reduction of roughly 75%... though I guess in .13 seconds, it's not taking so long, so it should be fine. I guess your webapp generates a lot of temporary data, fast. At least it gets cleaned-up quickly. >> Also, what happens if you remove all your *GC* options (other than >> logging) from your JAVA_OPTS? > > I am quite hesitant to try this. This is a production environment, and all > in all Tomcat is performing pretty good now, in comparison to what the > situation was before. Do you have a place where you can really play around with this? > By "all" GC options, do you also mean the UseConcMarkSweepGC? Wouldn't the > GC become serial then (with pauses which stop the whole webapp for a while)? I don't believe the GC will do "serial" collections unless explicitly told to do that. The days of "stop the world" garbage collection are long gone. > And also the +DisableExplicitGC? That only causes the JVM to ignore calls to System.gc(), which aren't guaranteed to do anything, anyway. Unless you are deploying unknown webapps, this probably isn't doing anything at all. >> Is this reproducible? > > Well, as I said, Tomcat is working much more stable now than it did before. > However, once in a few days it still becomes unresponsive, while CPU usage > stays incredibly low. I have tried load tests using jMeter on our > development environment, but it's working fine then. Must have something to > do with the "real" (more diverse, less predictable/repetitive) traffic on > the production environment, I guess.. I'd be interested in what a thread dump shows you during one of these pauses. I agree with Dan: this sounds much more like your webapp is waiting around for something like a db connection than doing anything active. If the GC were running like crazy, I suspect you'd see more CPU usage. - -chris -BEGIN PGP SIGNATURE- Version: GnuPG v1.4.10 (MingW32) Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/ iEUEARECAAYFAktojf4ACgkQ9CaO5/Lv0PAcAwCWJdL0fddltpbT4xliEY3Cgiqc 3QCfYE4EvIedEbFtQnGWVbij29Oz234= =rVYe -END PGP SIGNATURE- - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Tomcat 100% CPU usage after moving from Java 5 to 6
> > Well, as I said, Tomcat is working much more stable now than it did before. > However, once in a few days it still becomes unresponsive, while CPU usage > stays incredibly low. Unresponsive, meaning what, exactly? If the CPU is idle, but your webapp isn't returning a response... it seems to indicate that your webapp is waiting on something else... DB query, file read, whatever. It seems unlikely that it would be blocked, consistently by a garbage collection - especially with the heap sizes you are running with. VisualJVM can give you a clue as to what threads are running, and which ones are waiting when the system is unresponsive. - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Tomcat 100% CPU usage after moving from Java 5 to 6
Christopher Schultz-2 wrote: > > Can you give us a timestamp for when the trouble started? Reading GC > output is pretty tedious. > I believe the trouble started around 15 - 20 minutes before the end of the gc log, so that would be from ~61h36m. Christopher Schultz-2 wrote: > > Also, what happens if you remove all your *GC* options (other than > logging) from your JAVA_OPTS? > I am quite hesitant to try this. This is a production environment, and all in all Tomcat is performing pretty good now, in comparison to what the situation was before. By "all" GC options, do you also mean the UseConcMarkSweepGC? Wouldn't the GC become serial then (with pauses which stop the whole webapp for a while)? And also the +DisableExplicitGC? Christopher Schultz-2 wrote: > > Is this reproducible? > Well, as I said, Tomcat is working much more stable now than it did before. However, once in a few days it still becomes unresponsive, while CPU usage stays incredibly low. I have tried load tests using jMeter on our development environment, but it's working fine then. Must have something to do with the "real" (more diverse, less predictable/repetitive) traffic on the production environment, I guess.. -- View this message in context: http://old.nabble.com/Tomcat-100--CPU-usage-after-moving-from-Java-5-to-6-tp27305110p27416818.html Sent from the Tomcat - User mailing list archive at Nabble.com. - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Tomcat 100% CPU usage after moving from Java 5 to 6
-BEGIN PGP SIGNED MESSAGE- Hash: SHA1 Jesse, On 2/1/2010 5:22 AM, Jesse Klaasse wrote: > > In the meantime, the environment has been much more stable than it was before > the move to Java 6 and the new JVM options. However, a few minutes ago, > Tomcat became completely unresponsive, while the CPU usage was very low > (~3%). This was on our external server, with these options: > > -Djavax.sql.DataSource.Factory=org.apache.commons.dbcp.BasicDataSourceFactory > -Dcom.sun.management.jmxremote -XX:MaxPermSize=512m > -Xloggc:D:\logs\gc\tomcat-gc.log -XX:+PrintGCDetails -XX:+UseConcMarkSweepGC > -XX:+CMSClassUnloadingEnabled -XX:+DisableExplicitGC -XX:NewSize=3072m > -XX:+UseCompressedOops -Xms7168m -Xmx7168m > > The gc log is showing a lot of activity during the unresponsiveness (the gc > log is attached to this message). Do you guys see any clues? Thanks in > advance! Can you give us a timestamp for when the trouble started? Reading GC output is pretty tedious. Also, what happens if you remove all your *GC* options (other than logging) from your JAVA_OPTS? Is this reproducible? - -chris -BEGIN PGP SIGNATURE- Version: GnuPG v1.4.10 (MingW32) Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/ iEYEARECAAYFAktnFpsACgkQ9CaO5/Lv0PCLVgCdHzgBFn2cWkBhYpRgIbHHX1jV GqsAnjYuakiGzdELRgMEmzNGxKu8fIR+ =sPnf -END PGP SIGNATURE- - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Tomcat 100% CPU usage after moving from Java 5 to 6
In the meantime, the environment has been much more stable than it was before the move to Java 6 and the new JVM options. However, a few minutes ago, Tomcat became completely unresponsive, while the CPU usage was very low (~3%). This was on our external server, with these options: -Djavax.sql.DataSource.Factory=org.apache.commons.dbcp.BasicDataSourceFactory -Dcom.sun.management.jmxremote -XX:MaxPermSize=512m -Xloggc:D:\logs\gc\tomcat-gc.log -XX:+PrintGCDetails -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:+DisableExplicitGC -XX:NewSize=3072m -XX:+UseCompressedOops -Xms7168m -Xmx7168m The gc log is showing a lot of activity during the unresponsiveness (the gc log is attached to this message). Do you guys see any clues? Thanks in advance! The Tomcat GC log: http://old.nabble.com/file/p27402032/tomcat-gc.log tomcat-gc.log -- View this message in context: http://old.nabble.com/Tomcat-100--CPU-usage-after-moving-from-Java-5-to-6-tp27305110p27402032.html Sent from the Tomcat - User mailing list archive at Nabble.com. - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Tomcat 100% CPU usage after moving from Java 5 to 6
2010/1/26 Leon Rosenberg > Another customer of mine was playing with gc settings for nearly a > year, because his tomcats collection times went higher and higher, and > after a short look at the heap dump with jmap and jhat, we found out > that he had 100.000.000 uncollectable garbage objects in the heap (2/3 > of his heap actually). Instead of investigating his heap pollution he > spent 11 month playing with gc options to setup a faster gc. In the > end the problem was solved in two days. > > Definitely. I've had the same in Smalltalk, the same in C# under the CLR. Fewer live objects in the heap = faster GC. Creating fewer short-lived objects = less time spent in GC and in tenuring objects. Almost always, the root of a GC performance problem isn't the GC at all :-). - Peter
Re: Tomcat 100% CPU usage after moving from Java 5 to 6
On Tue, Jan 26, 2010 at 4:50 PM, Jesse Klaasse wrote: > > Hi Chuck, thanks for your extensive comments about the JVM options.. > On a site note... I have made the observation that the JVM is performing best without any explicit gc settings. Most time explicit GC settings just cause havoc (fixes sized generation spaces lead to 100% cpu usage and continuous full gcs, some performance options are extremely vm version specific and so on). Among the sites of my customers, one site is serving more than 500 requests per second in a single tomcat with only following options: -Xmx16G -Xms16G -XX:MaxPermSize=512M -XX:+PrintGCDetails -XX:+PrintGCTimeStamps Another customer of mine was playing with gc settings for nearly a year, because his tomcats collection times went higher and higher, and after a short look at the heap dump with jmap and jhat, we found out that he had 100.000.000 uncollectable garbage objects in the heap (2/3 of his heap actually). Instead of investigating his heap pollution he spent 11 month playing with gc options to setup a faster gc. In the end the problem was solved in two days. Most time I've seen people playing with gc settings, nothing good came out of it, save for real experts like Chuck. Thats just a side note ;-) regards Leon - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
RE: Tomcat 100% CPU usage after moving from Java 5 to 6
Hi Chuck, thanks for your extensive comments about the JVM options.. n828cl wrote: > >>-Xms10240m -Xmx10240m > > That's a very large heap; shouldn't hurt as long as you have enough RAM to > support it all without paging. (But see below for use with compressed > OOPs.) > This shouldn't be a problem, the system has 16 GB RAM, almost all of it dedicated to Tomcat. n828cl wrote: > >> Tomcat's CPU usage seems significantly lower than before >> (it's average seems about 10% now - which was 30-40% before) > > There are some improvements in the JDK/JRE 6 JIT and synchronization > handling, but probably not enough to account for that large a difference. > Well, I don't know where exactly it's coming from, but after a full day very closely monitoring the system, it turns out to be the truth. Which is not a bad thing, of course :) n828cl wrote: > >> I also added the -XX:+UseCompressedOops JVM option > > Be careful with that; it can impact CPU usage, since the compressed OOPs > have to be expanded into actual pointers every time they're used, and > pointers compressed when stored in a field. Works best with heap sizes > less than 4 GB, which avoids the decoding/encoding. For a real > explanation of compressed OOPs, look here: > http://wikis.sun.com/display/HotSpotInternals/CompressedOops > I already found that article myself. Since CPU usage is as low as it is now, I have decided to give it a try. Anyway, thanks again! -- View this message in context: http://old.nabble.com/Tomcat-100--CPU-usage-after-moving-from-Java-5-to-6-tp27305110p27324793.html Sent from the Tomcat - User mailing list archive at Nabble.com. - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
RE: Tomcat 100% CPU usage after moving from Java 5 to 6
> From: Jesse Klaasse [mailto:jesse.klaa...@indicia.nl] > Subject: Re: Tomcat 100% CPU usage after moving from Java 5 to 6 > > I found the following article particularly useful: > http://confluence.atlassian.com/display/DOC/Garbage+Collector+Performance+Issues Unfortunately, that article is so full of mistaken assumptions and outright errors that it must be taken with a large chunk of salt. There are some good things in it, but also a lot of rubbish. Among other things, the author is obviously unaware of how paging systems work, confusing contiguous virtual memory (required for the heap) with contiguous real memory (not required at all). > -XX:+UseConcMarkSweepGC This will reduce overall throughput, but also reduce the GC pause time. (GC pause time is pretty small even without that parameter these days.) It does make the GC threads do a lot more work, but you appear to have CPU time to burn. >-XX:+UseTLAB This has been the default for quite a few years now, so it's unnecessary to specify it. >-XX:+CMSClassUnloadingEnabled The above slows down CMS collections. You can leave it off if you never update JSPs on the fly, or redeploy webapps without a Tomcat restart. >-XX:+CMSPermGenSweepingEnabled The above is the old name for CMSClassUnloadingEnabled and should not be used. >-XX:+DisableExplicitGC Always a good idea to set the above. >-XX:NewSize=4096m I would be wary of setting the above parameter, preferring to let the JVM determine the value as needed. JDK/JRE 6 is much better at reacting to dynamic changes in workload than 1.4 was. >-Xms10240m -Xmx10240m That's a very large heap; shouldn't hurt as long as you have enough RAM to support it all without paging. (But see below for use with compressed OOPs.) > Tomcat's CPU usage seems significantly lower than before > (it's average seems about 10% now - which was 30-40% before) There are some improvements in the JDK/JRE 6 JIT and synchronization handling, but probably not enough to account for that large a difference. > I also added the -XX:+UseCompressedOops JVM option Be careful with that; it can impact CPU usage, since the compressed OOPs have to be expanded into actual pointers every time they're used, and pointers compressed when stored in a field. Works best with heap sizes less than 4 GB, which avoids the decoding/encoding. For a real explanation of compressed OOPs, look here: http://wikis.sun.com/display/HotSpotInternals/CompressedOops - Chuck THIS COMMUNICATION MAY CONTAIN CONFIDENTIAL AND/OR OTHERWISE PROPRIETARY MATERIAL and is thus for use only by the intended recipient. If you received this in error, please contact the sender and delete the e-mail and its attachments from all computers. - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Tomcat 100% CPU usage after moving from Java 5 to 6
I also added the -XX:+UseCompressedOops JVM option (as suggested in the Confluence article I mentioned earlier). BTW, for those who want to know: this option is available since update 14 of JDK 6 (see also http://java.sun.com/javase/6/webnotes/6u14.html), you don't need the "Performance branch" as mentioned in the article. This option is said to give a performance gain of 25% as well as a reduction of used heap space (see also http://blog.juma.me.uk/2008/10/14/32-bit-or-64-bit-jvm-how-about-a-hybrid/). Furthermore, I discovered the -XX:+UseTLAB option is a default option in JDK 6: http://java.sun.com/javase/technologies/hotspot/vmoptions.jsp I thought, I'd just let you all know! -- View this message in context: http://old.nabble.com/Tomcat-100--CPU-usage-after-moving-from-Java-5-to-6-tp27305110p27322864.html Sent from the Tomcat - User mailing list archive at Nabble.com. - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Tomcat 100% CPU usage after moving from Java 5 to 6
Jesse Klaasse wrote: I have now fixed the infinite loop, and again did the update from Java 5 to Java 6. This time all seems to be working like a charm! Along with fixing the infinite loop, I have dug a little deeper into the JVM arguments. I found the following article particularly useful: http://confluence.atlassian.com/display/DOC/Garbage+Collector+Performance+Issues Using that article plus common sense, my arguments are now: -Djavax.sql.DataSource.Factory=org.apache.commons.dbcp.BasicDataSourceFactory -Dcom.sun.management.jmxremote -XX:MaxPermSize=512m -Xloggc:D:\logs\gc\tomcat-gc.log -X:+PrintGCDetails -XX:+UseConcMarkSweepGC -XX:+UseTLAB -XX:+CMSClassUnloadingEnabled -XX:+CMSPermGenSweepingEnabled -XX:+DisableExplicitGC -XX:NewSize=4096m -Xms10240m -Xmx10240m The NewSize parameter was new to me, and it's explanation on the aforementioned link made much sense. A few things I'm still not completely sure about: - I don't want any serial garbage collection to occur. I'm not sure whether my arguments take care of this now.. - Do I still need the -XX:+UseTLAB argument? - Do I still need the -XX:+CMSClassUnloadingEnabled flag? - Do I still need the -XX:+CMSPermGenSweepingEnabled flag? So, still some research to be done. In the meantime I am very pleased with the results. Tomcat's CPU usage seems significantly lower than before (it's average seems about 10% now - which was 30-40% before) - scary! Jesse, thanks for the feedback. 1) for the people here trying to help, it just "feels nice" to know that they have actually done so. 2) the searchable archives of this list are a real resource in case of problems (at least for the people who bother to search them before asking questions). Having the solution to the problem contained in the archive is certainly a plus. - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Tomcat 100% CPU usage after moving from Java 5 to 6
I have now fixed the infinite loop, and again did the update from Java 5 to Java 6. This time all seems to be working like a charm! Along with fixing the infinite loop, I have dug a little deeper into the JVM arguments. I found the following article particularly useful: http://confluence.atlassian.com/display/DOC/Garbage+Collector+Performance+Issues Using that article plus common sense, my arguments are now: -Djavax.sql.DataSource.Factory=org.apache.commons.dbcp.BasicDataSourceFactory -Dcom.sun.management.jmxremote -XX:MaxPermSize=512m -Xloggc:D:\logs\gc\tomcat-gc.log -X:+PrintGCDetails -XX:+UseConcMarkSweepGC -XX:+UseTLAB -XX:+CMSClassUnloadingEnabled -XX:+CMSPermGenSweepingEnabled -XX:+DisableExplicitGC -XX:NewSize=4096m -Xms10240m -Xmx10240m The NewSize parameter was new to me, and it's explanation on the aforementioned link made much sense. A few things I'm still not completely sure about: - I don't want any serial garbage collection to occur. I'm not sure whether my arguments take care of this now.. - Do I still need the -XX:+UseTLAB argument? - Do I still need the -XX:+CMSClassUnloadingEnabled flag? - Do I still need the -XX:+CMSPermGenSweepingEnabled flag? So, still some research to be done. In the meantime I am very pleased with the results. Tomcat's CPU usage seems significantly lower than before (it's average seems about 10% now - which was 30-40% before) - scary! -- View this message in context: http://old.nabble.com/Tomcat-100--CPU-usage-after-moving-from-Java-5-to-6-tp27305110p27319482.html Sent from the Tomcat - User mailing list archive at Nabble.com. - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Tomcat 100% CPU usage after moving from Java 5 to 6
-BEGIN PGP SIGNED MESSAGE- Hash: SHA1 Jesse, On 1/25/2010 8:25 AM, Jesse Klaasse wrote: > I don't know what you mean exactly by "re-intrant" Re-entrant (never seen it as "re-intrant") means that more than one thread of execution might be running the same code concurrently. I've never heard this term used with languages that support threading directly (where it's simply called concurrency), but Leon was basically asking if your method was threadsafe (or if it didn't matter, because there was no shared data in the mix). > but your comment points out I have created an endless while-loop! Oops. That ought to create 100% usage :) cvs diff is your friend :) - -chris -BEGIN PGP SIGNATURE- Version: GnuPG v1.4.10 (MingW32) Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/ iEYEARECAAYFAktd9OQACgkQ9CaO5/Lv0PBISACfYFKQcf43RwMJbl6zdRKayQOF Bj8AoKWHB2N7iX0iZB7Sjx06AFC67nTp =LEu4 -END PGP SIGNATURE- - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Tomcat 100% CPU usage after moving from Java 5 to 6
Jesse Klaasse wrote: Hi Leon, I don't know what you mean exactly by "re-intrant", but your comment points out I have created an endless while-loop! Apart from moving to Java 6, I had commented out some lines to reduce logging, not noticing I had created an endless loop by doing so. I only did this in a jar compiled for Java 6, so everytime I tried rolling back to Java 5, I also used the old jar (which didn't have the lines commented out), and the old jar didn't have the infinite loop. Stupid! I was completely sure the change from Java 5 to Java 6 was a far bigger one than the commented-out-lines, but this turns out to be not true at all in this case! IME, the change from java 5 to java 6 is entirely transparent to the application, and the only difference I've seen is a bit better performance under 6. That probably won't be everybody's experience, but it is mine. D - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Tomcat 100% CPU usage after moving from Java 5 to 6
Jesse Klaasse wrote: ... ctory -Dcom.sun.management.jmxremote -XX:MaxPermSize=512m -Xloggc:D:\logs\gc\tomcat-gc.log -XX:+PrintGCDetails -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+UseTLAB -XX:+CMSClassUnloadingEnabled -XX:+CMSPermGenSweepingEnabled -Xms4096m -Xmx10240m Apart from your basic issue (now solved) : If I remember correctly, one area that has had some changes between Java 1.5 and 1.6, is memory management and GC, generally. It might not be a bad idea to review the settings above, to see if they are still appropriate for 1.6. - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Tomcat 100% CPU usage after moving from Java 5 to 6
Hi Leon,
I don't know what you mean exactly by "re-intrant", but your comment points
out I have created an endless while-loop! Apart from moving to Java 6, I had
commented out some lines to reduce logging, not noticing I had created an
endless loop by doing so. I only did this in a jar compiled for Java 6, so
everytime I tried rolling back to Java 5, I also used the old jar (which
didn't have the lines commented out), and the old jar didn't have the
infinite loop. Stupid!
I was completely sure the change from Java 5 to Java 6 was a far bigger one
than the commented-out-lines, but this turns out to be not true at all in
this case!
Best regards, and thanks again!
Jesse.
Leon Rosenberg-3 wrote:
>
> Hello Jesse,
>
> is the Workflow re-intrant? If yes:
>
> this is odd:
>
> you are iterating in a re-intrant action (i assume the action is
> re-intrant) over a shared variable?
> Vector vecOids = new Vector();
>
> in the method:
> Iterator oidIterator = vecOids.iterator();
> while (oidIterator.hasNext())
> {
> //System.out.println("Workflow/doAction: oid=" +
> ((ObjectId)oidIterator.next()).getKey());
> }
> and you are modifying this vector at multiple places in the same class.
>
> You should probably unit-test this code for concurrency.
>
> regards
> Leon
>
--
View this message in context:
http://old.nabble.com/Tomcat-100--CPU-usage-after-moving-from-Java-5-to-6-tp27305110p27306543.html
Sent from the Tomcat - User mailing list archive at Nabble.com.
-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Tomcat 100% CPU usage after moving from Java 5 to 6
Hello Jesse,
is the Workflow re-intrant? If yes:
this is odd:
you are iterating in a re-intrant action (i assume the action is
re-intrant) over a shared variable?
Vector vecOids = new Vector();
in the method:
Iterator oidIterator = vecOids.iterator();
while (oidIterator.hasNext())
{
//System.out.println("Workflow/doAction: oid=" +
((ObjectId)oidIterator.next()).getKey());
}
and you are modifying this vector at multiple places in the same class.
You should probably unit-test this code for concurrency.
regards
Leon
On Mon, Jan 25, 2010 at 1:41 PM, Jesse Klaasse wrote:
>
>
> Jesse Klaasse wrote:
>>
>> Those Workflow and DQWorkflow classes are from our company, written by the
>> programmer who worked on this project before me. I have attached the two
>> files for further examination.
>> I have noticed the performWorkflowAction method in DQWorkflow is not
>> synchronized and uses Vectors and Iterators. Could this be a possible
>> problem? Even though this all has been working perfectly fine in Java 4
>> and 5?
>>
>
> I forgot the attachments, sorry!
> http://old.nabble.com/file/p27306041/DQWorkflow.java DQWorkflow.java
> http://old.nabble.com/file/p27306041/Workflow.java Workflow.java
> --
> View this message in context:
> http://old.nabble.com/Tomcat-100--CPU-usage-after-moving-from-Java-5-to-6-tp27305110p27306041.html
> Sent from the Tomcat - User mailing list archive at Nabble.com.
>
>
> -
> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
> For additional commands, e-mail: users-h...@tomcat.apache.org
>
>
-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Tomcat 100% CPU usage after moving from Java 5 to 6
Jesse Klaasse wrote: > > Those Workflow and DQWorkflow classes are from our company, written by the > programmer who worked on this project before me. I have attached the two > files for further examination. > I have noticed the performWorkflowAction method in DQWorkflow is not > synchronized and uses Vectors and Iterators. Could this be a possible > problem? Even though this all has been working perfectly fine in Java 4 > and 5? > I forgot the attachments, sorry! http://old.nabble.com/file/p27306041/DQWorkflow.java DQWorkflow.java http://old.nabble.com/file/p27306041/Workflow.java Workflow.java -- View this message in context: http://old.nabble.com/Tomcat-100--CPU-usage-after-moving-from-Java-5-to-6-tp27305110p27306041.html Sent from the Tomcat - User mailing list archive at Nabble.com. - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Tomcat 100% CPU usage after moving from Java 5 to 6
Leon Rosenberg-3 wrote: > > they are all seem to be either in an infinite loop: > at java.util.AbstractList$Itr.hasNext(AbstractList.java:339) > at > nl.indicia.vip.framework.util.Workflow.performWorkflowAction(Workflow.java:166) > at > nl.indicia.vip.framework.util.DQWorkflow.performWorkflowAction(DQWorkflow.java:56) > at > org.apache.jsp.bamplaza.componenten.workflow.xmlworkflow_jsp._jspService(xmlworkflow_jsp.java:382) > > or iterating over a very huge list. This way or other they are > consuming your cpu: > "ajp-8009-18" Id=187 in RUNNABLE cpu=236296 ms usr=236265 ms blocked > 315 for -1 ms waited 256 for -1 ms > "ajp-8009-2" Id=171 in RUNNABLE cpu=221968 ms usr=218734 ms blocked > 12822 for -1 ms waited 10071 for -1 ms > "ajp-8009-30" Id=199 in RUNNABLE cpu=371562 ms usr=368234 ms blocked > 9527 for -1 ms waited 7543 for -1 ms > "ajp-8009-38" Id=210 in RUNNABLE cpu=518890 ms usr=515593 ms blocked > 10352 for -1 ms waited 9035 for -1 ms > http://old.nabble.com/file/p27305988/DQWorkflow.java DQWorkflow.java > http://old.nabble.com/file/p27305988/Workflow.java Workflow.java > > So either its a bug (maybe a concurrency issue, since java 1.6. has > improved a lot in terms of lock contention reduction) or, > its a side effect of an out of memory problem, can you make a heap > dump with jmap and check whether your Old Gen is 99.% full? > > Otherwise you should look into at > nl.indicia.vip.framework.util.Workflow.performWorkflowAction(Workflow.java:166) > which I never heard of, and don't have sources to check, what's > happening there exactly. > Those Workflow and DQWorkflow classes are from our company, written by the programmer who worked on this project before me. I have attached the two files for further examination. I have noticed the performWorkflowAction method in DQWorkflow is not synchronized and uses Vectors and Iterators. Could this be a possible problem? Even though this all has been working perfectly fine in Java 4 and 5? -- View this message in context: http://old.nabble.com/Tomcat-100--CPU-usage-after-moving-from-Java-5-to-6-tp27305110p27305988.html Sent from the Tomcat - User mailing list archive at Nabble.com. - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Tomcat 100% CPU usage after moving from Java 5 to 6
Pid Ster wrote: > > Have you tested those memory and garbage collection settings with this > version of Java? > Well, actually I haven't touched the settings which I used using Java 5. But, I have tested the settings to some extent. My development environment worked perfectly fine using the same memory and garbage collection settings, also under heavy load (with jMeter). Are there any obvious mistakes? Pid Ster wrote: > > What does the garbage collection log indicate, normal or abnormal > activity? > Unfortunately I forgot to look at the gc.log (also I'm not sure how to interpret it correctly), and it's overwritten when Tomcat is restarted, so there's really nothing I can say about that. Do you suspect any problems there? -- View this message in context: http://old.nabble.com/Tomcat-100--CPU-usage-after-moving-from-Java-5-to-6-tp27305110p27305900.html Sent from the Tomcat - User mailing list archive at Nabble.com. - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Tomcat 100% CPU usage after moving from Java 5 to 6
P.S. Your tomcat is writing gc logs, please attach them next time. On Mon, Jan 25, 2010 at 12:31 PM, Leon Rosenberg wrote: > take a look on threads > ajp-8009-2 > ajp-8009-18 > ajp-8009-30 > ajp-8009-38 > > they are all seem to be either in an infinite loop: > at java.util.AbstractList$Itr.hasNext(AbstractList.java:339) > at > nl.indicia.vip.framework.util.Workflow.performWorkflowAction(Workflow.java:166) > at > nl.indicia.vip.framework.util.DQWorkflow.performWorkflowAction(DQWorkflow.java:56) > at > org.apache.jsp.bamplaza.componenten.workflow.xmlworkflow_jsp._jspService(xmlworkflow_jsp.java:382) > > or iterating over a very huge list. This way or other they are > consuming your cpu: > "ajp-8009-18" Id=187 in RUNNABLE cpu=236296 ms usr=236265 ms blocked > 315 for -1 ms waited 256 for -1 ms > "ajp-8009-2" Id=171 in RUNNABLE cpu=221968 ms usr=218734 ms blocked > 12822 for -1 ms waited 10071 for -1 ms > "ajp-8009-30" Id=199 in RUNNABLE cpu=371562 ms usr=368234 ms blocked > 9527 for -1 ms waited 7543 for -1 ms > "ajp-8009-38" Id=210 in RUNNABLE cpu=518890 ms usr=515593 ms blocked > 10352 for -1 ms waited 9035 for -1 ms > > So either its a bug (maybe a concurrency issue, since java 1.6. has > improved a lot in terms of lock contention reduction) or, > its a side effect of an out of memory problem, can you make a heap > dump with jmap and check whether your Old Gen is 99.% full? > > Otherwise you should look into at > nl.indicia.vip.framework.util.Workflow.performWorkflowAction(Workflow.java:166) > which I never heard of, and don't have sources to check, what's > happening there exactly. > > Good luck > Leon > > > > > > > On Mon, Jan 25, 2010 at 12:14 PM, Pid wrote: >> On 25/01/2010 11:08, Jesse Klaasse wrote: >>> >>> I am running a production environment for a website (over half a million >>> hits per day), using Tomcat 5.5.20 (I'm stuck to that version due to >>> support restrictions) behind IIS 6 using JK connector 1.2.28, >>> tcnative-1.dll (1.1.19) on Windows Server 2003 R2 Enterprise x64 SP2 >>> (with 16 GB RAM). Until last week, I have been using Sun Java 5. Last >>> week I have upgraded the JDK to Sun Java 6. >>> The system uses a MS SQL Server 2005 database, which resides on another >>> server. >>> That's when things went wrong. At first, all seemed fine (average CPU >>> usage seems lower than when using Java 5), but after an hour or so (30 >>> minutes - 1,5 hour max) after a Tomcat restart, Tomcat's CPU usage jumps >>> to 100% (average CPU usage using Java 5 is around 30-40%, peaks around >>> 60%). I can't really figure out what is causing this. I have retried >>> about 6 restarts (including a complete system reboot), but without any >>> success. When I move back to Java 5, the problems are gone. >>> My Tomcat Java arguments: >>> -Dcatalina.base=D:\tomcat -Dcatalina.home=D:\tomcat >>> -Djava.endorsed.dirs=D:\tomcat\common\endorsed >>> -Djava.io.tmpdir=D:\tomcat\temp >>> >>> -Djavax.sql.DataSource.Factory=org.apache.commons.dbcp.BasicDataSourceFactory >>> -Dcom.sun.management.jmxremote -XX:MaxPermSize=512m >>> -Xloggc:D:\logs\gc\tomcat-gc.log -XX:+PrintGCDetails -XX:+UseParNewGC >>> -XX:+UseConcMarkSweepGC -XX:+UseTLAB -XX:+CMSClassUnloadingEnabled >>> -XX:+CMSPermGenSweepingEnabled -Xms4096m -Xmx10240m >>> Some further information which could be important: >>> - I have tried to reproduce the problems on my development environment >>> (using jMeter for generating server load), but without success; >>> - I have created some thread dumps during the 100% CPU periods (attached >>> as a zip file); >>> I would really like to make the move to Java 6, since Java 5's is EOL. >>> Any ideas, anyone? >> >> Have you tested those memory and garbage collection settings with this >> version of Java? >> >> What does the garbage collection log indicate, normal or abnormal activity? >> >> Java 6 has some pretty good tools for examining a running JVM, have a nose >> around in the java/bin directory. >> >> >> p >> >> >> >> >> >> >>> - >>> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org >>> For additional commands, e-mail: users-h...@tomcat.apache.org >> >> >> - >> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org >> For additional commands, e-mail: users-h...@tomcat.apache.org >> >> > - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Tomcat 100% CPU usage after moving from Java 5 to 6
take a look on threads ajp-8009-2 ajp-8009-18 ajp-8009-30 ajp-8009-38 they are all seem to be either in an infinite loop: at java.util.AbstractList$Itr.hasNext(AbstractList.java:339) at nl.indicia.vip.framework.util.Workflow.performWorkflowAction(Workflow.java:166) at nl.indicia.vip.framework.util.DQWorkflow.performWorkflowAction(DQWorkflow.java:56) at org.apache.jsp.bamplaza.componenten.workflow.xmlworkflow_jsp._jspService(xmlworkflow_jsp.java:382) or iterating over a very huge list. This way or other they are consuming your cpu: "ajp-8009-18" Id=187 in RUNNABLE cpu=236296 ms usr=236265 ms blocked 315 for -1 ms waited 256 for -1 ms "ajp-8009-2" Id=171 in RUNNABLE cpu=221968 ms usr=218734 ms blocked 12822 for -1 ms waited 10071 for -1 ms "ajp-8009-30" Id=199 in RUNNABLE cpu=371562 ms usr=368234 ms blocked 9527 for -1 ms waited 7543 for -1 ms "ajp-8009-38" Id=210 in RUNNABLE cpu=518890 ms usr=515593 ms blocked 10352 for -1 ms waited 9035 for -1 ms So either its a bug (maybe a concurrency issue, since java 1.6. has improved a lot in terms of lock contention reduction) or, its a side effect of an out of memory problem, can you make a heap dump with jmap and check whether your Old Gen is 99.% full? Otherwise you should look into at nl.indicia.vip.framework.util.Workflow.performWorkflowAction(Workflow.java:166) which I never heard of, and don't have sources to check, what's happening there exactly. Good luck Leon On Mon, Jan 25, 2010 at 12:14 PM, Pid wrote: > On 25/01/2010 11:08, Jesse Klaasse wrote: >> >> I am running a production environment for a website (over half a million >> hits per day), using Tomcat 5.5.20 (I'm stuck to that version due to >> support restrictions) behind IIS 6 using JK connector 1.2.28, >> tcnative-1.dll (1.1.19) on Windows Server 2003 R2 Enterprise x64 SP2 >> (with 16 GB RAM). Until last week, I have been using Sun Java 5. Last >> week I have upgraded the JDK to Sun Java 6. >> The system uses a MS SQL Server 2005 database, which resides on another >> server. >> That's when things went wrong. At first, all seemed fine (average CPU >> usage seems lower than when using Java 5), but after an hour or so (30 >> minutes - 1,5 hour max) after a Tomcat restart, Tomcat's CPU usage jumps >> to 100% (average CPU usage using Java 5 is around 30-40%, peaks around >> 60%). I can't really figure out what is causing this. I have retried >> about 6 restarts (including a complete system reboot), but without any >> success. When I move back to Java 5, the problems are gone. >> My Tomcat Java arguments: >> -Dcatalina.base=D:\tomcat -Dcatalina.home=D:\tomcat >> -Djava.endorsed.dirs=D:\tomcat\common\endorsed >> -Djava.io.tmpdir=D:\tomcat\temp >> >> -Djavax.sql.DataSource.Factory=org.apache.commons.dbcp.BasicDataSourceFactory >> -Dcom.sun.management.jmxremote -XX:MaxPermSize=512m >> -Xloggc:D:\logs\gc\tomcat-gc.log -XX:+PrintGCDetails -XX:+UseParNewGC >> -XX:+UseConcMarkSweepGC -XX:+UseTLAB -XX:+CMSClassUnloadingEnabled >> -XX:+CMSPermGenSweepingEnabled -Xms4096m -Xmx10240m >> Some further information which could be important: >> - I have tried to reproduce the problems on my development environment >> (using jMeter for generating server load), but without success; >> - I have created some thread dumps during the 100% CPU periods (attached >> as a zip file); >> I would really like to make the move to Java 6, since Java 5's is EOL. >> Any ideas, anyone? > > Have you tested those memory and garbage collection settings with this > version of Java? > > What does the garbage collection log indicate, normal or abnormal activity? > > Java 6 has some pretty good tools for examining a running JVM, have a nose > around in the java/bin directory. > > > p > > > > > > >> - >> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org >> For additional commands, e-mail: users-h...@tomcat.apache.org > > > - > To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org > For additional commands, e-mail: users-h...@tomcat.apache.org > > - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Tomcat 100% CPU usage after moving from Java 5 to 6
On 25/01/2010 11:08, Jesse Klaasse wrote: I am running a production environment for a website (over half a million hits per day), using Tomcat 5.5.20 (I'm stuck to that version due to support restrictions) behind IIS 6 using JK connector 1.2.28, tcnative-1.dll (1.1.19) on Windows Server 2003 R2 Enterprise x64 SP2 (with 16 GB RAM). Until last week, I have been using Sun Java 5. Last week I have upgraded the JDK to Sun Java 6. The system uses a MS SQL Server 2005 database, which resides on another server. That's when things went wrong. At first, all seemed fine (average CPU usage seems lower than when using Java 5), but after an hour or so (30 minutes - 1,5 hour max) after a Tomcat restart, Tomcat's CPU usage jumps to 100% (average CPU usage using Java 5 is around 30-40%, peaks around 60%). I can't really figure out what is causing this. I have retried about 6 restarts (including a complete system reboot), but without any success. When I move back to Java 5, the problems are gone. My Tomcat Java arguments: -Dcatalina.base=D:\tomcat -Dcatalina.home=D:\tomcat -Djava.endorsed.dirs=D:\tomcat\common\endorsed -Djava.io.tmpdir=D:\tomcat\temp -Djavax.sql.DataSource.Factory=org.apache.commons.dbcp.BasicDataSourceFactory -Dcom.sun.management.jmxremote -XX:MaxPermSize=512m -Xloggc:D:\logs\gc\tomcat-gc.log -XX:+PrintGCDetails -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+UseTLAB -XX:+CMSClassUnloadingEnabled -XX:+CMSPermGenSweepingEnabled -Xms4096m -Xmx10240m Some further information which could be important: - I have tried to reproduce the problems on my development environment (using jMeter for generating server load), but without success; - I have created some thread dumps during the 100% CPU periods (attached as a zip file); I would really like to make the move to Java 6, since Java 5's is EOL. Any ideas, anyone? Have you tested those memory and garbage collection settings with this version of Java? What does the garbage collection log indicate, normal or abnormal activity? Java 6 has some pretty good tools for examining a running JVM, have a nose around in the java/bin directory. p - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
