This discussion is archived
1 Reply Latest reply: Feb 26, 2010 9:09 AM by 843829 RSS

CMS not yielding to java.util.zip???

843829 Newbie
Currently Being Moderated
Hello,

I have been trying to track down some long pauses in our voldemort BDB JE server. It appears these pauses correspond to CMS concurrent phases. In one example below it is during the concurrent-mark and in the other example it is during concurrent-sweep. From what I have been able to piece together, the GC thread should be yielding to the applications threads soon after they post a yield request. But that doesn't appear to be happening below as far as I can tell. The application seems to hang until the CMS phase ends which can be several seconds with our 6g heap size.

Am I interpreting things properly? Should the GC thread be yielding to the application yield requests? Threads dumps frequently show a thread as RUNNABLE at java.util.zip.Adler32.updateBytes(Native Method). This happens more frequently than I would expect by chance. Is it possible that the java.util.zip native method is unable to post the yield request??? I am running out of ideas here. Any suggestions would be appreciated.

thanks,
-sfp

A strace shows:

14914 14:52:08.217539 write(1, "1880.097", 8) = 8 <0.000023>
14914 14:52:08.217619 write(1, ": ", 2) = 2 <0.000012>
14914 14:52:08.217673 write(1, "[CMS-concurrent-sweep: 3.206/3.2"..., 40) = 40 <0.000013>
14914 14:52:08.217724 write(1, " (CMS-concurrent-sweep yielded 0"..., 40) = 40 <0.000013>
14914 14:52:08.217773 times({tms_utime=106915, tms_stime=19188, tms_cutime=0, tms_cstime=0}) = 558234922 <0.000015>
14914 14:52:08.217829 write(1, " [Times: user=3.20 sys=0.00, rea"..., 45) = 45 <0.000012>
14914 14:52:08.217879 write(1, "\n", 1) = 1 <0.000012>
14914 14:52:08.217929 futex(0x2aac40a8a324, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x464a9c18, 8) = 1 <0.000014>

after which thread 14946 starts getting the WAKEs from the thread 14914 GC thread.

