tag:blogger.com,1999:blog-7735872642513631302.post19417969722169664..comments2023-07-15T17:54:51.492+01:00Comments on Alexey Ragozin: Safepoints in HotSpot JVMAlexey Ragozinhttp://www.blogger.com/profile/13720493857045012756noreply@blogger.comBlogger16125tag:blogger.com,1999:blog-7735872642513631302.post-48097499980857139282016-10-31T14:02:10.899+00:002016-10-31T14:02:10.899+00:00Thanks for your quick updates.
There are no prof...Thanks for your quick updates. <br /><br />There are no profiler attached to the java process. <br /><br />I don't see any log of general Threaddumps it means they are Internal Thread dumps as you mentioned. <br /><br />Any other suggestions what to look for next?<br /><br />Thanks,<br />KEshavkeshav upadhyayahttps://www.blogger.com/profile/06926101969250512861noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-39348217216674092232016-10-29T15:04:45.365+01:002016-10-29T15:04:45.365+01:00I would guess, it is result of profiler. Thread du...I would guess, it is result of profiler. Thread dumps are widely used by profiler and sometimes by monitoring tools. Java code could also cause thread dump for itself.Alexey Ragozinhttps://www.blogger.com/profile/13720493857045012756noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-26804165472551532432016-10-28T12:13:48.502+01:002016-10-28T12:13:48.502+01:00Hi,
I am getting millions of following messages:...Hi, <br /><br />I am getting millions of following messages:<br />54.104: ThreadDump [ 153 2 3 ] [ 0 0 0 0 0 ] 0 <br /> vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count<br />54.104: ThreadDump [ 153 3 4 ] [ 0 0 0 0 0 ] 0 <br /> vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count<br />54.104: ThreadDump [ 153 1 6 ] [ 0 0 0 0 0 ] 0 <br /> vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count<br />54.104: ThreadDump [ 153 2 2 ] [ 0 0 0 0 0 ] 0 <br /> vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count<br />54.105: ThreadDump [ 153 0 2 ] [ 0 0 0 0 0 ] 0 <br /> vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count<br />54.105: ThreadDump [ 153 1 6 ] [ 0 0 0 0 0 ] 0 <br /> vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count<br /><br /><br /><br />What could be the reason of ThreadDump activity in SafePoint?keshav upadhyayahttps://www.blogger.com/profile/06926101969250512861noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-22320790510529099902013-11-14T15:51:24.945+00:002013-11-14T15:51:24.945+00:00Running VMStat for 5 hours has given the following...Running VMStat for 5 hours has given the following result, i am providing a part of the output:<br> swap free re mf pi po 40336468 4025208 383 5473 465 59 40336132 4025732 383 5477 465 59 40336020 4025732 383 5478 465 59 40335940 4025752 383 5479 465 59 40335860 4025776 383 5479 465 59 40335776 4025796 383 5480 465 59 40335696 4025816 383 5481 465 59 40335584 4025816 383 5482 464 59 40335504 4025836 383 5483 464 59 40335420 4025856 383 5484 464 59<br /><br />Can we inference something from this outputAnonymousnoreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-74046532297266418772013-11-14T13:34:58.573+00:002013-11-14T13:34:58.573+00:00Hi Alexey, as suggested by you i have posted quest...Hi Alexey, as suggested by you i have posted question on stackoverflow.com and here is the link<br /><br />http://stackoverflow.com/questions/19979030/gc-is-taking-mammoth-time<br /><br />Also here is the start up parameters and PrintGCDetails are not enabled and will take time as it is production server.<br /><br /><br />-Xms6144m -Xmx6144m -XX:MaxPermSize=256m -Djava.security.policy=/bea/wlserver_10.3/server/lib/weblogic.policy -Dweblogic.ProductionModeEnabled=true -da -Dplatform.home=/bea/wlserver_10.3 -Dwls.home=/bea/wlserver_10.3/server -Dweblogic.home=/bea/wlserver_10.3/server -Dweblogic.management.discover=true -Dwlw.iterativeDev=false -Dwlw.testConsole=false -Dwlw.logErrorsToConsole=false -Dweblogic.ext.dirs=/bea/patch_wls1036/profiles/default/sysext_manifest_classpath -Djava.awt.headless=true -Djava.net.preferIPv4Stack=true -Duser.timezone=GMT -Dfile.encoding=UTF-8 -Duser.language=en -Duser.country=US -Dweblogic.wsee.wstx.wsat.deployed=false -XX:+DisableExplicitGC<br />Anonymousnoreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-56445079970738761662013-11-14T12:02:08.969+00:002013-11-14T12:02:08.969+00:00Hi,
To be able to give you a reasonable advise, I...Hi,<br /><br />To be able to give you a reasonable advise, I need<br />- your JVM start parameters<br />- excerpt from your GC logs with at least -Xx:+PrintGCDetails enabled<br /><br />I would also suggest you to post question on stackoverflow.com (and post link here) as it is better platform for that kind of questions.<br /><br />Regards,<br />AlexeyAlexey Ragozinhttps://www.blogger.com/profile/13720493857045012756noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-30346958799053668232013-11-14T10:17:57.740+00:002013-11-14T10:17:57.740+00:00Hi Alexey, your articles are very informative. Rec...Hi Alexey, your articles are very informative. Recently i have faced a situation where GC is taking mamooth time and not sure what can be the reason. Here is the output of jstat -gc command<br /><br /> S0C S1C S0U S1U EC EU OC OU PC PU YGC YGCT FGC FGCT GCT<br /><br />77440.0 73088.0 22896.4 0.0 1946624.0 222690.4 4194304.0 3638965.1 262144.0 216641.1 1093 11258.452 3 10031.493 21289.944<br />Anonymousnoreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-25953802343551153612013-10-03T07:08:28.527+01:002013-10-03T07:08:28.527+01:00Hi Alexey, thanks for the feedback. We did not alw...Hi Alexey, thanks for the feedback. We did not always turn on -XX:+PrintSafepointStatistics because the output is so obscure. Our test program that recreates the stall just uses log4j and does not make calls to JNI but it's great to know about this option PrintJNIGCStalls. lpcd2001https://www.blogger.com/profile/13123375442608540883noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-87074604599634759222013-10-03T06:52:32.808+01:002013-10-03T06:52:32.808+01:00Have you enabled -XX:+PrintSafepointStatistics ?
...Have you enabled -XX:+PrintSafepointStatistics ?<br /><br />Sometimes I've seen JVM spending too much time trying to enter to safe point. Safe point initiation time is accounted to GC pause time.<br /><br />Another suspects are native threads taking GC lock via JNI (+XX:+PrintJNIGCStals may help to identify if this is a case).<br /><br />Regards,<br />Alexey Alexey Ragozinhttps://www.blogger.com/profile/13720493857045012756noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-52903121516535175052013-09-24T06:05:38.998+01:002013-09-24T06:05:38.998+01:00Very informative article, thank you. We have seen ...Very informative article, thank you. We have seen due to IO overload inside Linux. When this happens, GC log entries show use_time ~0, sys_time ~ 0, and real-time ~ at least 1 second. We are able to recreate this type of stalls in the lab too. It turns out that deferred writes to append a file can be blocked for a long time when the write is blocked by journal commit. Or when dirty_ratio is exceeded. We straced the Java process and could correlate some but not all of the stalls to GC threads when they write to the gc.log file. If GC threads do not have park the Java threads running in kernel mode, we are stumped about what else could have caused the stall (where user_time ~ 0, sys_time ~0). Any other data/traces you would recommend to help us understand the issue better? Many thanks.lpcd2001https://www.blogger.com/profile/13123375442608540883noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-31610584120624024862013-04-29T10:46:14.174+01:002013-04-29T10:46:14.174+01:00No, I didn't track exact bug. Slight change of...No, I didn't track exact bug. Slight change of code has solved issue in my case.<br />Yep, 2221291 is a nasty one.Alexey Ragozinhttps://www.blogger.com/profile/13720493857045012756noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-48320758354520666022013-04-29T08:34:06.410+01:002013-04-29T08:34:06.410+01:00We switched to 1.6.0_43, at the time that happened...We switched to 1.6.0_43, at the time that happened we had 1.6.0_31. One of the reasons was bug 2221291. Can you tell me the bug ID for the problem related to JIT?Primushttps://www.blogger.com/profile/17804944559353196812noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-46586993898686341352013-04-24T19:35:29.330+01:002013-04-24T19:35:29.330+01:00First enable safe point logging -XX:+PrintSafepoin...First enable safe point logging -XX:+PrintSafepointStatistics<br />-XX:PrintSafepointStatisticsCount=1<br />This will allow you to understand whenever safepoint is culprit.<br /><br />Last problem with slow safepoints, was bug in JIT combined with weird application code.<br /><br />Trying latest JVM is another step.<br /><br />Alexey Ragozinhttps://www.blogger.com/profile/13720493857045012756noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-31551810393452319412013-04-24T13:27:45.401+01:002013-04-24T13:27:45.401+01:00Thank you for an eye-opening article on safepoints...Thank you for an eye-opening article on safepoints. Do you know if there is any way to identify the reason for a huge pause of hundreds of seconds that does not appear to be related to GC activity?<br /><br />Total time for which application threads were stopped: 0.0020916 seconds<br />Total time for which application threads were stopped: 0.0677614 seconds<br />Total time for which application threads were stopped: 0.0016208 seconds<br />Total time for which application threads were stopped: 195.2580105 seconds<br />Total time for which application threads were stopped: 0.0313111 seconds<br />Total time for which application threads were stopped: 0.0005465 seconds<br />Total time for which application threads were stopped: 0.0006269 seconds<br />Primushttps://www.blogger.com/profile/17804944559353196812noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-91866327218726626552012-10-10T09:17:51.134+01:002012-10-10T09:17:51.134+01:00Using page faults for read barrier ("quickly ...Using page faults for read barrier ("quickly trap moved/GC'ed addresses") would be prohibitively expensive. Azul JVM does not use page faults for read barrier, though it is using this technique for defragmenting physical memory associated with large object.<br /><br />Azul is using custom page mapping to facilitate software read barrier, but this technique does not relay on page faults.<br /><br />Or at least it was that way last time I was working with Azul.Alexey Ragozinhttps://www.blogger.com/profile/13720493857045012756noreply@blogger.comtag:blogger.com,1999:blog-7735872642513631302.post-73458414830509506842012-10-01T19:15:42.144+01:002012-10-01T19:15:42.144+01:00Nice article Alexey. Do you know what part of the ...Nice article Alexey. Do you know what part of the JDK code really does this - "JVM unmaps page with that address provoking page fault on application thread"?<br /><br />I think the Azul JVM also used to do this to quickly trap moved/GC'ed addresses.Ashwin Jayaprakashhttps://www.blogger.com/profile/14487665820971997426noreply@blogger.com