14946 14:52:08.217975 <... futex resumed> ) = 0 <1.891633>
14946 14:52:08.218028 futex(0x464a9c18, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
14914 14:52:08.218063 futex(0x464a9c18, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
14946 14:52:08.218085 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) <0.000033>
14946 14:52:08.218121 futex(0x464a9c18, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
14914 14:52:08.218140 <... futex resumed> ) = 0 <0.000062>
14946 14:52:08.218161 <... futex resumed> ) = 0 <0.000026>
14946 14:52:08.218196 futex(0x47275e84, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x464ab728, 62 <unfinished ...>

And from a later run (look at the 2 seconds before the thread dump was forced):
(the timelogger is a trivial webapp to log a timestamp to make sure we aren't in a Stop The World GC)

-XX:+CMSClassUnloadingEnabled -XX:CMSCoordinatorYieldSleepCount=20 -XX:CMSYieldSleepCount=10 -XX:+ExplicitGCInvokesConcurrent -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/var/tmp -XX:+ManagementServer -XX:MaxHeapSize=6442450944 -XX:NewSize=314572800 -XX:+PrintCMSInitiationStatistics -XX:PrintCMSStatistics=2 -XX:+PrintClassHistogram -XX:+PrintCommandLineFlags -XX:PrintFLSStatistics=1 -XX:+PrintGC -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:+TraceClassUnloading -XX:+UseConcMarkSweepGC

[...]

1122.994: [GC [1 CMS-initial-mark: 4754072K(5324800K)] 4772017K(5601280K), 0.0044590 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
Total time for which application threads were stopped: 0.0092070 seconds
1122.999: [CMS-concurrent-mark-start]
Dec 22, 2009 3:37:11 PM com.lotame.timelogger.TimeLoggerResource update
INFO: sequence: 2602 logged @ 2009-12-22.15:37:11.647 delta=250
Dec 22, 2009 3:37:11 PM com.lotame.timelogger.TimeLoggerResource update
INFO: sequence: 2603 logged @ 2009-12-22.15:37:11.896 delta=249
Dec 22, 2009 3:37:12 PM com.lotame.timelogger.TimeLoggerResource update
INFO: sequence: 2604 logged @ 2009-12-22.15:37:12.147 delta=251
Dec 22, 2009 3:37:12 PM com.lotame.timelogger.TimeLoggerResource update
INFO: sequence: 2605 logged @ 2009-12-22.15:37:12.397 delta=250
Dec 22, 2009 3:37:12 PM com.lotame.timelogger.TimeLoggerResource update
INFO: sequence: 2606 logged @ 2009-12-22.15:37:12.646 delta=249
Dec 22, 2009 3:37:12 PM com.lotame.timelogger.TimeLoggerResource update
INFO: sequence: 2607 logged @ 2009-12-22.15:37:12.897 delta=251
Dec 22, 2009 3:37:13 PM com.lotame.timelogger.TimeLoggerResource update
INFO: sequence: 2608 logged @ 2009-12-22.15:37:13.146 delta=249
Dec 22, 2009 3:37:13 PM com.lotame.timelogger.TimeLoggerResource update
INFO: sequence: 2609 logged @ 2009-12-22.15:37:13.396 delta=250
Application time: 2.0828760 seconds
2009-12-22 15:37:13
Full thread dump Java HotSpot(TM) 64-Bit Server VM (10.0-b23 mixed mode):

[...]

"voldemort-niosocket-server2" daemon prio=10 tid=0x00002aac40114800 nid=0x3d59 waiting on condition [0x00000000428c7000..0x00000000428c7d10]
java.lang.Thread.State: RUNNABLE
at java.util.zip.Adler32.updateBytes(Native Method)
at java.util.zip.Adler32.update(Adler32.java:49)
at com.sleepycat.je.log.ChecksumValidator.update(ChecksumValidator.java:61)
at com.sleepycat.je.log.LogManager.getLogEntryFromLogSource(LogManager.java:713)
at com.sleepycat.je.log.LogManager.getLogEntry(LogManager.java:664)
at com.sleepycat.je.tree.IN.fetchTarget(IN.java:1215)
at com.sleepycat.je.dbi.CursorImpl.searchAndPosition(CursorImpl.java:2103)
at com.sleepycat.je.Cursor.searchInternal(Cursor.java:1778)
at com.sleepycat.je.Cursor.searchAllowPhantoms(Cursor.java:1748)
at com.sleepycat.je.Cursor.search(Cursor.java:1615)
at com.sleepycat.je.Cursor.getSearchKey(Cursor.java:1067)
at voldemort.store.bdb.BdbStorageEngine.get(BdbStorageEngine.java:169)
at voldemort.store.bdb.BdbStorageEngine.get(BdbStorageEngine.java:126)
at voldemort.store.bdb.BdbStorageEngine.getVersions(BdbStorageEngine.java:112)
at voldemort.store.bdb.BdbStorageEngine.getVersions(BdbStorageEngine.java:67)
at voldemort.store.DelegatingStore.getVersions(DelegatingStore.java:86)
at voldemort.store.DelegatingStore.getVersions(DelegatingStore.java:86)
at voldemort.server.protocol.vold.VoldemortNativeRequestHandler.handleGetVersion(VoldemortNativeRequestHandler.java:89)
at voldemort.server.protocol.vold.VoldemortNativeRequestHandler.handleRequest(VoldemortNativeRequestHandler.java:74)
at voldemort.server.niosocket.AsyncRequestHandler.read(AsyncRequestHandler.java:170)
at voldemort.server.niosocket.AsyncRequestHandler.run(AsyncRequestHandler.java:98)
at voldemort.server.niosocket.SelectorManager.run(SelectorManager.java:143)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:619)
  • 1. Re: CMS not yielding to java.util.zip???
    843829 Newbie
    Currently Being Moderated
    See http://blogs.oracle.com/charlesLamb/2006/09/adler32_vs_the_gc.html for a explanation of the base problem.

    See http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6919638 for how the problem was greatly exacerbated by the -XX:+ExplicitGCInvokesConcurrent flag causing CMS to run its (slow) concurrent collection while silently keeping JNI blocked for the duration.