X

Recent Posts

Poonam Parhar

Can young generation size impact the application response times?

I was recently involved in a performance issue where the application's response times were decreasing over time, and I was tasked to determine if GC was playing any role in that. Well, as we all know that misconfiguration of the java heap space and its generations can lead to unexpected/frequent/longer garbage collection cycles causing inferior performance and longer response times of the application, and that indeed was the cause of this performance issue. I want to share some details of this issue, how it was resolved, and also want to emphasize on the importance of proper configuration of the memory pools that are managed by the garbage collector in the JVM. For this case, the first thing to look at, of course, were GC logs. The application was configured to run with the CMS and ParNew collectors. The GC logs revealed the following: There were too frequent ParNew collections. This indicated that the young generation was sized smaller than the allocation rate of the application. Pause times of ParNew collections were increasing over time. This meant that the time taken to promote young objects from the Young generation to the CMS generation was increasing over time. There were ‘ParNew promotion’ and ‘CMS concurrent mode’ failures. Here’s a log entry pertaining to one of the concurrent mode failures: [GC: [ParNew (promotion failed): 528684K->529315K(613440K), 0.0234550 secs] [CMS: [CMS-concurrent-sweep: 2.807/3.322 secs] [Times: user=5.09 sys=0.15, real=3.32 secs]  (concurrent mode failure): 4425412K->3488043K(7707072K), 10.4466460 secs] 4954097K->3488043K(8320512K), [CMS Perm : 389189K->388749K(653084K)] , 10.4703900 secs] [Times: user=10.61 sys=0.00, real=10.46 secs] The interesting thing to notice here is that there is plenty of room available (~ 3GB) in the CMS generation yet the promotion of around 500MB (at the most) of young objects had failed. This indicated that there was severe fragmentation in the CMS space. To confirm that the application was suffering from fragmentation in the CMS generation, we collected GC logs with the -XX:PrintFLSStatistics=1 JVM option. FLS statistics showed that the Maximum and the average chunk sizes of the binary tree dictionaries in the CMS space were decreasing over time, indicating that the fragmentation was increasing. All the above three observations helped us conclude that the young space was sized smaller than the application’s actual requirement, and the CMS space was suffering from acute fragmentation. The application was tested with increased young generation sizes. Please note that the JVM options -XX:NewSize=n and -XX:MaxNewSize=m, or -XX:NewRatio=p can be used to configure the young generation size. Increasing the young gen size helped address all the above points: It helped in reducing the ParNew collections frequency It helped in reducing premature promotions of objects into the old gen, and that helped combat CMS fragmentation With reduced fragmentation, the rising ParNew GC times also became stable. This case and the involved exercise showed us again how important it is to size the JVM memory pools in accordance with our application’s requirements. More later!

I was recently involved in a performance issue where the application's response times were decreasing over time, and I was tasked to determine if GC was playing any role in that. Well, as we all know...

Clarifying some confusion around Java Flight Recordings

In this blog, I am going to talk about two confusions around Java Flight Recordings that I have come across from multiple users/customers. Let's take a look at them one by one. Flight Recordings Interval A number of Java Flight Recorder users seem to have a confusion around the 'start-time' and the 'interval' of the flight recordings. The complaint is that the flight recordings in the Java Mission Control show longer recording interval than their actual recorded data. For example, the following screenshot shows that the flight recording has the interval of 5 hours and 35 minutes but the actual recording data in it is only for 59 minutes. This might seem like a bug, and you might question as to why the flight recording is having timeline with no obvious recorded events in it. Well, this isn’t a bug. If we go to the Events->Log tab and sort the events with their ‘Start Time’, we can see an Event ‘Java Thread Park’ that had started at 1:37:28 PM. This event had started before the actual start-time of the recording. The JMC chose to include this event, and to accommodate this event it ended up showing interval of the recording which is much longer than the actual duration of the recording.  So, whenever we see part of the recording timeline not having any data in it, it is worth checking the events log to see if there are any events that had started before we had actually started that flight recording. JFR Repository and Destination Another confusion I often hear is around the use of the JFR Repository and the destination for recordings. One such question: “I have configured maxsize for my recordings but the recordings I see created in my JFR repository are much smaller than my specified maxsize. Why is that so?” Well, JFR repository is not the destination folder for the recordings. JFR repository is used internally by the Flight Recorder to store chunks of JFR data when the thread/global JFR buffers are flushed out to the disk. ‘maxage’ and ‘maxsize’ settings are honored for the collective size of chunk files that are kept in the Repository folder and the individual chunk files can be smaller than the specified maximum 'maxsize' i.e. the total size of all the chunks created in the repository folder should not go beyond the limit set with the ‘maxsize’ option. The older chunk files exceeding the maxsize/maxage limit are deleted by the Flight Recorder. Let’s consider this example, where I start a java process with the FlightRecorder enabled, and then start a flight recording in it with ‘maxsize’ limit as 2mb. D:\tests>jcmd 30824 JFR.start name=recording1 maxsize=2mb 30824: Started recording 1. Use JFR.dump name=recording1 filename=FILEPATH to copy recording data to file. D:\tests>jcmd 30824 JFR.check 30824: Recording: recording=1 name="recording1" maxsize=2.0MB (running) Now, every time I dump the running recording, it is written to the disk either in the specified destination folder or in the current working folder if ‘destination’ is not specified. D:\tests>jcmd 30824 JFR.dump recording=1 filename=1.jfr 30824: Dumped recording 1, 1.8 MB written to: D:\tests\1.jfr D:\tests>jcmd 30824 JFR.dump recording=1 filename=1.jfr 30824: Dumped recording 1, 2.0 MB written to: D:\tests\1.jfr And each time the recording is dumped, before it is written to the destination folder, data in the JFR buffers is flushed out in the form of chunk files to the JFR repository. At this point, the Flight Recorder checks for the limits configured for the recording (maxsize in this case) and removes the older chunk files to ensure that the specified limits are honored. For example, in this case, every time a new chunk file is written into the repository, the Flight Recorder deletes old chunk files to ensure that the total size of all the files in the repository does not exceed 2MB.   Now, when I dump again, the older files in the repository are removed to keep the total size of all the chunk files up to 2mb as shown in the following image. D:\tests>jcmd 30824 JFR.dump recording=1 filename=1.jfr 30824: Dumped recording 1, 2.0 MB written to: D:\tests\1.jfr   That's all for this post!  

In this blog, I am going to talk about two confusions around Java Flight Recordings that I have come across from multiple users/customers. Let's take a look at them one by one. Flight Recordings...

How do I find what's getting promoted to my old generation?

This question comes up every now and then that how can I find what the minor/young collections are promoting to the old generation of my Java application. Recently, there was a case where the customer wanted to know the types of objects getting promoted to the old generation at different input loads for their application. Well, one longer and a little bit tedious way is to use -XX:+TraceScavenge option. This is a non-product JVM option and hence you would need to build a debug version of the HotSpot JVM to be able to use this option. The output generated by this option is too verbose as it logs each and every object being processed by the young generation collections. There is another way - it is possible to extract this information from the heap dumps. Heap dumps collected after minor collection(s) paired with the heap boundaries information collected with –XX:+PrintHeapAtGC option can help us find the objects piling up in the old generation. Let’s see how we can achieve that with the help of a simple example. I ran a small Java program with the following options: java -Xmx100m -XX:NewSize=10m -XX:+PrintGCDetails -XX:+HeapDumpBeforeFullGC -XX:+PrintHeapAtGC MemoryEater After 4 young generation collections, the old generation became full and a Full GC was invoked. At this point a Heap Dump was generated. Let’s analyze this heap dump to find out what got promoted to the old generation with minor GC #4. The GC logs show the following heap usage details before and after GC #4: {Heap before GC invocations=4 (full 0):  PSYoungGen      total 17408K, used 17392K [0x00000000fdf00000, 0x0000000100000000, 0x0000000100000000)   eden space 16384K, 100% used [0x00000000fdf00000,0x00000000fef00000,0x00000000fef00000)   from space 1024K, 98% used [0x00000000fef00000,0x00000000feffc010,0x00000000ff000000)   to   space 1024K, 0% used [0x00000000fff00000,0x00000000fff00000,0x0000000100000000)  ParOldGen       total 68608K, used 34096K [0x00000000f9c00000, 0x00000000fdf00000, 0x00000000fdf00000)   object space 68608K, 49% used [0x00000000f9c00000,0x00000000fbd4c000,0x00000000fdf00000)  Metaspace       used 2612K, capacity 4486K, committed 4864K, reserved 1056768K   class space    used 285K, capacity 386K, committed 512K, reserved 1048576K [GC (Allocation Failure) [PSYoungGen: 17392K->1024K(32768K)] 51488K->52816K(101376K), 0.0101398 secs] [Times: user=0.00 sys=0.00, real=0.00 Heap after GC invocations=4 (full 0):  PSYoungGen      total 32768K, used 1024K [0x00000000fdf00000, 0x0000000100000000, 0x0000000100000000)   eden space 31744K, 0% used [0x00000000fdf00000,0x00000000fdf00000,0x00000000ffe00000)   from space 1024K, 100% used [0x00000000fff00000,0x0000000100000000,0x0000000100000000)   to   space 1024K, 0% used [0x00000000ffe00000,0x00000000ffe00000,0x00000000fff00000)  ParOldGen       total 68608K, used 51792K [0x00000000f9c00000, 0x00000000fdf00000, 0x00000000fdf00000)   object space 68608K, 75% used [0x00000000f9c00000,0x00000000fce94050,0x00000000fdf00000)  Metaspace       used 2612K, capacity 4486K, committed 4864K, reserved 1056768K   class space    used 285K, capacity 386K, committed 512K, reserved 1048576K } Heap Dump (before full gc): Dumping heap to java_pid31684.hprof ... Please note the changes in the ‘object space’ usage for the ParOldGen. Now let’s open the heap dump java_pid31684.hprof in Eclipse MAT. But before we do that we want to make sure that MAT is configured to ‘Keep unreachable objects’ when it loads the heap dump. This would make sure that the objects that might have become unreachable now but are present in the Java Heap are also accounted and shown by the tool. Go to Window->Preferences->Memory Analyzer to enable this configuration setting. After we open the heap dump in MAT, take a look at the heap histogram. The histogram shows that byte[] are the objects that occupy the maximum amount of space in the Java Heap, but that does not tell anything about the generation where the significant number of these byte[] reside. From the GC log above, we can see that the old generation's start address was 0x00000000f9c00000. Before the minor GC #4, the old generation was used up to the address 0x00000000fbd4c000, and after the GC the old generation grep up to 0x00000000fce94050. This means that the objects promoted with GC #4 were copied in the address range 0x00000000fbd4c000 to 0x00000000fce94050. We can use a query like the following to see the objects present in the old generation in the address range 0x00000000fbd4c000 to 0x00000000fce94050. SELECT * FROM INSTANCEOF java.lang.Object t WHERE (toHex(t.@objectAddress) >= "0xfbd4c000" AND toHex(t.@objectAddress) <= "0xfce94050") We can also add a filter and see how many instances of a specific type got promoted. For example, adding a filter for byte[] shows that 15,407 instances of byte[] were promoted with minor GC #4 Following these simple steps, we can get a fair idea as to what is filling up our old generation, and whether we need to tune the young generation size or the survivor spaces to avoid or minimize those promotions.  

This question comes up every now and then that how can I find what the minor/young collections are promoting to the old generation of my Java application. Recently, there was a case where the customer...

HotSpot JVM throwing OOM even when there is memory available

I was recently asked a question that why my Java application runs out of Java Heap when there is still so much memory available to use? Here is the question in detail - I am running my application with -Xmx1600m but the logs show that it runs out of memory without fully using the 1600mb. 2017-03-21T13:15:39.478+0000: 289274.599: [Full GC [PSYoungGen: 338944K->0K(425472K)] [ParOldGen: 1092073K->1055276K(1092096K)] 1431017K->1055276K(1517568K) [PSPermGen: 493920K->493889K(494592K)], 1.1709840 secs] [Times: user=5.06 sys=0.00, real=1.18 secs] ... 2017-03-21T13:19:50.517+0000: 289525.638: [Full GC [PSYoungGen: 322035K->0K(364544K)] [ParOldGen: 1092088K->1091814K(1092096K)] 1414124K->1091814K(1456640K) [PSPermGen: 494764K->494163K(495104K)], 2.5423990 secs] [Times: user=15.30 sys=0.00, real=2.54 secs] The maximum capacity of the heap sometimes goes up to 1517568K and sometimes stays at 1456640K. Why does it not use the whole 1600mb? Well, the short answer is that the rest of the unaccounted space is for one of the survivor spaces. Long answer: Young generation is composed of Eden and 2 survivor spaces - From and To. Out of these only 'Eden' and 'From' space are available for allocations. 'To' is kept free to be used for copying surviving objects and is omitted while reporting the Young generation capacity. Let's take a look at another example where I run a simple program that allocates extensively and runs out of the Java Heap. I run that program with the following options: java -XX:+PrintGCDetails -Xmx60m -XX:MaxNewSize=20m TestProgram ...<snip>... [Full GC (Ergonomics) [PSYoungGen: 15360K->15360K(17920K)] [ParOldGen: 40464K->40464K(40960K)] 55824K->55824K(58880K), [Metaspace: 2723K->2723K(1056768K)], 0.1519409 secs] [Times: user=0.50 sys=0.00, real=0.15 secs] [Full GC (Ergonomics) [PSYoungGen: 15360K->15360K(17920K)] [ParOldGen: 40465K->40465K(40960K)] 55825K->55825K(58880K), [Metaspace: 2723K->2723K(1056768K)], 0.1196922 secs] [Times: user=0.41 sys=0.00, real=0.12 secs] Exception in thread "main" java.lang.OutOfMemoryError: GC overhead limit exceeded         at TestProgram.main(TestProgram.java:15)[Full GC (Ergonomics) [PSYoungGen: 15360K->0K(17920K)] [ParOldGen: 40468K->324K(30720K)] 55828K->324K(48640K), [Metaspace: 2748K->2748K(1056768K)], 0.0072977 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] I had the heap size configured at 60MB but the total capacity of the Java heap from the above logs is only 58880K. YoungGen:17920K + OldGen:40960K = Total:58880K. Where is 60*1024K-58880K = 2560K? Now, if we look at the heap usage details: Heap PSYoungGen      total 17920K, used 307K [0x00000000fec00000, 0x0000000100000000, 0x0000000100000000)   eden space 15360K, 2% used [0x00000000fec00000,0x00000000fec4ce70,0x00000000ffb00000)   from space 2560K, 0% used [0x00000000ffb00000,0x00000000ffb00000,0x00000000ffd80000)   to   space 2560K, 0% used [0x00000000ffd80000,0x00000000ffd80000,0x0000000100000000) ParOldGen       total 30720K, used 324K [0x00000000fc400000, 0x00000000fe200000, 0x00000000fec00000)   object space 30720K, 1% used [0x00000000fc400000,0x00000000fc4511e0,0x00000000fe200000) Metaspace       used 2755K, capacity 4486K, committed 4864K, reserved 1056768K   class space    used 301K, capacity 386K, committed 512K, reserved 1048576K  Capacity of PSYoungGen:17920K = eden:15360K + from:2560K It does not include the 'To' survivor space.

I was recently asked a question that why my Java application runs out of Java Heap when there is still so much memory available to use? Here is the question in detail - I am running my application with...

WeakReferences and GC

I was recently working on a memory growth issue involving WeakReferences, and I came across this great blog post on how non-strong references can affect the heap usage and the garbage collection: https://plumbr.eu/blog/garbage-collection/weak-soft-and-phantom-references-impact-on-gc It has a demo application that demonstrates an increase in the number of objects getting promoted from young to old generation when WeakReferences are used. That made me deeply interested in investigating the cause of increase in the promotion rate with WeakReferences. WeakReferences are defined as: Weak reference objects, which do not prevent their referents from being made finalizable, finalized, and then reclaimed. Weak references are most often used to implement canonicalizing mappings. Suppose that the garbage collector determines at a certain point in time that an object is weakly reachable. At that time it will atomically clear all weak references to that object and all weak references to any other weakly-reachable objects from which that object is reachable through a chain of strong and soft references. At the same time it will declare all of the formerly weakly-reachable objects to be finalizable. At the same time or at some later time it will enqueue those newly-cleared weak references that are registered with reference queues. I turned to the HotSpot sources to understand how the garbage collector in HotSpot deals with the non-strong references. In simple steps, this is how young garbage collection works and processes the non-strong references. - scavenge (copy objects from Eden to Survivor or Tenured space)         - allocate memory in the destination (say new_object) for the object either in the survivor space or in the tenured gen depending upon its age     - visit new_object         - if it is a reference object and its referent is not yet known to be reachable then discover it i.e. add it to its respective - soft, weak or phantom - discovered list (note that soft refs are determined to be discover-able differently than weak refs that itself makes a topic for a separate post) - process the discovered refs lists prepared during scavenge     - remove the references from the discovered lists whose referents are still strongly reachable     - otherwise clear its referent - enqueue the discovered refs Following are comments from the HotSpot sources which I think are worth mentioning here. These comments describe the two policies that the HotSpot can use for discovering Reference objects. HotSpot by default uses ReferenceBasedDiscovery policy. The other policy RefeferentBasedDiscovery is experimental and is not well tested. // We mention two of several possible choices here // #0: if the reference object is not in the "originating generation" //     (or part of the heap being collected, indicated by our "span" //     we don't treat it specially (i.e. we scan it as we would //     a normal oop, treating its references as strong references). //     This means that references can't be discovered unless their //     referent is also in the same span. This is the simplest, //     most "local" and most conservative approach, albeit one //     that may cause weak references to be enqueued least promptly. //     We call this choice the "ReferenceBasedDiscovery" policy. // #1: the reference object may be in any generation (span), but if //     the referent is in the generation (span) being currently collected //     then we can discover the reference object, provided //     the object has not already been discovered by //     a different concurrently running collector (as may be the //     case, for instance, if the reference object is in CMS and //     the referent in DefNewGeneration), and provided the processing //     of this reference object by the current collector will //     appear atomic to every other collector in the system. //     (Thus, for instance, a concurrent collector may not //     discover references in other generations even if the //     referent is in its own generation). This policy may, //     in certain cases, enqueue references somewhat sooner than //     might Policy #0 above, but at marginally increased cost //     and complexity in processing these references. //     We call this choice the "RefeferentBasedDiscovery" policy. bool ReferenceProcessor::discover_reference(oop obj, ReferenceType rt) { To see things in action, I modified the WeakReferences test program a bit to store objects of class MyObject in the refs[] array so as to be able to identify them easily in the heap dumps. The modified test looks like the following:   public class WeakReferencesPromotion {     private static final int BUFFER_SIZE = 65536;     public static volatile MyObject strongRef;     public static void main(String[] args) throws InterruptedException {         final Object[] refs = new Object[BUFFER_SIZE];         for (int index = 0;;) {             MyObject object = MyObject.createMyObject();                          // hold a strong reference to this newly created object               strongRef = object;                // In the next iteration, at this point, this 'object' will only be reachable through             // the WeakReference instance at refs[index]                          // create WeakReference instace holding 'object' as its referent             // WeakReference instance itself is atrongly reachable through refs[]             refs[index++] = new WeakReference<>(object);                                                     if (index == BUFFER_SIZE) {                 // make the WeakReference objects in the array unreachable                 Arrays.fill(refs, null);                   index = 0;             }         }     }     } class MyObject {   byte[] bytes;     public static MyObject createMyObject() {     MyObject obj = new MyObject();     obj.bytes = new byte[190];     return obj;   } } In the above test program, if a GC (say GC1) occurs when the java thread is at the following statement: MyObject object = MyObject.createMyObject(); at this point, MyObject (say obj1) created in the previous iteration of the 'for' loop is still strongly reachable through 'strongRef'. That MyObject instance (obj1) would become only weakly reachable after 'strongRef' is reassigned with the following: strongRef = object; So GC1 would see obj1 as strongly reachable but the next GC (say GC2) should see obj1 as reachable only through a weak reference. Now, to find which objects get promoted and why, I ran this program with -XX:+TraceReferenceGC -XX:+TraceScavenge options, collected the heap dumps before Full GC to inspect the objects promoted to the old gen. Please note that -XX:+TraceReferenceGC -XX:+TraceScavenge JVM options are available only in the debug/fastdebug build of the JVM. You can build it yourself from the OpenJDK sources.   java -XX:+HeapDumpBeforeFullGC -Xmx25m -XX:MaxTenuringThreshold=1 -XX:+PrintGCDetails -XX:+TraceReferenceGC -XX:+TraceScavenge WeakReferencesPromotion.java Note that -XX:MaxTenuringThreshold is set to 1 which means that the objects surviving second GC would get promoted to the tenured gen. From the heap dumps, I could see that the instances of WeakReference and MyObject were among the top growers in the heap: -------------------------------------------------------------------- Class Name                 | Objects | Shallow Heap | Retained Heap -------------------------------------------------------------------- java.lang.ref.WeakReference| 473,677 |   15,157,664 |               byte[]                     |   9,484 |    1,995,992 |               int[]                      |   2,220 |      542,280 |               java.lang.Object[]         |     511 |      287,536 |               MyObject                   |   9,477 |      151,632 |               -------------------------------------------------------------------- Looking at some of the MyObject instances: Class Name                                                      | Shallow Heap | Retained Heap ----------------------------------------------------------------------------------------------- MyObject @ 0xff627da0                                           |           16 |           224 '- referent java.lang.ref.WeakReference @ 0xff627d80 Unreachable|           32 |           256 MyObject @ 0xff5772e0                                           |           16 |           224 '- referent java.lang.ref.WeakReference @ 0xff575a00 Unreachable|           32 |           256 MyObject @ 0xff4ebce0                                           |           16 |           224 '- referent java.lang.ref.WeakReference @ 0xff4ef060 Unreachable|           32 |           256 MyObject @ 0xff43c120                                           |           16 |           224 '- referent java.lang.ref.WeakReference @ 0xff43c100 Unreachable|           32 |           256 MyObject @ 0xff3c1000                                           |           16 |           224 '- referent java.lang.ref.WeakReference @ 0xff3bf180 Unreachable|           32 |           256 MyObject @ 0xff30e960                                           |           16 |           224 '- referent java.lang.ref.WeakReference @ 0xff30b9a0 Unreachable|           32 |           256 MyObject @ 0xff2a1cc0                                           |           16 |           224 '- referent java.lang.ref.WeakReference @ 0xff2a1ca0 Unreachable|           32 |           256 ----------------------------------------------------------------------------------------------- From the GC logs, the address ranges of the young and the old generations are:  PSYoungGen      total 6144K, used 4064K [0x00000000ff780000, 0x0000000100000000, 0x0000000100000000)   eden space 3584K, 100% used [0x00000000ff780000,0x00000000ffb00000,0x00000000ffb00000)   from space 2560K, 18% used [0x00000000ffd80000,0x00000000ffdf8000,0x0000000100000000)   to   space 2560K, 0% used [0x00000000ffb00000,0x00000000ffb00000,0x00000000ffd80000)  ParOldGen       total 17920K, used 7208K [0x00000000fe600000, 0x00000000ff780000, 0x00000000ff780000) From these address ranges, we can see that the above sample set of WeakReferences and their referents lie in the tenured gen, and they are unreachable. Looking at the first sample, and searching for the MyObject instance at address 0xff627da0 in the gc logs shows: D:\tests\GC_WeakReferences> grep ff627da0 gc.1.log {tenuring MyObject 0x00000000ffdba600 -> 0x00000000ff627da0 (2)} {forwarding MyObject 0x00000000ffdba600 -> 0x00000000ff627da0 (2)} This means that MyObject instance (0x00000000ffdba600) was in one of the survivor spaces and was tenured to the address 0x00000000fe600420 in the old gen. Searching for ffdba600 in the logs gets us: {copying MyObject 0x00000000ffcffe40 -> 0x00000000ffdba600 (2)} {forwarding MyObject 0x00000000ffcffe40 -> 0x00000000ffdba600 (2)} This means that this MyObject instance was in Eden at address 0x00000000ffcffe40, it survived and was copied to the survivor space at address 0x00000000ffdba600. To put things in context, I extracted all the log entries containing WeakReference instance at 0xff627d80 and MyObject instance at 0xffdba600 from the gc logs: //GC #11 Discovered reference (mt) (0x00000000ffd08000: java.lang.ref.WeakReference) ... {copying java.lang.ref.WeakReference 0x00000000ffcfff20 -> 0x00000000ffd08000 (4)}  //copy reference object from eden to a survivor space    Process discovered as normal 0x00000000ff4f63b8 {forwarding java.lang.ref.WeakReference 0x00000000ffcfff20 -> 0x00000000ffd08000 (4)} ... Dropping strongly reachable reference (0x00000000ffd08000: java.lang.ref.WeakReference) //Dropped from discovered list because its referent is strongly reachable at the moment. {copying MyObject 0x00000000ffcffe40 -> 0x00000000ffdba600 (2)} {forwarding MyObject 0x00000000ffcffe40 -> 0x00000000ffdba600 (2)}  Dropped 1 active Refs out of 5630 Refs in discovered list 0x00000000ffd5c040 ..... //GC #12 {tenuring java.lang.ref.WeakReference 0x00000000ffd08000 -> 0x00000000ff627d80 (4)} //Weak reference gets promoted and does not get discovered in this scavenge because it does not lie in the young generation now. ... {forwarding java.lang.ref.WeakReference 0x00000000ffd08000 -> 0x00000000ff627d80 (4)} ... {tenuring MyObject 0x00000000ffdba600 -> 0x00000000ff627da0 (2)}  // its referent object gets promoted too {forwarding MyObject 0x00000000ffdba600 -> 0x00000000ff627da0 (2)} I added comments besides the log entries above to explain what is happening with each log entry. Here's the complete story: During the scavenge process, GC #11 finds the weak reference (0x00000000ffcfff20) strongly reachable and copies that and its referent to the survivor space, and adds the weak reference to the discovered references list. But this weak reference gets removed from the discovered references list when GC finds its referent still being strongly reachable during the references-processing phase. The next GC, GC #12 finds that weak reference still strongly reachable (through ref[]) and copies that and its referent to the tenured space during the scavenge phase. At this point, the referent is not strongly reachable and one would expect it to get collected. But since the weak reference had been moved to the tenured gen, with the ReferenceBasedDiscovery discovery policy, the garbage collector does not discover it i.e. does not add it to the discovered references list and does not treat it like a reference object. The weak reference is treated like a normal reachable object and its referent too gets copied over to the tenured generation. If we increase the tenuring threshold from 1 to 2, the weak references like in the above example would get collected in the young generation itself. The second GC would copy the weak reference object to the survivor space and that would allow the weak reference to get discovered during the scavenge phase. The reference processing phase of this GC would then clear the referent and would enqueue the reference object. Final Thoughts Weak references and their referents can get prematurely promoted to the old generation. By increasing -XX:MaxTenuringThreshold to a sufficiently large number, we can avoid this premature promotion.  

I was recently working on a memory growth issue involving WeakReferences, and I came across this great blog post on how non-strong references can affect the heap usage and the garbage collection:https:...

Hung JVM due to the threads stuck in pthread_cond_timedwait()

In this post, I am going to discuss a couple of scenarios where the Java process hangs are actually NOT because of a Java/JVM issue but happen due to the OS problems. Both the hangs being discussed here occur on the Linux operating system. Lets take a look at the first case where a thread seems to be stuck in the Java Thread.sleep() call. From the process stack trace, the two threads of interest are: Thread 26755: (state = IN_VM)  - java.lang.Thread.interrupt0() @bci=0 (Interpreted frame)  - java.lang.Thread.interrupt() @bci=51, line=852 (Interpreted frame)  - oracle.core.ojdl.BufferedLogWriter.stopFlusher() @bci=17, line=380 (Interpreted frame) Thread 21714: (state = BLOCKED)  - java.lang.Thread.sleep(long) @bci=0 (Interpreted frame)  - oracle.core.ojdl.BufferedLogWriter$Flusher.run() @bci=30, line=401 (Interpreted frame) Thread 26755 is attempting to interrupt thread 21714 which is executing Thread.sleep(). Thread 21714 stays in the BLOCKED state preventing other threads in the process from making any progress, and thus causing the process to hang. Looking at their native stack traces: Thread 26755: #0  0xf77e7430 in __kernel_vsyscall () #1  0x4dcc31b9 in __lll_lock_wait () from /lib/libpthread.so.0 #2  0x4dcbe550 in _L_lock_677 () from /lib/libpthread.so.0 #3  0x4dcbe421 in pthread_mutex_lock () from /lib/libpthread.so.0 #4  0x064ff034 in os::Linux::Event::unpark() () #5  0x064fc60a in os::interrupt(Thread*) () Thread 21714: #0  0xf77e7430 in __kernel_vsyscall () #1  0x4dc0fc43 in __lll_lock_wait_private () from /lib/libc.so.6 #2  0x4db94348 in _L_lock_9835 () from /lib/libc.so.6 #3  0x4db91f27 in calloc () from /lib/libc.so.6 #4  0x4dcc0e1c in pthread_cond_timedwait@GLIBC_2.0 () from /lib/libpthread.so.0 #5  0x064fefa1 in os::Linux::Event::timedwait(timespec*) () #6  0x064fc2bf in os::sleep(Thread*, long long, bool) () #7  0x063d5d90 in JVM_Sleep () You might be wondering as to what was the value of time duration passed to pthread_cond_timedwait() function. It was 5 secs, and so after 5 seconds pthread_cond_timedwait() should have come out of its wait. pthread_cond_timedwait() accepts 'pthread_cond_t* cond' and 'pthread_mutex_t* mutex' arguments that it uses to coordinate with the other threads (https://linux.die.net/man/3/pthread_cond_timedwait). Take a look at the cond and the mutex arguments: (gdb) print *((pthread_cond_t*)0xad533ff0) $3 = {__c_lock = {__status = 0, __spinlock = 17}, __c_waiting = 0xad534050}(gdb) print *((pthread_mutex_t*)0xad533fd8) $4 = {__m_reserved = 2, __m_count = 0, __m_owner = 0x54d2, __m_kind = 0, __m_lock = {__status = 1, __spinlock = 0}} __m_owner = 0x54d2 = 21714 (gdb) print *$11->_osthread->_interrupt_event $14 = {<CHeapObj> = {<No data fields>}, _count = 0, _nParked = 1, cachePad = {-2.3622328335110874e-90, 4.2439915835115547e-313,     1.4480588116526359e-314, 4.2439915866735748e-313}, _mutex = {{__m_reserved = 2, __m_count = 0, __m_owner = 0x54d2, __m_kind = 0, __m_lock = {         __status = 1, __spinlock = 0}}}, _cond = {{__c_lock = {__status = 0, __spinlock = 17}, __c_waiting = 0xad534050}}, FreeNext = 0xbad, Immortal = 1} From the above data, we can see that the sleeping thread owns the _mutex, and the interrupting thread is waiting to acquire that _mutex to signal the sleeping thread. If we look closely, the sleeping thread is actually waiting on a native heap lock to complete some allocation (in calloc) before it could release the _mutex. So it turned out not to be a JVM issue but some problem with the lock synchronization at the linux kernel level, causing the thread to be stuck in pthread_cond_timedwait() for infinite amount of time.Let's take look at another case where there were three threads stuck in __pthread_cond_timedwait(), stopping the progress of other threads in the process. ----------------- 11374 ----------------- 0x00000032f1c0ba0e      __pthread_cond_timedwait + 0x13e 0x00007fb1453bbf94      _ZN13ObjectMonitor4waitElbP6Thread + 0x224 0x00007fb1454a0d83      _ZN18ObjectSynchronizer4waitE6HandlelP6Thread + 0x53 0x00007fb14520b34b      JVM_MonitorWait + 0x1fb 0x00007fb13d010eee      * java.lang.Object.wait(long) bci:0 (Interpreted frame) 0x00007fb13d005a82      * java.lang.Thread.join(long) bci:70 line:1214 (Interpreted frame) 0x00007fb13d005a82      * iasauto.execution.GetCfgRunDTE.execute() bci:864 line:504 (Interpreted frame) 0x00007fb13d005a82      * iasauto.execution.RunOneJob.execute() bci:1675 line:1521 (Interpreted frame) 0x00007fb13d005a82      * iasauto.execution.RunOneJob.main(java.lang.String[]) bci:18 line:58 (Interpreted frame) 0x00007fb13d000438      <StubRoutines> 0x00007fb14519e8d0      _ZN9JavaCalls11call_helperEP9JavaValueP12methodHandleP17JavaCallArgumentsP6Thread + 0x1e0 0x00007fb1453ca829      _ZN2os20os_exception_wrapperEPFvP9JavaValueP12methodHandleP17JavaCallArgumentsP6ThreadES1_S3_S5_S7_ + 0x19 0x00007fb14519e6e5      _ZN9JavaCalls4callEP9JavaValue12methodHandleP17JavaCallArgumentsP6Thread + 0x25 0x00007fb1451d99f7      _Z17jni_invoke_staticP7JNIEnv_P9JavaValueP8_jobject11JNICallTypeP10_jmethodIDP18JNI_ArgumentPusherP6Thread + 0x147 0x00007fb1451c753f      jni_CallStaticVoidMethod + 0x20f 0x0000000040002284      JavaMain + 0x2a4 ----------------- 31490 ----------------- 0x00000032f1c0ba0e      __pthread_cond_timedwait + 0x13e 0x00007fb1453bbf94      _ZN13ObjectMonitor4waitElbP6Thread + 0x224 0x00007fb1454a0d83      _ZN18ObjectSynchronizer4waitE6HandlelP6Thread + 0x53 0x00007fb14520b34b      JVM_MonitorWait + 0x1fb 0x00007fb13d010eee      * java.lang.Object.wait(long) bci:0 (Interpreted frame) 0x00007fb13d005a82      * java.lang.Thread.join(long) bci:70 line:1214 (Interpreted frame) 0x00007fb13d005a82      * iasauto.engine.LocalTaskProcess.execute() bci:70 line:206 (Interpreted frame) 0x00007fb13d005a82      * iasauto.engine.TaskProcess.executeLocal(boolean) bci:277 line:751 (Interpreted frame) 0x00007fb13d005a82      * iasauto.engine.TaskProcess.run() bci:631 line:289 (Interpreted frame) 0x00007fb13d005f5c      * java.lang.Thread.run() bci:11 line:682 (Interpreted frame) 0x00007fb13d000438      <StubRoutines> 0x00007fb14519e8d0      _ZN9JavaCalls11call_helperEP9JavaValueP12methodHandleP17JavaCallArgumentsP6Thread + 0x1e0 0x00007fb1453ca829      _ZN2os20os_exception_wrapperEPFvP9JavaValueP12methodHandleP17JavaCallArgumentsP6ThreadES1_S3_S5_S7_ + 0x19 0x00007fb14519e246      _ZN9JavaCalls12call_virtualEP9JavaValue11KlassHandle12symbolHandleS3_P17JavaCallArgumentsP6Thread + 0x116 0x00007fb14519e2c7      _ZN9JavaCalls12call_virtualEP9JavaValue6Handle11KlassHandle12symbolHandleS4_P6Thread + 0x47 0x00007fb145230c12      _Z12thread_entryP10JavaThreadP6Thread + 0xa2 0x00007fb1454d3401      _ZN10JavaThread3runEv + 0x121 ----------------- 11681 ----------------- 0x00000032f1c0ba0e      __pthread_cond_timedwait + 0x13e 0x00007fb1453bbf94      _ZN13ObjectMonitor4waitElbP6Thread + 0x224 0x00007fb1454a0d83      _ZN18ObjectSynchronizer4waitE6HandlelP6Thread + 0x53 0x00007fb14520b34b      JVM_MonitorWait + 0x1fb 0x00007fb13d010eee      * java.lang.Object.wait(long) bci:0 (Interpreted frame) 0x00007fb13d005a82      * java.util.TimerThread.mainLoop() bci:201 line:509 (Interpreted frame) 0x00007fb13d005a82      * java.util.TimerThread.run() bci:1 line:462 (Interpreted frame) 0x00007fb13d000438      <StubRoutines> 0x00007fb14519e8d0      _ZN9JavaCalls11call_helperEP9JavaValueP12methodHandleP17JavaCallArgumentsP6Thread + 0x1e0 0x00007fb1453ca829      _ZN2os20os_exception_wrapperEPFvP9JavaValueP12methodHandleP17JavaCallArgumentsP6ThreadES1_S3_S5_S7_ + 0x19 0x00007fb14519e246      _ZN9JavaCalls12call_virtualEP9JavaValue11KlassHandle12symbolHandleS3_P17JavaCallArgumentsP6Thread + 0x116 0x00007fb14519e2c7      _ZN9JavaCalls12call_virtualEP9JavaValue6Handle11KlassHandle12symbolHandleS4_P6Thread + 0x47 0x00007fb145230c12      _Z12thread_entryP10JavaThreadP6Thread + 0xa2 0x00007fb1454d3401      _ZN10JavaThread3runEv + 0x121 0x00007fb1453cbcdf      _Z10java_startP6Thread + 0x13f From the investigations so far, we believe it to be a Linux Kernel issue, probably related to the fix done by the following commit.https://github.com/torvalds/linux/commit/76835b0ebf8a7fe85beb03c75121419a7dec52f0To summarize, even when on the surface the Java process hangs look to be Java/JVM issues, they may not be. We should be looking closely at the native stack traces of the threads to understand what is really holding them up, and where they are stuck.

In this post, I am going to discuss a couple of scenarios where the Java process hangs are actually NOT because of a Java/JVM issue but happen due to the OS problems. Both the hangs being...

G1 and Flight Recorder's -XX:FlightRecorderOptions=stackdepth option

Recently there was a report from a customer that they observed performance degradation while using JFR with G1 when they used it along with -XX:FlightRecorderOptions=stackdepth=512, but didn't see any performance impact when using the same setting for the stackdepth with the Parallel Collector. The flight recordings revealed that the poor performance was due to the long pauses introduced by the JFRCheckpoint operations. The long JFRCheckpoints occurred only for the recordings started with -XX:FlightRecorderOptions=stackdepth=512. When tested with -XX:FlightRecorderOptions=stackdepth=3, there were no long pause JFRCheckpoint operations.Lets look at the possible reasons for that. The time taken by the JFRCheckpoint operations is directly proportional to the amount of data that needs to be written to the disk. In G1, TLAB size is smaller, so in effect it generates more number of 'Allocation in TLAB' and 'Allocation outside TLAB' events. And if we increase the stack depth using 'stackdepth' option, in G1 we'd have much more stack traces data to be written to the disk as compared to the other collectors.I ran a simple test where I started a GC intensive application first with the Parallel collector, and then with the G1 collector. For both of these tests, I started HotSpot Default recording, and then started a manual time-fixed recording with the profile settings. Observations:1. The number of GC events created in case of G1 are much more than the parallel collector.2. The TLABs are smaller in G1 and that leads to the generation of more allocation events in comparison to the parallel collector.3. If we compare the size of the file written for a 2 minute profile recording with both the collectors, for G1 the size was 3M and for parallel collector it was 600K. This shows that the amount of data that gets written to the disk with G1 collector is more as compared to the ParallelGC, and that contributes towards longer JFRCheckpoint pauses. To summarize, if you are using JFR with the G1 collector, my suggestion would be to either use the default value for the 'stackdepth' which is 64, or use an even lower value if you observe long JFRCheckpoint operations.

Recently there was a report from a customer that they observed performance degradation while using JFR with G1 when they used it along with -XX:FlightRecorderOptions=stackdepth=512, but didn't see any...

Crashes in ZIP_GetEntry

Recently, received quite a few reports of the application crashes from different customers and product groups with the stack trace looking like this: Stack: [0xb0c00000,0xb0c80000],  sp=0xb0c7c890,  free space=498kNative frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)C  [libc_psr.so.1+0x700]  memcpy+0x2f8C  [libzip.so+0xd19c]C  [libzip.so+0x2380]  ZIP_GetEntry+0xe4C  [libzip.so+0x2800]  Java_java_util_zip_ZipFile_getEntry+0xc4j  java.util.zip.ZipFile.getEntry(JLjava/lang/String;Z)J+0j  java.util.zip.ZipFile.getEntry(JLjava/lang/String;Z)J+0j  java.util.zip.ZipFile.getEntry(Ljava/lang/String;)Ljava/util/zip/ZipEntry;+31j  java.util.jar.JarFile.getEntry(Ljava/lang/String;)Ljava/util/zip/ZipEntry;+2j  java.util.jar.JarFile.getJarEntry(Ljava/lang/String;)Ljava/util/jar/JarEntry;+2 Most of the times, the crashes in ZIP_GetEntry occur when the jar file being accessed has been modified/overwritten while the JVM instance was running. For performance reasons, HotSpot JVM memory maps each Jar file's central directory structure using mmap. This is done so as to avoid reading the central directory structure data from the disk every time it needs to read entries from the Jar file. When a Jar file is modified or overwritten on the disk, the JVM's copy of the data read earlier becomes inconsistent with the jar file on the disk, and any attempt to read and load entries from the modified jar can result in an application crash.Since 1.6.0_23, a property can be used to disable the memory mapping of the central directory structure of the Jar files: -Dsun.zip.disableMemoryMapping=truePlease note that enabling this property would have some performance impact on the application as the JVM needs to read the central directory structure from the Jar files on the disk again and again whenever it reads a Jar file entry. So, it is best to ensure that the jar files are not modified or overwritten while the JVM has an image of them loaded.In Java 9, this ZIP crash has been resolved with the following enhancement: JDK-8142508: To bring j.u.z.ZipFile's native implementation to Java to remove the expensive jni cost and mmap crash risk The code review thread for this change is here:http://mail.openjdk.java.net/pipermail/core-libs-dev/2015-November/036495.htmlThis enhancement replaces the ZIP file native implementation that used mmap with the Java implementation, and that removes the risk of application crashes described above.

Recently, received quite a few reports of the application crashes from different customers and product groups with the stack trace looking like this: Stack: [0xb0c00000,0xb0c80000], sp=0xb0c7c890, ...

Eager reclamation of Humongous objects with G1

G1 collector in JDK 8u40 and 8u60 got a very nice enhancement that might come as a surprise to users when they upgrade to either of these releases.As we all know that the objects larger than half of the size of the regions are called Humongous objects, and are allocated in special regions called Humongous regions. Up until 8u40, the Humongous regions were not collected during Evacuation pauses, and were collected only at the end of the marking cycle or during Full GCs.In 8u40, the following G1 enhancement was added: JDK-8027959: Early reclamation of large objects in G1This enabled the reclamation of Humongous objects that don't have any reference pointing into it. It added two new experimental JVM options: G1ReclaimDeadHumongousObjectsAtYoungGC - Experimental option which is enabled by default. When enabled, G1 reclaims dead objects at every young GC. G1TraceReclaimDeadHumongousObjectsAtYoungGC - Experimental option which is disabled by default. When enabled, G1 prints information about the collection of humongous objects at young GCs. The above change however introduced a regression which is fixed in 8u60. JDK-8069367: Eagerly reclaimed humongous objects left on mark stack In 8u60, this enhancement was improved, and the early reclamation now also looks at the Humongous regions that could have a few incoming references. Upon inspection of those incoming references, if G1 finds those references to be stale/dead then that Humongous region is reclaimed. This work was done under the following enhancement request: JDK-8048179: Early reclaim of large objects that are referenced by a few objectsThis change renamed the JVM option G1ReclaimDeadHumongousObjectsAtYoungGC to G1EagerReclaimHumongousObjects, and G1TraceReclaimDeadHumongousObjectsAtYoungGC to G1TraceEagerReclaimHumongousObjects. It added a new JVM option G1EagerReclaimHumongousObjectsWithStaleRefs. G1EagerReclaimHumongousObjectsWithStaleRefs - This is an Experimental option, and is enabled by default. When this option is enabled, G1 attempts to reclaim Humongous objects that may have a few stale incoming references, at every young GC.

G1 collector in JDK 8u40 and 8u60 got a very nice enhancement that might come as a surprise to users when they upgrade to either of these releases.As we all know that the objects larger than half of...

Using NMT with custom JVM launcher

I recently worked with a customer, facing problem in using Native Memory Tracker with their custom JVM launcher created using the JNI API JNI_CreateJavaVM, and learned how NMT can be enabled when used with the custom JVM launchers (non 'java' launchers). This blog post shares details on how that can be done.Let's start with the following JNI code example where I am passing the JVM option -XX:+NativeMemoryTracking=detail as an argument while creating the JVM with JNI_CreateJavaVM call. -XX:+NativeMemoryTracking=detail option should enable the Native Memory Tracker at the detail level. JavaVM *javaVM;JNIEnv *env;        // VM initialization arguments JavaVMInitArgs vmArgs; JavaVMOption* options = new JavaVMOption[1];options[0].optionString = "-XX:+NativeMemoryTracking=detail";vmArgs.version = JNI_VERSION_1_8;vmArgs.nOptions = 1;vmArgs.options = options;vmArgs.ignoreUnrecognized = false; // Create Java VMJNI_CreateJavaVM(&javaVM, (void**)&env, &vmArgs); delete options; Compile code with the following: JAVA_INCLUDES=-I$(JAVA_HOME)/include/ -I$(JAVA_HOME)/include/$(JAVA_OS)/ -L$(JAVA_HOME)/jre/lib/amd64/serverg++ jnicode.cpp $(JAVA_INCLUDES) -ljvm When this program is compiled using the above compile command, and executed, it reports the following error: Java HotSpot(TM) 64-Bit Server VM warning: Native Memory Tracking did not setup properly, using wrong launcher? The reason for this behavior is that the Native Memory Tracker requires an environment variable to be set for the process before the JVM can be initialized and created. That environment variable is NMT_LEVEL_<pid> where <pid> is the identifier of the process. Also, please note that since this environment variable should already be set before the JVM gets initialized, we need to dynamically load the JVM shared library at runtime after setting the env variable .Here's the sample code showing how we can do that: // env variable to be set for NMTconst char*  NMT_Env_Name    = "NMT_LEVEL_";const int TOTAL_LEN = strlen(NMT_Env_Name)+20;char *nmtEnv = (char*)calloc(TOTAL_LEN,1); snprintf(nmtEnv,TOTAL_LEN, "%s%d", NMT_Env_Name, getpid()); // Set the env variablesetenv(nmtEnv, "detail", 1); // Dynamically load libjvm.soconst char* jvmpath = "<path to libjvm.so>/libjvm.so"; void* libjvm = dlopen(jvmpath, RTLD_NOW + RTLD_GLOBAL);if (libjvm == NULL) { printf("Could not open libjvm.so\n"); return -1;}// VM initialization arguments JavaVMInitArgs vmArgs; JavaVMOption* options = new JavaVMOption[1];options[0].optionString = "-XX:+NativeMemoryTracking=detail";vmArgs.version = JNI_VERSION_1_8;vmArgs.nOptions = 1;vmArgs.options = options;vmArgs.ignoreUnrecognized = false;// get a handle to JNI_CreateJavaVM function in the dynamically loaded JVMCreateJavaVM_t CreateJavaVM;CreateJavaVM = (CreateJavaVM_t)dlsym(libjvm, "JNI_CreateJavaVM"); // Create the JVMJavaVM *javaVM;JNIEnv *jniEnv;long flag = CreateJavaVM(&javaVM, (void**)&jniEnv, &vmArgs); Compile code with the following: g++ jnivm.cc $(JAVA_INCLUDES) -ldl In the above example code, I am setting env variable NMT_LEVEL_<pid> and dynamically loading libjvm.so after setting this env variable. Note that I removed -ljvm from the g++ options so as not to load the JVM shared library at the process load time. With these simple changes, NMT can be used with the custom JVM launchers.

I recently worked with a customer, facing problem in using Native Memory Tracker with their custom JVM launcher created using the JNI API JNI_CreateJavaVM, and learned how NMT can be enabled when...

VM warning: PICL (libpicl.so.1) is missing

To increase the compiled code performance, following two fixes were integrated into JDK 8u40 and 7u80. With these changes, HotSpot uses PICL library available on Sparc Platform to get the CPU L2 cache line data size. This information can be used by the Compiler to optimize the generated compiled code and thus improve the runtime performance. 1. JDK-8056124: Hotspot should use PICL interface to get cacheline size on SPARC Changeset: http://hg.openjdk.java.net/jdk9/jdk9/hotspot/rev/63934ec778a2 2. JDK-8059200:Promoted JDK9 b31 for Solaris-amd64 fails (Error: dl failure on line 744, no picl library) on Solaris 11.1 Changeset: http://hg.openjdk.java.net/jdk9/jdk9/hotspot/rev/d0e59d57dda2 This enhancement attempts to load the PICL library dynamically, and if the library is not found on the system it issues the following warning and continues with the execution of the process: Java HotSpot(TM) Server VM warning: PICL (libpicl.so.1) is missing. Performance will not be optimal. Please note that this warning just indicates that the JVM could not load the PICL library so it won't be able to turn on some of the JIT Compiler optimizations that require the cache line data size information. It does not stop the Java process, or impact the process in any other way. Also, note that this is not a Java bug. The warning message is just intended to inform the user that the platform it is running on does not have the PICL library.

To increase the compiled code performance, following two fixes were integrated into JDK 8u40 and 7u80. With these changes, HotSpot uses PICL library available on Sparc Platform to get the CPU L2 cachel...

JVM hang with CMS collector

This blog post was long due but better late than never. Sometime back I worked on an interesting GC problem which initially looked like an issue with the JVM runtime system. I am talking about 'JDK-8085965: VM hangs in C2Compiler'. This bug has been fixed in JDK 9 and 8u45+. In this post, I want to share interesting symptoms of this bug, and the troubleshooting steps taken that helped in getting to the root of the problem.This report came in as a JVM hang when running with the CMS collector. Looking at the core file revealed that the JVM was in the '_synchronizing' state at that point. (gdb) print SafepointSynchronize::_state $1 = SafepointSynchronize::_synchronizing (gdb) print SafepointSynchronize::_waiting_to_block $2 = 1It was waiting for one thread to come to safe-point state and block.And the only thread running at that time was the Compiler thread. Stack trace of the Compiler thread: (gdb) where #0  Dependencies::find_finalizable_subclass (k=0x101047428) #1  0x00007fd6804a38ee in ciInstanceKlass::has_finalizable_subclass (this=0x7fd67913e950) #2  0x00007fd6809c28fb in Parse::call_register_finalizer (this=0x7fd6395405a0) #3  0x00007fd6809c2fb9 in Parse::return_current (this=0x101047428, value=0x0) #4  0x00007fd6809cf526 in Parse::do_one_bytecode (this=0x101047428)     #5  0x00007fd6809c17d8 in Parse::do_one_block (this=0x7fd6395405a0) #6  0x00007fd6809c1a57 in Parse::do_all_blocks (this=0x7fd6395405a0) #7  0x00007fd6809c5fe9 in Parse::Parse (this=0x7fd6395405a0, caller=<optimized out>, parse_method=<optimized out>, expected_uses=5377) #8  0x00007fd6804784e8 in ParseGenerator::generate (this=0x7fd63004dd60, jvms=0x7fd61c402f40) #9  0x00007fd6805eea36 in Parse::do_call (this=0x7fd6395409c0) #10 0x00007fd6809cf5aa in Parse::do_one_bytecode (this=0x101047428) #11 0x00007fd6809c17d8 in Parse::do_one_block (this=0x7fd6395409c0) #12 0x00007fd6809c1a57 in Parse::do_all_blocks (this=0x7fd6395409c0) #13 0x00007fd6809c5fe9 in Parse::Parse (this=0x7fd6395409c0, caller=<optimized out>, parse_method=<optimized out>, expected_uses=5377)The klass* passed to find_finalizable_subclass() was: 0x101047428 (gdb) info frame Stack level 0, frame at 0x7fd639540240:  rip = 0x7fd6805955a0 in Dependencies::find_finalizable_subclass (gdb) print k $1 = (Klass *) 0x101047428 (gdb) print *$1 $2 = {<Metadata> = {<MetaspaceObj> = {<No data fields>}, _vptr.Metadata = 0x7fd680fc9670 <vtable for InstanceKlass+16>}, _layout_helper = 16,   _super_check_offset = 64, _name = 0x7fd618009850, _secondary_super_cache =  0x100009608, _secondary_supers = 0x7fd668848a88, _primary_supers = {     0x100000f28, 0x100009418, 0x1000097f0, 0x101047428, 0x0, 0x0, 0x0, 0x0},  _java_mirror = 0xa77b4b40, _super = 0x1000097f0, _subklass = 0x0,    _next_sibling = 0x101047428, _next_link = 0x0, _class_loader_data =  0x7fd618003ab0, _modifier_flags = 1, _access_flags = {_flags = 536870913},    _last_biased_lock_bulk_revocation_time = 0, _prototype_header = 0x5,  _biased_lock_revocation_count = 0, _trace_id = 1685520384,    _modified_oops = 0 '\000', _accumulated_modified_oops = 0 '\000',  _shared_class_path_index = -1} (gdb) x/s 0x7fd618009850+8  0x7fd618009858: "sun/reflect/GeneratedMethodAccessor1389" _next_sibling = 0x101047428 The next_sibling in this case was the same as the klass itself. So, the compiler thread was stuck in the following loop: 1187 Klass* Dependencies::find_finalizable_subclass(Klass* k) { 1188   if (k->is_interface())  return NULL; 1189   if (k->has_finalizer()) return k; 1190   k = k->subklass(); 1191   while (k != NULL) { 1192     Klass* result = find_finalizable_subclass(k); 1193     if (result != NULL) return result; 1194     k = k->next_sibling();   1195   } 1196   return NULL; 1197 } Then we did another run with the failing program using TraceClassLoading and TraceClassUnloading JVM options. From the core file of this run, found that VM was stuck while going over a circular siblings list. Note that the subklasses of a Klass are maintained using the _next_sibling field of its first _subklass.Here's the klass and subklasses chain built from the core file: super class sun/reflect/SerializationConstructorAccessorImpl - 0x1001acec0    |--subklasses chain 0x1010eec30-sun/reflect/GeneratedSerializationConstructorAccessor232-> 0x1010ef030-sun/reflect/GeneratedSerializationConstructorAccessor231-> 0x1010ef430-sun/reflect/GeneratedSerializationConstructorAccessor230-> 0x1010ef830-sun/reflect/GeneratedSerializationConstructorAccessor229-> 0x1010efc30-sun/reflect/GeneratedSerializationConstructorAccessor228-> 0x1010f0030-sun/reflect/GeneratedSerializationConstructorAccessor227-> 0x1010f0430-sun/reflect/GeneratedSerializationConstructorAccessor226-> 0x1010f0830-sun/reflect/GeneratedSerializationConstructorAccessor225-> 0x1010f0c30- sun/reflect/GeneratedSerializationConstructorAccessor224-> 0x1010f1030-sun/reflect/GeneratedSerializationConstructorAccessor223-> 0x1010f1430-sun/reflect/GeneratedSerializationConstructorAccessor222-> 0x1010f1830-sun/reflect/GeneratedSerializationConstructorAccessor221-> 0x1010f1c30-sun/reflect/GeneratedSerializationConstructorAccessor220-> 0x1010f2030-sun/reflect/GeneratedSerializationConstructorAccessor219-> 0x1010f2430- sun/reflect/GeneratedSerializationConstructorAccessor218-> 0x1010f2830-sun/reflect/GeneratedSerializationConstructorAccessor217-> 0x10110b830-sun/reflect/GeneratedMethodAccessor94-> 0x1010e8430-sun/reflect/GeneratedSerializationConstructorAccessor256-> 0x1010e8830-sun/reflect/GeneratedSerializationConstructorAccessor255-> 0x1010e8c30-sun/reflect/GeneratedSerializationConstructorAccessor254-> 0x1010e9830-sun/reflect/GeneratedSerializationConstructorAccessor253-> 0x1010e9c30-sun/reflect/GeneratedSerializationConstructorAccessor252-> 0x1010ea030-sun/reflect/GeneratedSerializationConstructorAccessor251-> 0x1010ea430-sun/reflect/GeneratedSerializationConstructorAccessor250-> 0x1010ea830-sun/reflect/GeneratedSerializationConstructorAccessor249-> 0x1010eac30-sun/reflect/GeneratedSerializationConstructorAccessor248-> 0x1010eb030-sun/reflect/GeneratedSerializationConstructorAccessor247-> 0x1010eb430-sun/reflect/GeneratedSerializationConstructorAccessor246-> 0x1010eb830-sun/reflect/GeneratedSerializationConstructorAccessor245-> 0x1010ebc30-sun/reflect/GeneratedSerializationConstructorAccessor244-> 0x1010ec030-sun/reflect/GeneratedSerializationConstructorAccessor243-> 0x1010ec430-sun/reflect/GeneratedSerializationConstructorAccessor242-> 0x1010ec830-sun/reflect/GeneratedSerializationConstructorAccessor241-> 0x1010ecc30-sun/reflect/GeneratedSerializationConstructorAccessor240-> 0x1010ed030-sun/reflect/GeneratedSerializationConstructorAccessor239-> 0x1010ed430-sun/reflect/GeneratedSerializationConstructorAccessor238-> 0x1010ed830-sun/reflect/GeneratedSerializationConstructorAccessor237-> 0x1010edc30-sun/reflect/GeneratedSerializationConstructorAccessor236-> 0x1010ee030-sun/reflect/GeneratedSerializationConstructorAccessor235-> 0x1010ee430-sun/reflect/GeneratedSerializationConstructorAccessor234-> 0x1010ee830-sun/reflect/GeneratedSerializationConstructorAccessor233-> 0x1010eec30-sun/reflect/GeneratedSerializationConstructorAccessor232The GC logs generated with TraceClassLoading and TraceClassUnloading options had: [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor216 0x000000010110b830] So, GeneratedSerializationConstructorAccessor216 was unloaded from address 0x10110b830, and sun/reflect/GeneratedMethodAccessor94 got loaded at the same address. But the link to GeneratedSerializationConstructorAccessor216 in the siblings list was not updated after this class was unloaded, and that corrupted the subKlasses chain.That made me look at the other JVM options used for this failing program. hs_err file showed that -Xnoclassgc was being used to turn off the class unloading but the logs indicated that classes were still getting unloaded. From that point, this mystery was not very hard to solve.In JDK8, CMSClassUnloadingEnabled option which is used to control the class-unloading in CMS collector, was enabled by default. And this problem was occurring due to the conflicting values getting set for CMSClassUnloadingEnabled and ClassUnloading options. One phase of the class-unloading which is common to the other collectors too that updates subkalsses/siblings links is performed only when ClassUnloading option is enabled. So when -Xnoclassgc or -XX:-ClassUnloading are specified on the command line, due to this bug CMSClassUnloadingEnabled stays enabled and classes get unloaded but that common step gets skipped which corrupts the class hierarchy links leading to hangs or crashes. The fix was simple - disable CMS class unloading options when -Xnoclassgc or -XX:-ClassUnloading are specified.There is a similar bug open for G1 collector which is being worked and is targeted for JDK9:    JDK-8114823: G1 doesn't honor request to disable class unloading

This blog post was long due but better late than never. Sometime back I worked on an interesting GC problem which initially looked like an issue with the JVM runtime system. I am talking...

Why do I get message "CodeCache is full. Compiler has been disabled"?

JVM JIT generates compiled code and stores that in a memory area called CodeCache. The default maximum size of the CodeCache on most of the platforms is 48M. If any application needs to compile large number of methods resulting in huge amount of compiled code then this CodeCache may become full. When it becomes full, the compiler is disabled to stop any further compilations of methods, and a message like the following gets logged: Java HotSpot(TM) 64-Bit Server VM warning: CodeCache is full. Compiler has been disabled.Java HotSpot(TM) 64-Bit Server VM warning: Try increasing the code cache size using -XX:ReservedCodeCacheSize=Code Cache  [0xffffffff77400000, 0xffffffff7a390000, 0xffffffff7a400000) total_blobs=11659 nmethods=10690 adapters=882 free_code_cache=909Kb largest_free_block=502656 When this situation occurs, JVM may invoke sweeping and flushing of this space to make some room available in the CodeCache. There is a JVM option UseCodeCacheFlushing that can be used to control the flushing of the Codeache. With this option enabled JVM invokes an emergency flushing that discards older half of the compiled code(nmethods) to make space available in the CodeCache. In addition, it disables the compiler until the available free space becomes more than the configured CodeCacheMinimumFreeSpace. The default value of CodeCacheMinimumFreeSpace option is 500K. UseCodeCacheFlushing is set to false by default in JDK6, and is enabled by default since JDK7u4. This essentially means that in jdk6 when the CodeCache becomes full, it is not swept and flushed and further compilations are disabled, and in jdk7u+, an emergency flushing is invoked when the CodeCache becomes full. Enabling this option by default made some issues related to the CodeCache flushing visible in jdk7u4+ releases. The following are two known problems in jdk7u4+ with respect to the CodeCache flushing:1. The compiler may not get restarted even after the CodeCache occupancy drops down to almost half after the emergency flushing.2. The emergency flushing may cause high CPU usage by the compiler threads leading to overall performance degradation. This performance issue, and the problem of the compiler not getting re-enabled again has been addressed in JDK8. To workaround these in JDK7u4+, we can increase the code cache size using ReservedCodeCacheSize option by setting it to a value larger than the compiled-code footprint so that the CodeCache never becomes full. Another solution to this is to disable the CodeCache Flushing using -XX:-UseCodeCacheFlushing JVM option.The above mentioned issues have been fixed in JDK8 and its updates. Here's the list of the bugs that have been fixed in jdk8 and 8u20 that address these problems:    * JDK-8006952: CodeCacheFlushing degenerates VM with excessive codecache freelist iteration (fixed in 8)    * JDK-8012547: Code cache flushing can get stuck without completing reclamation of memory (fixed in 8)    * JDK-8020151: PSR:PERF Large performance regressions when code cache is filled (fixed in 8)    * JDK-8029091 Bug in calculation of code cache sweeping interval (fixed in 8u20)    * 8027593: performance drop with constrained codecache starting with hs25 b111 (fixed in 8)

JVM JIT generates compiled code and stores that in a memory area called CodeCache. The default maximum size of the CodeCache on most of the platforms is 48M. If any application needs to compile large...

Updates to the Java Troubleshooting Guide

Mattis Castegren who is my manager at Oracle, and is the guest writer for this blog post would like to share some details on the Java Troubleshooting Guide. Here's what he has to say:-- With the release of JDK 8, the official Java Troubleshooting Guide got a big overhaul. All pages were looked over and updated for JDK 8, and the two previous guides for the JVM and for Desktop Technologies were merged into one. In the last month, with the release of 8u40, we have launched the next phase in this project. In this phase, we have added a lot of chapters about the new supportability tools that have been introduced in Java over the last few years. The biggest new additions are a set of pages on how to use the Java Flight Recorder (JFR). If you haven't used JFR before, you should definitely check out the following chapters: 2.3 What are Java Flight Recordings 2.4 How to Produce a Flight Recording 2.5 Inspect a Flight Recording These chapters contain step by step instructions on how to record a JFR and also goes through what to look for in a recording to find common issues. The chapters contain lots of screen shots and details on how to interpret the data. Once you have learned the basics, you can also look at the following two chapters on how to use JFR to debug specific issues: 3.1 Debug a Memory Leak Using Java Flight Recorder 4 Troubleshoot Performance Issues Using JFR When you have read through these chapters, you will be ready to use this great tool to find bottle necks in your own application. Other new additions to the troubleshooting guide is a new chapter on how to set up Java for better troubleshooting: Prepare Java for Troubleshooting, as well as a lot of minor updates and clarifications.

Mattis Castegren who is my manager at Oracle, and is the guest writer for this blog post would like to share some details on the Java Troubleshooting Guide. Here's what he has to say:-- With the...

Analysis of Strange Hotspot Crashes

In this blog post, I am going to talk about the core file analysis of some strange looking hotspot crashes using gdb and Serviceability Agent debugging tools. At the first glance, these crashes appeared to be caused by some Hotspot Server Compiler issue but in the end these actually turned out to be due to a Linux Kernel bug.This first crash happened in the compiled code of method SafeHashMap.put() # Problematic frame: # J 3575 C2 com.tangosol.util.SafeHashMap.put(Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object; (190 bytes) @ 0x00002aaaabda7ffd [0x00002aaaabda7da0+0x25d] # # Core dump written.I opened the core with gdb and the stack trace of the crashing thread looked like this: #15 0x00002afd41aa5e7f in JVM_handle_linux_signal (sig=11, info=0x40fd7c90, ucVoid=0x40fd7b60, abort_if_unrecognized=1) #16 0x00002afd41a9ce13 in signalHandler (sig=11, info=0x40fd7c90, uc=0x40fd7b60) #17 <signal handler called> #18 0x00002aaaabda7ffd in ?? () #19 0x00000000c005e3c8 in ?? () #20 0x00000000c005e3c8 in ?? () #21 0x00000000c005e3c8 in ?? () #22 0xc005e3c82000cb42 in ?? () #23 0x0000000000000007 in ?? () #24 0x0000000000000000 in ?? ()Opened the core file with Serviceability Agent tool too and inspected the addresses present in the above stack trace: hsdb> whatis 0x00002aaaabda7ffd Address 0x00002aaaabda7ffd: In code in NMethod for com/tangosol/util/SafeHashMap.put(Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object; content: [0x00002aaaabda7da0, 0x00002aaaabda9280),  code: [0x00002aaaabda7da0, 0x00002aaaabda9280),  data: [0x00002aaaabda9280, 0x00002aaaabda9f18),  oops: [0x00002aaaabda9280, 0x00002aaaabda9288),  frame size: 144 hsdb> whatis 0x00000000c005e3c8 Address 0x00000000c005e3c8: In unknown section of Java heap So, all the above digging confirmed that the crash happened in the compiled code of com.tangosol.util.SafeHashMap.put(). I looked at the assembly of the generated code in gdb: (gdb) x/610i 0x00002aaaabda7da0 .... ....    0x2aaaabda7f83:      mov    $0x2000cbc5,%r9d    0x2aaaabda7f89:      movabs $0x0,%r11    0x2aaaabda7f93:      lea    (%r11,%r9,8),%r11    0x2aaaabda7f97:      mov    0xa8(%r11),%r11    0x2aaaabda7f9e:      mov    %r11,0x0(%r13)    0x2aaaabda7fa2:      movl   $0x2000cbc5,0x8(%r13)    0x2aaaabda7faa:      mov    %r12d,0xc(%r13)    0x2aaaabda7fae:      mov    %r12,0x10(%r13)    0x2aaaabda7fb2:      mov    %r12,0x18(%r13)    0x2aaaabda7fb6:      mov    %r13,%r9    0x2aaaabda7fb9:      mov    %r14,%r11    0x2aaaabda7fbc:      mov    %r11d,0x10(%r13)    0x2aaaabda7fc0:      shr    $0x9,%r9    0x2aaaabda7fc4:      movabs $0x2aaab9f5b000,%r11    0x2aaaabda7fce:      mov    %r12b,(%r11,%r9,1)    0x2aaaabda7fd2:      mov    (%rsp),%r9d    0x2aaaabda7fd6:      mov    %r9d,0x14(%r13)    0x2aaaabda7fda:      mov    %r13,%r11    0x2aaaabda7fdd:      shr    $0x9,%r11    0x2aaaabda7fe1:      movabs $0x2aaab9f5b000,%r9    0x2aaaabda7feb:      mov    %r12b,(%r9,%r11,1)    0x2aaaabda7fef:      lock addl $0x0,(%rsp)    0x2aaaabda7ff4:      mov    %r10d,0xc(%r13)    0x2aaaabda7ff8:      movq   %xmm0,%r11    0x2aaaabda7ffd:      mov    (%r11),%rax  <---crash here, r11 is 0    0x2aaaabda8000:      mov    %rax,%r11 .... .... The thread crashed while accessing the value at an address stored in r11 register. Looking at the value of r11 register: r11 0x0r11 contains 0 and accessing the value at null address caused the crash.Now, if we look at the previous instruction "movq   %xmm0,%r11", value in r11 was copied over from xmm0 register. The value in xmm0 register is 0. There is a bug in Linux kernel where the xmm registers may get corrupted under certain circumstances. Details on the kernel bug: https://bugzilla.redhat.com/show_bug.cgi?format=multiple&id=547893The machine where this crash was observed: RELEASE=2.6.18-308.4.1.0.1.el5xen  VERSION=#1 SMP Tue Apr 17 16:41:30 EDT 2012  MACHINE=x86_64 So, the process was running on a machine which is vulnerable to that Linux kernel bug.Let's take a look at another such Hotspot crash. # # A fatal error has been detected by the Java Runtime Environment: # #  Internal Error (sharedRuntime.cpp:833), pid=26946, tid=1082554688 #  fatal error: exception happened outside interpreter, nmethods and vtable stubs at pc 0x00002aaaab1f5340 Current thread (0x000000001ee9b000):  JavaThread "main" [_thread_in_Java, id=26949, stack(0x0000000040767000,0x0000000040868000)] Stack: [0x0000000040767000,0x0000000040868000],  sp=0x00000000408631a0,  free space=1008k Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code) V  [libjvm.so+0xaaa6ea]  VMError::report_and_die()+0x2ba V  [libjvm.so+0x4f2749]  report_fatal(char const*, int, char const*)+0x59 V  [libjvm.so+0x9a952a]  SharedRuntime::continuation_for_implicit_exception(JavaThread*, unsigned char*, SharedRuntime::ImplicitExceptionKind)+0x33a V  [libjvm.so+0x91370a]  JVM_handle_linux_signal+0x48a V  [libjvm.so+0x909c83]  signalHandler(int, siginfo*, void*)+0x43 C  [libpthread.so.0+0xebe0] J 528 C2 com.sun.org.apache.xerces.internal.impl.xs.opti.SchemaDOMParser.characters(Lcom/sun/org/apache/xerces/internal/xni/XMLString;Lcom/sun/org/apache/xerces/internal/xni/Augmentations;)V (110 bytes) @ 0x00002aaaab607423 [0x00002aaaab606ec0+0x563] (gdb) where #0  0x0000003968a30265 in raise () #1  0x0000003968a31d10 in abort () #2  0x00002b96ba0bbea5 in os::abort (dump_core=true) #3  0x00002b96ba258af3 in VMError::report_and_die (this=0x40863320) #4  0x00002b96b9ca0749 in report_vm_error (detail_msg=<optimized out>, error_msg=<optimized out>, line=<optimized out>, file=<optimized out>)    #5  report_fatal (file=0x2b96ba2e0330, line=833, message=0x408633b8)    #6  0x00002b96ba15752a in SharedRuntime::continuation_for_implicit_exception(thread=0x1ee9b000,     pc=0x2aaaab1f5340, exception_kind=<optimized out>)    #7  0x00002b96ba0c170a in JVM_handle_linux_signal (sig=11, info=0x408637c0, ucVoid=0x40863690, abort_if_unrecognized=1)    #8  0x00002b96ba0b7c83 in signalHandler (sig=11, info=0x408637c0, uc=0x40863690) #9  <signal handler called> #10 0x00002aaaab1f5340 in ?? () #11 0x00000000fe8bace8 in ?? () #12 0x00002aaaab607423 in ?? () #13 0x00000000fe94d0a0 in ?? () #14 0x00000000fe8bacd0 in ?? () #15 0x00000000fe8bacd0 in ?? () #16 0x00002aaac0cdd850 in ?? () #17 0x0000000000000007 in ?? () Inspecting the crashing PC 0x00002aaaab1f5340 with SA: hsdb> whatis 0x00002aaaab1f5340 Address 0x00002aaaab1f5340: In code in StubRoutines (2) content: [0x00002aaaab1f4e20, 0x00002aaaab1fa410),  code: [0x00002aaaab1f4e20, 0x00002aaaab1fa410),  data: [0x00002aaaab1fa410, 0x00002aaaab1fa410),  frame size: 0 Frame #12: hsdb> whatis 0x00002aaaab607423 Address 0x00002aaaab607423: In code in NMethod for com/sun/org/apache/xerces/internal/impl/xs/opti/SchemaDOMParser.characters(Lcom/sun/org/apache/xerces/internal/xni/XMLString;Lcom/sun/org/apache/xerces/inte rnal/xni/Augmentations;)V content: [0x00002aaaab606ec0, 0x00002aaaab6083d8),  code: [0x00002aaaab606ec0, 0x00002aaaab6083d8),  data: [0x00002aaaab6083d8, 0x00002aaaab608e98),  oops: [0x00002aaaab6083d8, 0x00002aaaab6083e8),  frame size: 144 Disassembly around the crashing PC: 0x2aaaab1f5280:      movdqu 0x30(%rdi,%rdx,8),%xmm0    0x2aaaab1f5286:      movdqu %xmm0,0x30(%rsi,%rdx,8)    0x2aaaab1f528c:      movdqu 0x20(%rdi,%rdx,8),%xmm1    0x2aaaab1f5292:      movdqu %xmm1,0x20(%rsi,%rdx,8)    0x2aaaab1f5298:      movdqu 0x10(%rdi,%rdx,8),%xmm2    0x2aaaab1f529e:      movdqu %xmm2,0x10(%rsi,%rdx,8)    0x2aaaab1f52a4:      movdqu (%rdi,%rdx,8),%xmm3    0x2aaaab1f52a9:      movdqu %xmm3,(%rsi,%rdx,8)    0x2aaaab1f52ae:      sub    $0x8,%rdx    0x2aaaab1f52b2:      jge    0x2aaaab1f5280    0x2aaaab1f52b4:      add    $0x4,%rdx    0x2aaaab1f52b8:      jl     0x2aaaab1f52d4    0x2aaaab1f52ba:      movdqu 0x10(%rdi,%rdx,8),%xmm0    0x2aaaab1f52c0:      movdqu %xmm0,0x10(%rsi,%rdx,8)    0x2aaaab1f52c6:      movdqu (%rdi,%rdx,8),%xmm1    0x2aaaab1f52cb:      movdqu %xmm1,(%rsi,%rdx,8)    0x2aaaab1f52d0:      sub    $0x4,%rdx    0x2aaaab1f52d4:      add    $0x4,%rdx    0x2aaaab1f52d8:      jg     0x2aaaab1f5265    0x2aaaab1f52da:      xor    %rax,%rax    0x2aaaab1f52dd:      leaveq    0x2aaaab1f52de:      retq    0x2aaaab1f52df:      nop    0x2aaaab1f52e0:      push   %rbp    0x2aaaab1f52e1:      mov    %rsp,%rbp    0x2aaaab1f52e4:      mov    %rdx,%rcx    0x2aaaab1f52e7:      shr    $0x2,%rdx    0x2aaaab1f52eb:      lea    -0x8(%rdi,%rdx,8),%rdi    0x2aaaab1f52f0:      lea    -0x8(%rsi,%rdx,8),%rsi    0x2aaaab1f52f5:      neg    %rdx    0x2aaaab1f52f8:      jmpq   0x2aaaab1f5370    0x2aaaab1f52fd:      mov    0x8(%rdi,%rdx,8),%rax    0x2aaaab1f5302:      mov    %rax,0x8(%rsi,%rdx,8)    0x2aaaab1f5307:      inc    %rdx    0x2aaaab1f530a:      jne    0x2aaaab1f52fd    0x2aaaab1f530c:      test   $0x2,%ecx    0x2aaaab1f5312:      je     0x2aaaab1f5322    0x2aaaab1f5314:      mov    0x8(%rdi),%eax    0x2aaaab1f5317:      mov    %eax,0x8(%rsi)    0x2aaaab1f531a:      add    $0x4,%rdi    0x2aaaab1f531e:      add    $0x4,%rsi    0x2aaaab1f5322:      test   $0x1,%ecx    0x2aaaab1f5328:      je     0x2aaaab1f5332    0x2aaaab1f532a:      mov    0x8(%rdi),%ax    0x2aaaab1f532e:      mov    %ax,0x8(%rsi)    0x2aaaab1f5332:      xor    %rax,%rax    0x2aaaab1f5335:      leaveq    0x2aaaab1f5336:      retq    0x2aaaab1f5337:      nopw   0x0(%rax,%rax,1) => 0x2aaaab1f5340:      movdqu -0x38(%rdi,%rdx,8),%xmm0    0x2aaaab1f5346:      movdqu %xmm0,-0x38(%rsi,%rdx,8)    0x2aaaab1f534c:      movdqu -0x28(%rdi,%rdx,8),%xmm1    0x2aaaab1f5352:      movdqu %xmm1,-0x28(%rsi,%rdx,8)    0x2aaaab1f5358:      movdqu -0x18(%rdi,%rdx,8),%xmm2    0x2aaaab1f535e:      movdqu %xmm2,-0x18(%rsi,%rdx,8)    0x2aaaab1f5364:      movdqu -0x8(%rdi,%rdx,8),%xmm3    0x2aaaab1f536a:      movdqu %xmm3,-0x8(%rsi,%rdx,8)    0x2aaaab1f5370:      add    $0x8,%rdxIn the assembly code of the StubRoutine, we can see that the values are being moved to and from xmm registers and the crash happens while accessing value at an address present in rdi register. rdx 0xffffffffffffffc8 rdi 0x1f8 Machine details where this crash happened: RELEASE=2.6.18-308.4.1.0.1.el5xen  VERSION=#1 SMP Tue Apr 17 16:41:30 EDT 2012  MACHINE=x86_64If you encounter such weird looking Hotspot crashes where the cause of the register/memory corruption seems to be unreasonable, please make sure that you are running on a latest patched Linux kernel. Kernels of version older that 2.6.32 may be vulnerable to this kernel bug.

In this blog post, I am going to talk about the core file analysis of some strange looking hotspot crashes using gdb and Serviceability Agent debugging tools. At the first glance, these crashes...

Long Class-Unloading Pauses with JDK8

Recently, I came across a report where a user was facing long GC pauses with JDK8. They didn't see this issue while running with JDK7. The problem with jdk8 was that sometimes the class unloading step of CMS-remark phase was taking a very long time to do its job. They were running with large pages enabled with both jdk7 and jdk8. 2014-11-30T01:51:35.632+0000: [GC (CMS Final Remark) [YG occupancy: 292006 K (1179648 K)][Rescan (parallel) , 0.0397261 secs][weak refs processing, 0.0954205 secs][class unloading, 29.2450253 secs][scrub symbol table, 4.9592268 secs][scrub string table, 0.0034572 secs][1 CMS-remark: 1101173K(1835008K)] 1393180K(3014656K), 34.3796360 secs] [Times: user=0.92 sys=0.38, real=34.37 secs]2014-12-01T02:01:44.452+0000: [GC (CMS Final Remark) [YG occupancy: 550275 K (1179648 K)][Rescan (parallel) , 0.0785401 secs][weak refs processing, 0.0931797 secs][class unloading, 28.0163134 secs][scrub symbol table, 5.2806525 secs][scrub string table, 0.0034023 secs][1 CMS-remark: 1101982K(1835008K)] 1652257K(3014656K), 33.5087749 secs] [Times: user=1.48 sys=0.36, real=33.51 secs]Now, here if we look closely, there is a huge difference in the times reported for 'user' 'sys' and 'real'. As we all know, 'user' is the amount of CPU time spent in user-mode within the process and 'sys' is the amount of CPU time spent in the kernel within the process. Other processes and the time the process spends blocked does not count towards these two figures. The 'real' time is the total elapsed time including time slices used by other processes and the time the process spends blocked (for example in waiting for I/O to complete, or system is performing memory activities such as paging/swapping).In this case too, the problem seemed not be with the JVM or more specifically with the class unloading step but more with the GC threads getting blocked out. It turned out that the class unloading phase was causing lot of paging activity to occur at the system level which took away the CPU time from the GC threads.What changed in the JVM from JDK7 to JDK8 is that in JDK8 we don't have PermGen. Instead we have MetaSpace which is allocated out of native memory space. As I mentioned earlier, the user was running with Large Pages enabled. With JDK7 by using option -XX:+UseLargePages, we get the large pages enabled for the Java Heap as well as for the PermGen. But with jdk8, with the class meta data stored in MetaSpace(native space), we don't get large pages enabled for the MetaSpace by default when we use +UseLargePages. In this particular case, the system was configured to have higher number of large pages and a limited memory resource was left for the regular small pages. And a limited number of regular pages available for the MetaSpace caused paging activity during the class unloading phase leading to long GC pauses. The solution for this problem was to use -XX:+UseLargePagesInMetaspace that enables the large pages support for the MetaSpace. This avoided the paging activity and the class-unloading times returned to normal.Please note that UseLargePagesInMetaspace is not enabled by default when UseLargePages is ON. This is intentional and is done to avoid any memory usage regressions. A classloader (and its classes metadata) is stored in a chunk of memory called Metachunk in the MetaSpace. To be able to hand back pages to the system, we have to clean out an entire page. It is possible that there may be many Metachunks of different classloaders present on a page, and that page can be returned to the system only when all the classloaders are dead and their Metachunks are not needed any more. This leads to delayed deallocation of pages and it is a bit more likely with large pages.Another reason for not turning UseLargePagesInMetaspace option on by default is that we can not use large pages for the CompressedClass space. The problem there is that we can not dynamically grow the number of large pages; we have to pre-commit all the large pages when memory is reserved. CompressedClass space by default is 1GB of reserved memory and committing that 1GB up-front would cause memory usage regressions.So, if one has the system configured in such a way that a larger part of memory is set aside for large pages and a relatively smaller part for the regular pages, it is likely to observe the above described long GC pauses during the clean up of MetaSpace. In such situation, using UseLargePagesInMetaspace may help resolve the problem.

Recently, I came across a report where a user was facing long GC pauses with JDK8. They didn't see this issue while running with JDK7. The problem with jdk8 was that sometimes the class unloading step...

Increased heap usage with G1 GC

G1 garbage collector is a predictable low pause collector that works efficiently to achieve the low pause time goals. To meet the set pause time goals, G1 tries to: pick only those many old heap regions for the collection-set that it thinks could be collected in the specified goal time adapt the young generation size to contain the collection times within the set goal. In that effort, however, G1 may end up causing a side effect of increased usage of the Java Heap. For example, in an experimental run with CMS using a heap size of 8GB, the maximum observed heap usage was around 4GB. But after switching to G1, with -XX:MaxGCPauseMillis=50, the heap usage went up to 6GB. In both the cases, the application load was same. Part of the CMS GC logs:------------------------2014-11-21T05:18:18.790-0500: 1918944.850: [GC2014-11-21T05:18:18.790-0500: 1918944.850: [ParNew: 32704K->64K(32704K), 0.0698450 secs] 4274067K->4247066K(8388544K), 0.0700480 secs] [Times: user=0.32 sys=0.01, real=0.06 secs] 2014-11-21T05:18:18.864-0500: 1918944.924: [GC [1 CMS-initial-mark: 4247002K(8355840K)] 4247095K(8388544K), 0.1249300 secs] [Times: user=0.12 sys=0.00, real=0.13 secs] 2014-11-21T05:18:18.989-0500: 1918945.050: [CMS-concurrent-mark-start]2014-11-21T05:18:31.163-0500: 1918957.223: [GC2014-11-21T05:18:31.163-0500: 1918957.223: [ParNew: 32704K->64K(32704K), 0.0365220 secs] 4279706K->4247775K(8388544K), 0.0367530 secs] [Times: user=0.26 sys=0.00, real=0.04 secs] 2014-11-21T05:18:37.588-0500: 1918963.648: [CMS-concurrent-mark: 18.547/18.598 secs] [Times: user=39.03 sys=0.47, real=18.59 secs] 2014-11-21T05:18:37.588-0500: 1918963.648: [CMS-concurrent-preclean-start]2014-11-21T05:18:37.708-0500: 1918963.768: [CMS-concurrent-preclean: 0.114/0.120 secs] [Times: user=0.13 sys=0.00, real=0.12 secs] 2014-11-21T05:18:37.708-0500: 1918963.768: [CMS-concurrent-abortable-preclean-start]CMS: abort preclean due to time 2014-11-21T05:18:42.724-0500: 1918968.785: [CMS-concurrent-abortable-preclean: 3.008/5.016 secs] [Times: user=3.34 sys=0.12, real=5.02 secs] 2014-11-21T05:18:42.728-0500: 1918968.789: [GC[YG occupancy: 25109 K (32704 K)]2014-11-21T05:18:42.728-0500: 1918968.789: [Rescan (parallel) , 0.1196710 secs]2014-11-21T05:18:42.848-0500: 1918968.909: [weak refs processing, 0.0002300 secs]2014-11-21T05:18:42.848-0500: 1918968.909: [class unloading, 0.0219670 secs]2014-11-21T05:18:42.870-0500: 1918968.931: [scrub symbol table, 0.0144900 secs]2014-11-21T05:18:42.885-0500: 1918968.945: [scrub string table, 0.0046370 secs] [1 CMS-remark: 4247711K(8355840K)] 4272821K(8388544K), 0.1740580 secs] [Times: user=0.99 sys=0.00, real=0.17 secs] 2014-11-21T05:18:42.903-0500: 1918968.963: [CMS-concurrent-sweep-start] Part of the G1 GC logs:-----------------------  [Times: user=0.40 sys=0.01, real=0.06 secs]     [Eden: 368.0M(368.0M)->0.0B(372.0M) Survivors: 40.0M->36.0M Heap: 6622.9M(8192.0M)->6259.7M(8192.0M)] 2014-10-08T04:38:46.675-0400: 1311963.055: [GC pause (young) (initial-mark), 0.0564110 secs]    [Parallel Time: 51.4 ms, GC Workers: 8]       [GC Worker Start (ms): Min: 1311963055.7, Avg: 1311963055.7, Max: 1311963055.8, Diff: 0.1]       [Ext Root Scanning (ms): Min: 6.3, Avg: 11.8, Max: 16.2, Diff: 9.9, Sum: 94.7]       [Update RS (ms): Min: 3.0, Avg: 4.7, Max: 7.4, Diff: 4.4, Sum: 37.8]          [Processed Buffers: Min: 2, Avg: 8.8, Max: 18, Diff: 16, Sum: 70]       [Scan RS (ms): Min: 1.0, Avg: 1.3, Max: 1.4, Diff: 0.5, Sum: 10.0]       [Object Copy (ms): Min: 29.0, Avg: 33.0, Max: 39.7, Diff: 10.7, Sum: 264.3]       [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]       [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.9]       [GC Worker Total (ms): Min: 50.9, Avg: 51.0, Max: 51.1, Diff: 0.2, Sum: 407.8]       [GC Worker End (ms): Min: 1311963106.7, Avg: 1311963106.7, Max: 1311963106.9, Diff: 0.2]    [Code Root Fixup: 0.0 ms]    [Clear CT: 1.5 ms]    [Other: 3.6 ms]       [Choose CSet: 0.0 ms]       [Ref Proc: 1.8 ms]       [Ref Enq: 0.1 ms]       [Free CSet: 0.7 ms]    [Eden: 372.0M(372.0M)->0.0B(368.0M) Survivors: 36.0M->40.0M Heap: 6631.7M(8192.0M)->6262.8M(8192.0M)]  [Times: user=0.42 sys=0.01, real=0.05 secs]     ......    ...... 2014-10-08T04:34:59.344-0400: 1311735.724: [GC pause (mixed), 0.0666200 secs]    [Parallel Time: 60.4 ms, GC Workers: 8]       [GC Worker Start (ms): Min: 1311735724.4, Avg: 1311735724.5, Max: 1311735724.5, Diff: 0.2]       [Ext Root Scanning (ms): Min: 10.1, Avg: 13.0, Max: 19.3, Diff: 9.2, Sum: 104.3]       [Update RS (ms): Min: 0.0, Avg: 4.5, Max: 6.6, Diff: 6.6, Sum: 35.6]          [Processed Buffers: Min: 0, Avg: 9.1, Max: 20, Diff: 20, Sum: 73]       [Scan RS (ms): Min: 3.5, Avg: 4.8, Max: 5.1, Diff: 1.6, Sum: 38.7]       [Object Copy (ms): Min: 37.1, Avg: 37.6, Max: 38.4, Diff: 1.3, Sum: 301.1]       [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]       [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.1]       [GC Worker Total (ms): Min: 60.0, Avg: 60.1, Max: 60.2, Diff: 0.2, Sum: 481.1]       [GC Worker End (ms): Min: 1311735784.5, Avg: 1311735784.6, Max: 1311735784.7, Diff: 0.2]    [Code Root Fixup: 0.0 ms]    [Clear CT: 2.2 ms]    [Other: 4.0 ms]       [Choose CSet: 0.1 ms]       [Ref Proc: 1.9 ms]       [Ref Enq: 0.0 ms]       [Free CSet: 0.9 ms]    [Eden: 372.0M(372.0M)->0.0B(368.0M) Survivors: 36.0M->40.0M Heap: 6633.2M(8192.0M)->6254.9M(8192.0M)]------------------------------------------The reason for this unexpected behaviour is that G1 tries to select minimal number of old regions in the collection-set so that it can do the evacuation pauses within the specified pause time goal. Due to this, it fails to clean up the garbage in the old regions, and hence the increased heap usage. To overcome this side effect with G1, if one does not have very strict pause time goals, the young generation size can be increased so that most of the die-young objects get collected in the young regions itself and don't get promoted to the old generation. One can also try relaxing the pause time goals so that G1 includes more number of old regions in the collection set and good amount of garbage gets collected with the evacuation pauses.

G1 garbage collector is a predictable low pause collector that works efficiently to achieve the low pause time goals. To meet the set pause time goals, G1 tries to: pick only those many old heap...

Running on a 64bit platform and still running out of memory

It sounds strange that one is running with 64bit JVM but still running out of native memory or Java Heap space. On a 64bit machine, with 64bit JVM we get almost unlimited memory then how is it possible to run out of memory? Well, it may happen in certain situations.HotSpot JVM has a feature called CompressedOops with which it uses 32-bit (compressed) pointers on 64-bit platforms to have smaller footprints and better performance on 64-bit platforms. 64-bit address values are stored into 32-bit pointers using an encoding and are retrieved back using the corresponding decoding.CompressedOops implementation tries to allocate Java Heap using different strategies based on the heap size and the platform it runs on. If the heap size is less than 4Gb then it tries to allocate it into low virtual address space (below 4Gb) so that the compressed oops can be used without encoding/decoding. If it fails or heap size > 4Gb then it tries to allocate the heap below 32Gb to use zero based compressed oops. If this also fails then it switches to regular compressed oops with narrow oop base.The heap base where the Java Heap would be based at is computed by the JVM function Universe::preferred_heap_base():http://hg.openjdk.java.net/jdk8/jdk8/hotspot/file/87ee5ee27509/src/share/vm/memory/universe.cpp#l672Heap base computation depends on the heap size and the HeapBaseMinAddress value for the platform we are running on. If the heap_size+HeapBaseMinAddress can fit in the first 4G address space, then heap is allocated below 4G. Then it checks if it can fit under 32G boundary otherwise java heap is allocated in the higher addresses.In doing so, it puts a cap on the size that the native memory can grow up to, and also limits the growth of the Java Heap, and this may lead to out of memory errors for memory intensive applications. The following process map shows that the java heap is allocated just next to the native heap.0000000100000000          8K r-x--  /sw/.es-base/sparc/pkg/jdk-1.7.0_60/bin/sparcv9/java0000000100100000          8K rwx--  /sw/.es-base/sparc/pkg/jdk-1.7.0_60/bin/sparcv9/java0000000100102000         56K rwx--    [ heap ]0000000100110000       2624K rwx--    [ heap ]   <--- native Heap00000001FB000000      24576K rw---    [ anon ]   <--- Java Heap starts here0000000200000000    1396736K rw---    [ anon ]0000000600000000     700416K rw---    [ anon ] Workarounds for this situation:1. Run with -XX:-UseCompressedOops (keeping in mind that you would lose the performance benefit that comes with enabling CompressedOops). This will instruct the JVM to run without the Compressed Oops feature and it would not try to fit the Java Heap in the first 4GB of heap.2. Keep the CompressedOops and set the base of the Java Heap with the JVM option -XX:HeapBaseMinAddress=n to specify the address where the Java Heap should start from. If you are running out of native memory, set it to a higher address so that there is enough room available for the native mallocs, and if Java Heap is getting exhausted then set it to a lower value. And if you need java heap to be allocated beyond 4GB or 32GB then HeapBaseMinAddress should be set to a value so that HeapBaseMinAddress + heap size > 4GB or 32GB.The default value of HeapBaseMinAddress on most of the platforms is 2GB. Let's run a simple test program on solaris-sparc 10 and solaris-x64 11 and see where the Java Heap is placed on these platforms when using CompressedOops. On Solaris-sparc 10 with JDK 1.7.0_67 % uname -aSunOS svr 5.10 Generic_148888-03 sun4v sparc SUNW,Sun-Fire-T200 % java -versionjava version "1.7.0_67"Java(TM) SE Runtime Environment (build 1.7.0_67-b32)Java HotSpot(TM) Server VM (build 24.65-b04, mixed mode)% java -d64 -XX:+PrintCommandLineFlags -XX:+PrintFlagsFinal TestClass &[3] 22638% -XX:InitialHeapSize=266338304 -XX:MaxHeapSize=4261412864 -XX:+PrintCommandLineFlags -XX:+PrintFlagsFinal -XX:+UseCompressedOops -XX:+UseParallelGC[Global flags]    uintx AdaptivePermSizeWeight                    = 20              {product}    ...<snip>..    uintx GCTimeRatio                               = 99              {product}    uintx HeapBaseMinAddress                        = 4294967296      {pd product}    bool HeapDumpAfterFullGC                        = false           {manageable}    ....<snip>...    Heap Parameters:ParallelScavengeHeap [ PSYoungGen [ eden =  [0xffffffff1e800000,0xffffffff1ebf5d88,0xffffffff22a00000] , from =  [0xffffffff23500000,0xffffffff23500000,0xffffffff24000000] , to =  [0xffffffff22a00000,0xffffffff22a00000,0xffffffff23500000]  ] PSOldGen [  [0xfffffffe75400000,0xfffffffe75400000,0xfffffffe7fc00000]  ] PSPermGen [  [0xfffffffe70400000,0xfffffffe706843a0,0xfffffffe71c00000]  ] The default value of HeapBaseMinAddress is 4GB here and the Java Heap is allocated in the higher virtual address space. On Solaris-x64 11 with JDK 1.7.0_67bash-4.1$ uname -aSunOS hsdev-15 5.11 11.0 i86pc i386 i86pcbash-4.1$ java -d64 -XX:+PrintCommandLineFlags -XX:+PrintFlagsFinal TestClass &[1] 6049bash-4.1$ -XX:InitialHeapSize=805015296 -XX:MaxHeapSize=12880244736 -XX:+PrintCommandLineFlags -XX:+PrintFlagsFinal -XX:+UseCompressedOops -XX:+UseParallelGC[Global flags]    ....    uintx GCTimeRatio                               = 99              {product}    uintx HeapBaseMinAddress                        = 268435456       {pd product}    bool HeapDumpAfterFullGC                       = false           {manageable}    ....bash-4.1$ java -d64 -classpath $JAVA_HOME/lib/sa-jdi.jar sun.jvm.hotspot.CLHSDB 6049Attaching to process 6049, please wait...hsdb> universeHeap Parameters:ParallelScavengeHeap [ PSYoungGen [ eden =  [0x0000000700000000,0x00000007007ae238,0x000000070c000000] , from =  [0x000000070e000000,0x000000070e000000,0x0000000710000000] , to =  [0x000000070c000000,0x000000070c000000,0x000000070e000000]  ] PSOldGen [  [0x0000000500400000,0x0000000500400000,0x0000000520200000]  ] PSPermGen [  [0x00000004fb200000,0x00000004fb483380,0x00000004fc800000]  ]bash-4.1$ pmap 60490000000000400000          4K r-x--  /java/bin/amd64/java0000000000410000          4K rw---  /java/bin/amd64/java0000000000411000       2288K rw---    [ heap ]00000004FB200000      22528K rw---    [ anon ]0000000500400000     522240K rw---    [ anon ]0000000700000000     262144K rw---    [ anon ]Here, the default value of HeapBaseMinAddress is 256MB and the Java Heap is allocated in the 32G address space. On Solaris-x64 11 with JDK 1.8.0_20 bash-4.1$ java -versionjava version "1.8.0_20"Java(TM) SE Runtime Environment (build 1.8.0_20-b26)Java HotSpot(TM) 64-Bit Server VM (build 25.20-b23, mixed mode)bash-4.1$ java -d64 -XX:+PrintCommandLineFlags -XX:+PrintFlagsFinal TestClass &[1] 19069bash-4.1$ -XX:InitialHeapSize=805015296 -XX:MaxHeapSize=12880244736 -XX:+PrintCommandLineFlags -XX:+PrintFlagsFinal -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC[Global flags]    uintx AdaptiveSizeDecrementScaleFactor          = 4                                   {product}    ....    uintx GCTimeRatio                               = 99                                  {product}    uintx HeapBaseMinAddress                        = 2147483648                          {pd product}    bool HeapDumpAfterFullGC                        = false                               {manageable}    .....bash-4.1$ java -d64 -classpath $JAVA_HOME/lib/sa-jdi.jar sun.jvm.hotspot.CLHSDB 19069Attaching to process 19069, please wait...hsdb> universeHeap Parameters:ParallelScavengeHeap [ PSYoungGen [ eden =  [0x00000006c0200000,0x00000006c190a4d8,0x00000006cc200000] , from =  [0x00000006ce200000,0x00000006ce200000,0x00000006d0200000] , to =  [0x00000006cc200000,0x00000006cc200000,0x00000006ce200000]  ] PSOldGen [  [0x00000004c0400000,0x00000004c0400000,0x00000004e0400000]  ]  ]bash-4.1$ pmap 1906919069:  java -d64 -XX:+PrintCommandLineFlags -XX:+PrintFlagsFinal TestClass0000000000411000       3696K rw---    [ heap ]00000004C0400000     524288K rw---    [ anon ]00000006C0200000     262144K rw---    [ anon ]00000007C0000000        512K rw---    [ anon ] Here, HeapBaseMinAddress is 2GB by default and heap is allocated in the first 32GB address space. The default value of HeapBaseMinAddress for Solaris-x64 systems in jdk1.7.0_xx is 256M. It has been changed to 2G in jdk8 with the following bug fix: https://bugs.openjdk.java.net/browse/JDK-8013938. 

It sounds strange that one is running with 64bit JVM but still running out of native memory or Java Heap space. On a 64bit machine, with 64bit JVM we get almost unlimited memory then how is it...

About G1 Garbage Collector, Permanent Generation and Metaspace

We received some questions around the G1 garbage collectorand the use of Permanent Generation with it. There seems to be some confusionthat the Hotspot JVM does not use permanent generation when G1 is used as the garbagecollector. Here’s some clarification: JDK 7: PermGen Permanent Generation still exists in JDK 7 and its updates,and is used by all the garbage collectors. In JDK7, the effort to remove thepermanent generation was started and some parts of the data residing in thepermanent generation were moved to either the Java Heap or to the native heap.Permanent generation was not completely removed and it still exists in JDK 7and its updates. Here's the list of things that were moved out of the permanentgeneration in JDK7: Symbols were moved to the native heap Interned strings were moved to the Java Heap Class statics were moved to the Java Heap JDK7: G1 and PermGen With G1 collector, PermGen is collected only at a Full GCwhich is a stop-the-world (STW) GC. IfG1 is running optimally then it does not do Full GCs. G1 invokes the Full GCsonly when the PermGen is full or when the application does allocations fasterthan G1 can concurrently collect garbage. With CMS garbage collector, we can use option-XX:+CMSClassUnloadingEnabled to collect PermGen space in the CMS concurrentcycle. There is no equivalent option for G1. G1 only collects PermGen during the Full stop-the-world GCs. We can use options PermSize and MaxPermSize to tune thePermGen space size according to the application needs. JDK8: PermGen Permanent generation has been completely removed in JDK 8.This work has been done under the bughttps://bugs.openjdk.java.net/browse/JDK-6964458. Options PermSize andMaxPermSize have also been removed in JDK 8. Email to openjdk alias regarding the PermGen eliminationproject: http://mail.openjdk.java.net/pipermail/hotspot-dev/2012-September/006679.html JDK8: Metaspace In JDK 8, classes metadata is now stored in the native heapand this space is called Metaspace. There are some new flags added forMetaspace in JDK 8: -XX:MetaspaceSize=<NNN> where <NNN> is the initial amount of space(the initial high-water-mark) allocated for class metadata (in bytes) that may induce a garbage collection to unload classes. The amount is approximate. After the high-water-mark is first reached, the next high-water-mark is managed by the garbage collector -XX:MaxMetaspaceSize=<NNN> where <NNN> is the maximum amount of space to be allocated for class metadata (in bytes). This flag can be used to limit the amount of space allocated for class metadata. This value is approximate. By default there is no limit set. -XX:MinMetaspaceFreeRatio=<NNN> where <NNN> is the minimum percentage of class metadata capacity free after a GC to avoid an increase in the amount of space (high-water-mark) allocated for class metadata that will induce a garbage collection. -XX:MaxMetaspaceFreeRatio=<NNN> where <NNN> is the maximum percentage of class metadata capacity free after a GC to avoid a reduction in the amount of space (high-water-mark) allocated for class metadata that will induce a garbage collection. By default classmetadata allocation is only limited by the amount of available native memory. Wecan use the new option MaxMetaspaceSize to limit the amount of native memoryused for the class metadata. It is analogous to MaxPermSize. A garbage collection is induced to collect the dead classloadersand classes when the class metadata usage reaches MetaspaceSize (12Mbytes onthe 32bit client VM and 16Mbytes on the 32bit server VM with larger sizes onthe 64bit VMs). Set MetaspaceSize to a higher value to delay the inducedgarbage collections. After an induced garbage collection, the class metadata usageneeded to induce the next garbage collection may be increased.

We received some questions around the G1 garbage collector and the use of Permanent Generation with it. There seems to be some confusionthat the Hotspot JVM does not use permanent generation when G1...

UseLargePages on Linux

There is a JVM option UseLargePages (introduced in JDK 5.0u5) that can be used to request large memory pages from the system if large pages memory is supported by the system. The goal of the large page support is to optimize processor Translation-Lookaside Buffers and hence increase performance. Recently we saw few instances of HotSpot crashes with JDK7 on the Linux platform when using the large memory pages. 8013057: assert(_needs_gc || SafepointSynchronize::is_at_safepoint()) failed: only read at safepointhttps://bugs.openjdk.java.net/browse/JDK-8013057 8007074: SIGSEGV at ParMarkBitMap::verify_clear() https://bugs.openjdk.java.net/browse/JDK-8007074 Cause: The cause of these crashes is the way mmap works on the Linux platform. If the large page support is enabled on the system, commit_memory() implementation of HotSpot on Linux platform tries to commit the earlier reserved memory with 'mmap' call using the large pages. If there are not enough number of large pages available, the mmap call fails releasing the reserved memory, allowing the same memory region to be used for other allocations. This causes the same memory region to be used for different purposes and leads to unexpected behaviors. Symptoms: With the above mentioned issue, we may see crashes with stack traces something like this: V  [libjvm.so+0x759a1a]  ParMarkBitMap::mark_obj(HeapWord*, unsigned long)+0x7a V  [libjvm.so+0x7a116e]  PSParallelCompact::MarkAndPushClosure::do_oop(oopDesc**)+0xce V  [libjvm.so+0x485197]  frame::oops_interpreted_do(OopClosure*, RegisterMap const*, bool)+0xe7 V  [libjvm.so+0x863a4a]  JavaThread::oops_do(OopClosure*, CodeBlobClosure*)+0x15a V  [libjvm.so+0x77c97e]  ThreadRootsMarkingTask::do_it(GCTaskManager*, unsigned int)+0xae V  [libjvm.so+0x4b7ec0]  GCTaskThread::run()+0x130 V  [libjvm.so+0x748f90]  java_start(Thread*)+0x100Here the crash happens while writting to an address 0x00007f2cf656eef0 in the mapped region of ParMarkBitMap. And that memory belongs to the rt.jar (from hs_err log file):7f2cf6419000-7f2cf65d7000 r--s 039dd000 00:31 106601532                  /jdk/jdk1.7.0_21/jre/lib/rt.jarDue to this bug, the same memory region got mapped for two different allocations and caused this crash.Fixes: 8013057 strengthened the error handling of mmap failures on Linux platform and also added some diagnostic information for these failures. It is fixed in 7u40. 8007074 fixes the reserved memory mapping loss issue when using the large pages on the Linux platform. Details on this fix: http://mail.openjdk.java.net/pipermail/hotspot-dev/2013-July/010117.html. It is fixed in JDK 8 and will also be included into 7u60, scheduled to be released in May 2014.Workarounds:1. Disable the use of large pages with JVM option -XX:-UseLargePages.2. Increase the number of large pages available on the system. By having the sufficient number of large pages on the system, we can reduce the risk of memory commit failures and thus reduce the chances of hitting the large pages issue. Please see the details on how to configure the number of large pages here:http://www.oracle.com/technetwork/java/javase/tech/largememory-jsp-137182.htmlOther related fixes: 8026887: Make issues due to failed large pages allocations easier to debug https://bugs.openjdk.java.net/browse/JDK-8026887With the fix of 8013057, diagnostic information for the memory commit failures was added. It printed the error messages something like this:os::commit_memory(0x00000006b1600000, 352321536, 2097152, 0) failed;error='Cannot allocate memory' (errno=12)With this fix of 8026887, this error message has been modified to suggest that the memory commit failed due to the lack of large pages, and it now looks like the following:os::commit_memory(0x00000006b1600000, 352321536, 2097152, 0) failed;error='Cannot allocate large pages, falling back to small pages' (errno=12) This change has been integrated into 7u51. The fix for 8007074 will be available in 7u60 and could not be included into 7u51, so this change (JDK-8026887) makes the error messages printed for the large pages related commit memory failures more informative. If we see these messages in the JVM logs that indicates that we have the risk of hitting the unexpected behaviors due to the bug 8007074. 8024838: Significant slowdown due to transparent huge pages https://bugs.openjdk.java.net/browse/JDK-8024838With the fix of 8007074, significant performance degradation was detected. This regression has been fixed with JDK-8024838 in JDK 8 and will also be included in JDK 7u60.

There is a JVM option UseLargePages (introduced in JDK 5.0u5) that can be used to request large memory pages from the system if large pages memory is supported by the system. The goal of the large...

Troubleshooting Long GC Pauses

Low pause times during the application run is the mostimportant goal for many enterprise applications, especially forthe transaction-based systems where long latencies can result in the transactiontime-outs. For systems running on the Java Virtual Machines, garbagecollections can sometimes be the cause of the long pauses. In this post I am going to describe different scenarioswhere we can encounter long GC pauses and how we can diagnose and troubleshootthese GC pauses. Causes Following are the different situations that can cause longGC pauses during the application run. 1. Fragmentation in the heap Fragmentation in the Java Heap can cause GCs to occur morefrequently and also sometimes causing long pauses in the GCs. This is moreprobable in the case of Concurrent Mark Sweep collector, also known as CMS,where the tenured generation space is not compacted with the concurrentcollections. In case of the CMS, due to fragmentation in the tenuredgeneration space, the young generation collections can face promotion failuresand thus triggering 'Concurrent Mode Failure' collections that arestop-the-world Full GCs, and Full GCs take a long time to finish as compared tothe concurrent collection pauses. Due to the fragmentation, the direct allocations in thetenured generation may fail even when there is lot of free space available andthus causing Full GCs. Fragmentation can also cause frequent allocation failuresand thus triggering frequent Full GCs that increase the overall time theapplication is paused for. The following logs collected with the CMS collector showthat the fragmentation in the CMS generation space is very high, that leads tothe promotion failure during a young generation ParNew collection and then a'concurrent mode failure'. A Full GC is done in the event of 'concurrent modefailure' that takes a very long time, 17.1365396 seconds to finish. {Heap before GC invocations=7430 (full 24): par newgeneration total 134400K, used 121348K[0x53000000, 0x5c600000, 0x5c600000) eden space115200K, 99% used [0x53000000,0x5a07e738, 0x5a080000) from space19200K, 32% used [0x5a080000,0x5a682cc0, 0x5b340000) to space 19200K, 0% used [0x5b340000, 0x5b340000, 0x5c600000) concurrentmark-sweep generation total 2099200K, used 1694466K [0x5c600000, 0xdc800000, 0xdc800000) concurrent-mark-sweep perm gen total 409600K,used 186942K [0xdc800000, 0xf5800000, 0xfbc00000) 10628.167: [GC Before GC: Statistics for BinaryTreeDictionary: ------------------------------------ Total Free Space: 103224160 Max Chunk Size:5486 Number of Blocks: 57345 Av. Block Size: 1800 Tree Height:36 Statistics for IndexedFreeLists: -------------------------------- Total Free Space: 371324 Max Chunk Size:254 Number of Blocks: 8591 <---- High fragmentation Av. Block Size: 43 free=103595484frag=1.0000 <---- High fragmentation Before GC: Statistics for BinaryTreeDictionary: ------------------------------------ Total Free Space: 0 Max Chunk Size: 0 Number of Blocks: 0 Tree Height: 0 Statistics for IndexedFreeLists: -------------------------------- Total Free Space: 0 Max Chunk Size: 0 Number of Blocks: 0 free=0 frag=0.0000 10628.168: [ParNew (promotion failed) Desired survivor size 9830400 bytes, new threshold 1 (max1) - age 1: 4770440 bytes, 4770440 total : 121348K->122157K(134400K), 0.4263254 secs]10628,594:[CMS10630.887: [CMS-concurrent-mark: 7.286/8.682 secs] [Times: user=14.81sys=0.34, real=8.68 secs] (concurrent mode failure):1698044K->625427K(2099200K), 17.1365396 secs]1815815K->625427K(2233600K), [CMS Perm : 186942K->180711K(409600K)]AfterGC: Statistics for BinaryTreeDictionary: ------------------------------------ Total Free Space: 377269492 Max Chunk Size:377269492 Number of Blocks: 1 Av. Block Size: 377269492 Tree Height: 1 Statistics for IndexedFreeLists: -------------------------------- Total Free Space: 0 Max Chunk Size: 0 Number of Blocks: 0 free=377269492frag=0.0000 After GC: Statistics for BinaryTreeDictionary: ------------------------------------ Total Free Space: 0 Max Chunk Size: 0 Number of Blocks: 0 Tree Height: 0 Statistics for IndexedFreeLists: -------------------------------- Total Free Space: 0 Max Chunk Size: 0 Number of Blocks: 0 free=0 frag=0.0000 , 17.5645589 secs] [Times: user=17.82 sys=0.06,real=17.57 secs] Heap after GC invocations=7431 (full 25): par newgeneration total 134400K, used 0K[0x53000000, 0x5c600000, 0x5c600000) eden space115200K, 0% used [0x53000000,0x53000000, 0x5a080000) from space19200K, 0% used [0x5b340000,0x5b340000, 0x5c600000) to space 19200K, 0% used [0x5a080000, 0x5a080000, 0x5b340000) concurrentmark-sweep generation total 2099200K, used 625427K [0x5c600000, 0xdc800000,0xdc800000) concurrent-mark-sweep perm gen total 409600K,used 180711K [0xdc800000, 0xf5800000, 0xfbc00000) } Total time for which application threads were stopped:17.5730653 seconds 2. Other OS activities happening at the time of GC Sometimes the OS activities such as the swap space ornetworking activity happening at the time when GC is taking place can make theGC pauses last much longer. These pauses can be of the order of few seconds tosome minutes. If your system is configured to use swap space, OperatingSystem may move inactive pages of memory of the JVM process to the swap space,to free up memory for the currently active process which may be the sameprocess or a different process on the system. Swapping is very expensive as itrequires disk accesses which are much slower as compared to the physical memoryaccess. So, if during a garbage collection the system needs to performswapping, the GC would seem to run for a very long time. Following is the log of a young generation collection thatlasts for 29.47 seconds. {Heap before GC invocations=132 (full 0): par newgeneration total 2696384K, used2696384K [0xfffffffc20010000, 0xfffffffce0010000, 0xfffffffce0010000) eden space2247040K, 100% used [0xfffffffc20010000, 0xfffffffca9270000,0xfffffffca9270000) from space449344K, 100% used [0xfffffffca9270000, 0xfffffffcc4940000, 0xfffffffcc4940000) to space 449344K, 0% used [0xfffffffcc4940000,0xfffffffcc4940000, 0xfffffffce0010000) concurrentmark-sweep generation total 9437184K, used 1860619K [0xfffffffce0010000,0xffffffff20010000, 0xffffffff20010000) concurrent-mark-sweep perm gen total 1310720K,used 511451K [0xffffffff20010000, 0xffffffff70010000, 0xffffffff70010000) 2013-07-17T03:58:06.601-0700: 51522.120: [GC Before GC: :2696384K->449344K(2696384K), 29.4779282 secs]4557003K->2326821K(12133568K) ,29.4795222 secs] [Times: user=915.56sys=6.35, real=29.48 secs] Corresponding 'vmstat' output at 03:58: kthr memory page disk faults cpu r b w swap free re mf pipo fr de sr s0 s1 s2 s3 in sy cs us sy id 20130717_035806 0 0 0 77611960 94847600 55 266 0 0 0 0 00 0 0 0 3041 2644 2431 44 8 48 20130717_035815 0 0 0 76968296 94828816 79 324 0 18 18 00 0 0 1 0 3009 3642 2519 59 13 28 20130717_035831 1 0 0 77316456 94816000 389 2848 0 7 7 00 0 0 2 0 40062 78231 61451 42 6 53 20130717_035841 2 0 0 77577552 94798520 115 591 0 13 13 00 13 12 1 0 4991 8104 5413 2 0 98 This minor GC takes around 29 secs to complete. Thecorresponding vmstat output shows that the available swap space drops down by~600mb during this period. That means during this garbage collection some pagesfrom the RAM were moved out to the swap space, not necessarily by the sameprocess running on the system. From the above, it is clear that the physical memoryavailable on the system is not enough for all the processes running on thesystem. The way to resolve this is to run fewer processes or if possible, addmore RAM to increase the physical memory of the system. In the case above, thespecified maximum tenured generation size is set as 9G and out of that only1.8G is occupied. So it makes sense to reduce the heap size to lower the memorypressure on the physical memory so as to avoid or minimize the swappingactivity. Apart from swapping, we should monitor if there is any i/oor network activity happening during the long GC pauses. These can be monitoredusing iostat and netstat tools. It is also helpful to see the CPU statisticswith the mpstat tool to figure out if enough CPU resources were availableduring the GC pauses. 3. Insufficient heap size If the application footprint is larger than the maximum heapspace that we have specified for the JVM, it results in frequent collections.Due to the insufficient heap space, the allocation requests fail and the JVMneeds to invoke garbage collections in an attempt to reclaim space for theallocations. But since it cannot claim much space with each collection,subsequent allocation failures result in more GC invocations. These frequent Full GCs cause long pauses in the applicationrun. For example, in the following case, the permanent generation is almostfull and the allocation attempts into the permanent generation are failing,triggering the Full GCs. 166687.013: [Full GC [PSYoungGen:126501K->0K(922048K)] [PSOldGen: 2063794K->1598637K(2097152K)]2190295K->1598637K(3019200K) [PSPermGen: 165840K->164249K(166016K)],6.8204928 secs] [Times: user=6.80 sys=0.02, real=6.81 secs] 166699.015: [Full GC [PSYoungGen:125518K->0K(922048K)] [PSOldGen: 1763798K->1583621K(2097152K)]1889316K->1583621K(3019200K) [PSPermGen: 165868K->164849K(166016K)],4.8204928 secs] [Times: user=4.80 sys=0.02, real=4.81 secs] Similarly, the frequent Full GCs can occur if there isinsufficient space in the tenured generation for the allocations or promotions. The solution for these long pauses is to identify theaverage footprint of the application and then specify the heap sizeaccordingly. 4. Bug in the JVM Sometimes these long pauses could be due to a bug in theJVM. For example, due to the following bugs in the JVM, Java applications mayface long GC pauses. 6459113: CMS+ParNew: wildly different ParNewpause times depending on heap shape caused by allocation spread fixedin JDK 6u1 and 7 6572569: CMS: consistently skewed workdistribution indicated in (long) re-mark pauses fixedin JDK 6u4 and 7 6631166: CMS: better heuristics when combattingfragmentation fixedin JDK 6u21 and 7 6999988: CMS: Increased fragmentation leading topromotion failure after CR#6631166 got implemented fixedin JDK 6u25 and 7 6683623: G1: use logarithmic BOT code such asused by other collectors fixedin JDK 6u14 and 7 6976350: G1: deal with fragmentation whilecopying objects during GC fixedin JDK 8 If you are running with a JVM version affected with thesebugs, please upgrade to the version where these bugs are fixed. 5. Explicit System GCs Check if there are any explicit System GCs happening.Requests to invoke these System GCs which are stop-the-world Full GCs could becoming from the System.gc() calls from some class in the application or from asome third party module. These explicit System GCs too can cause very longpauses. 164638.058: [Full GC (System) [PSYoungGen: 22789K->0K(992448K)][PSOldGen: 1645508K->1666990K(2097152K)] 1668298K->1666990K(3089600K)[PSPermGen: 164914K->164914K(166720K)], 5.7499132 secs] [Times: user=5.69sys=0.06, real=5.75 secs] If you are using RMI and are observing explicit Full GCs ona regular interval, then these are coming from the RMI implementation thattriggers System.gc() on a regular interval. This interval can be configuredusing the following system properties: -Dsun.rmi.dgc.server.gcInterval=n -Dsun.rmi.dgc.client.gcInterval=n The default value for these properties in JDK 1.4.2 and 5.0is 60000 milliseconds, and 3600000 milliseconds in JDK 6 and later releases. If you want to disable the explicit Full GCs invoked usingSystem.gc(), run the application with -XX:+DisableExplicitGC JVM option. How to approach the problem 1. Collect GC logs with -XX:+PrintGCDetails -XX:+PrintHeapAtGC-XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps and -XX:+PrintGCApplicationStoppedTime.In case of the CMS collector, add option -XX:PrintFLSStatistics=2 as well. The GC logs can give us details on the nature and the frequencyof the GC pauses i.e. they can provide answers to the questions like - are the longGC pauses occurring during young collections or old collections, and howfrequently those collections are encountering long pauses. 2. Monitor the overall health of the system using OS toolslike vmstat, iostat, netstat and mpstat etc. on Solaris and Linux platforms, andtools like Process Monitorand Task Manager on the Windows operating system. 3. Use GCHistotool to visually analyze the GC Logs and figure out which GCs are taking longtime and if there is a pattern in the occurrence of these collections. 4. Try to see from the GC logs if there are any signs offragmentation in the Java Heap space. 5. Monitor if the specified Heap size is enough to containthe footprint of the application. 6. Check if you are running with a JVM that has a known bugrelated to the long GC pauses and then upgrade if that bug is fixed in a laterversion.

Low pause times during the application run is the most important goal for many enterprise applications, especially for the transaction-based systems where long latencies can result in the transactionti...

Understanding G1 GC Logs

Thepurpose of this post is to explain the meaning of GC logsgenerated with some tracing and diagnostic options for G1 GC. We willtake a look at the output generated with PrintGCDetails which is aproduct flag and provides the most detailed level of information.Along with that, we will also look at the output of two diagnosticflags that get enabled with -XX:+UnlockDiagnosticVMOptions option - G1PrintRegionLivenessInfothat prints the occupancy and the amount of space used by liveobjects in each region at the end of the marking cycle andG1PrintHeapRegions that provides detailed information on the heapregions being allocated and reclaimed. Wewill be looking at the logs generated with JDK 1.7.0_04 using theseoptions. Option-XX:+PrintGCDetails Here's a sample log of G1 collection generated with PrintGCDetails. 0.522: [GC pause (young), 0.15877971 secs] [Parallel Time: 157.1 ms] [GC Worker Start (ms): 522.1 522.2 522.2 522.2 Avg: 522.2, Min: 522.1, Max: 522.2, Diff: 0.1] [Ext Root Scanning (ms): 1.6 1.5 1.6 1.9 Avg: 1.7, Min: 1.5, Max: 1.9, Diff: 0.4] [Update RS (ms): 38.7 38.8 50.6 37.3 Avg: 41.3, Min: 37.3, Max: 50.6, Diff: 13.3] [Processed Buffers : 2 2 3 2 Sum: 9, Avg: 2, Min: 2, Max: 3, Diff: 1] [Scan RS (ms): 9.9 9.7 0.0 9.7 Avg: 7.3, Min: 0.0, Max: 9.9, Diff: 9.9] [Object Copy (ms): 106.7 106.8 104.6 107.9 Avg: 106.5, Min: 104.6, Max: 107.9, Diff: 3.3] [Termination (ms): 0.0 0.0 0.0 0.0 Avg: 0.0, Min: 0.0, Max: 0.0, Diff: 0.0] [Termination Attempts : 1 4 4 6 Sum: 15, Avg: 3, Min: 1, Max: 6, Diff: 5] [GC Worker End (ms): 679.1 679.1 679.1 679.1 Avg: 679.1, Min: 679.1, Max: 679.1, Diff: 0.1] [GC Worker (ms): 156.9 157.0 156.9 156.9 Avg: 156.9, Min: 156.9, Max: 157.0, Diff: 0.1] [GC Worker Other (ms): 0.3 0.3 0.3 0.3 Avg: 0.3, Min: 0.3, Max: 0.3, Diff: 0.0] [Clear CT: 0.1 ms] [Other: 1.5 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.3 ms] [Ref Enq: 0.0 ms] [Free CSet: 0.3 ms] [Eden: 12M(12M)->0B(10M) Survivors: 0B->2048K Heap: 13M(64M)->9739K(64M)] [Times: user=0.59 sys=0.02, real=0.16 secs] This is the typical log of an Evacuation Pause (G1 collection)in which live objects are copied from one set of regions (young ORyoung+old) to another set. It is a stop-the-world activity and allthe application threads are stopped at a safepoint during this time. This pause is made up of several sub-tasks indicated by theindentation in the log entries. Here's is the top most line that getsprinted for the Evacuation Pause. 0.522:[GC pause (young), 0.15877971 secs] This is the highest level information telling us that it is anEvacuation Pause that started at 0.522 secs from the start of theprocess, in which all the regions being evacuated are Young i.e. Edenand Survivor regions. This collection took 0.15877971 secs tofinish. EvacuationPauses can be mixed as well. In which case the set of regionsselected include all of the young regions as well as some oldregions. 1.730:[GC pause (mixed), 0.32714353 secs] Let's take a look at all the sub-tasks performed in this EvacuationPause. [Parallel Time: 157.1 ms] Parallel Time is the total elapsed time spent by all the parallel GCworker threads. The following lines correspond to the parallel tasksperformed by these worker threads in this total parallel time, whichin this case is 157.1 ms. [GC Worker Start (ms): 522.1 522.2 522.2 522.2Avg: 522.2, Min: 522.1, Max: 522.2, Diff: 0.1] The first line tells us the start time of each of the worker threadin milliseconds. The start times are ordered with respect to theworker thread ids – thread 0 started at 522.1ms and thread 1started at 522.2ms from the start of the process. The second linetells the Avg, Min, Max and Diff of the start times of all of theworker threads. [Ext Root Scanning (ms): 1.6 1.5 1.6 1.9 Avg: 1.7, Min: 1.5, Max: 1.9, Diff: 0.4] This gives us the time spent by each worker thread scanning the roots(globals, registers, thread stacks and VM data structures). Here,thread 0 took 1.6ms to perform the root scanning task and thread 1took 1.5 ms. The second line clearly shows the Avg, Min, Max and Diffof the times spent by all the worker threads. [Update RS (ms): 38.7 38.8 50.6 37.3 Avg: 41.3, Min: 37.3, Max: 50.6, Diff: 13.3] UpdateRS gives us the time each thread spent in updating the RememberedSets. Remembered Sets are the data structures that keep track of thereferences that point into a heap region. Mutator threads keepchanging the object graph and thus the references that point into aparticular region. We keep track of these changes in buffers calledUpdate Buffers. TheUpdate RS sub-task processes the update buffers that were not able tobe processed concurrently, and updates the corresponding rememberedsets of all regions. [Processed Buffers : 2 2 3 2Sum: 9, Avg: 2, Min: 2, Max: 3, Diff: 1] This tells us the number of Update Buffers (mentioned above)processed by each worker thread. [Scan RS (ms): 9.9 9.7 0.0 9.7 Avg: 7.3, Min: 0.0, Max: 9.9, Diff: 9.9] These are the times each worker thread had spent in scanning theRemembered Sets. Remembered Set of a region contains cards thatcorrespond to the references pointing into that region. This phasescans those cards looking for the references pointing into all theregions of the collection set. [Object Copy (ms): 106.7 106.8 104.6 107.9 Avg: 106.5, Min: 104.6, Max: 107.9, Diff: 3.3] These are the times spent by each worker thread copying live objectsfrom the regions in the Collection Set to the other regions. [Termination (ms): 0.0 0.0 0.0 0.0 Avg: 0.0, Min: 0.0, Max: 0.0, Diff: 0.0] Termination time is the time spent by the worker thread offering toterminate. But before terminating, it checks the work queues of otherthreads and if there are still object references in other workqueues, it tries to steal object references, and if it succeeds instealing a reference, it processes that and offers to terminateagain. [Termination Attempts : 1 4 4 6 Sum: 15, Avg: 3, Min: 1, Max: 6, Diff: 5] This gives the number of times each thread has offered to terminate. [GC Worker End (ms): 679.1 679.1 679.1 679.1 Avg: 679.1, Min: 679.1, Max: 679.1, Diff: 0.1] These are the times in milliseconds at which each worker threadstopped. [GC Worker (ms): 156.9 157.0 156.9 156.9 Avg: 156.9, Min: 156.9, Max: 157.0, Diff: 0.1] These are the total lifetimes of each worker thread. [GC Worker Other (ms): 0.3 0.3 0.3 0.3Avg: 0.3, Min: 0.3, Max: 0.3, Diff: 0.0] These are the times that each worker thread spent in performing someother tasks that we have not accounted above for the total ParallelTime. [Clear CT: 0.1 ms] This is the time spent in clearing the Card Table. This task isperformed in serial mode. [Other: 1.5 ms] Timespent in the some other tasks listed below. Thefollowing sub-tasks (which individually may be parallelized) areperformed serially. [Choose CSet: 0.0 ms] Time spent in selecting the regions for the Collection Set. [Ref Proc: 0.3 ms] Total time spent in processing Reference objects. [Ref Enq: 0.0 ms] Time spent in enqueuing references to the ReferenceQueues. [Free CSet: 0.3 ms] Time spent in freeing the collection set data structure. [Eden: 12M(12M)->0B(13M) Survivors: 0B->2048K Heap:14M(64M)->9739K(64M)] Thisline gives the details on the heap size changes with the EvacuationPause. This shows that Eden had the occupancy of 12M and its capacitywas also 12M before the collection. After the collection, itsoccupancy got reduced to 0 since everything is evacuated/promotedfrom Eden during a collection, and its target size grew to 13M. Thenew Eden capacity of 13M is not reserved at this point. This value isthe target size of the Eden. Regions are added to Eden as the demandis made and when the added regions reach to the target size, we startthe next collection. Similarly,Survivors had the occupancy of 0 bytes and it grew to 2048K after thecollection. The total heap occupancy and capacity was 14M and 64Mreceptively before the collection and it became 9739K and 64M afterthe collection. Apart from the evacuation pauses, G1 also performs concurrent-markingto build the live data information of regions. 1.416: [GC pause (young) (initial-mark), 0.62417980 secs]…....2.042: [GC concurrent-root-region-scan-start]2.067: [GC concurrent-root-region-scan-end, 0.0251507]2.068: [GC concurrent-mark-start]3.198: [GC concurrent-mark-reset-for-overflow]4.053: [GC concurrent-mark-end, 1.9849672 sec]4.055: [GC remark 4.055: [GC ref-proc, 0.0000254 secs], 0.0030184 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]4.088: [GC cleanup 117M->106M(138M), 0.0015198 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]4.090: [GC concurrent-cleanup-start]4.091: [GC concurrent-cleanup-end, 0.0002721] The first phase of a marking cycle is Initial Marking where all theobjects directly reachable from the roots are marked and this phaseis piggy-backed on a fully young Evacuation Pause. 2.042:[GC concurrent-root-region-scan-start] This marks the start of aconcurrent phase that scans the set of root-regions which aredirectly reachable from the survivors of the initial markingphase. 2.067:[GC concurrent-root-region-scan-end, 0.0251507] End of the concurrent root region scan phase and it lasted for 0.0251507 seconds. 2.068:[GC concurrent-mark-start] Start of the concurrent marking at 2.068 secs from the start of theprocess. 3.198:[GC concurrent-mark-reset-for-overflow] This indicates that the global marking stack had became full andthere was an overflow of the stack. Concurrent marking detected thisoverflow and had to reset the data structures to start the markingagain. 4.053:[GC concurrent-mark-end, 1.9849672 sec] End of the concurrent marking phase and it lasted for 1.9849672seconds. 4.055:[GC remark 4.055: [GC ref-proc, 0.0000254 secs], 0.0030184 secs] This corresponds to the remark phase which is a stop-the-world phase.It completes the left over marking work (SATB buffers processing)from the previous phase. In this case, this phase took 0.0030184 secsand out of which 0.0000254 secs were spent on Reference processing. 4.088:[GC cleanup 117M->106M(138M), 0.0015198 secs] Cleanup phase which is again a stop-the-world phase. It goes throughthe marking information of all the regions, computes the live datainformation of each region, resets the marking data structures andsorts the regions according to their gc-efficiency. In this example,the total heap size is 138M and after the live data counting it wasfound that the total live data size dropped down from 117M to 106M. 4.090:[GC concurrent-cleanup-start] This concurrent cleanup phase frees up the regions that were found tobe empty (didn't contain any live data) during the previousstop-the-world phase. 4.091:[GC concurrent-cleanup-end, 0.0002721] Concurrent cleanup phase took 0.0002721 secs to free up the emptyregions. Option-XX:G1PrintRegionLivenessInfo Now, let's look at the output generated with the flagG1PrintRegionLivenessInfo. This is a diagnostic option and getsenabled with -XX:+UnlockDiagnosticVMOptions.G1PrintRegionLivenessInfo prints the live data information of eachregion during the Cleanup phase of the concurrent-markingcycle. 26.896:[GC cleanup ###PHASE Post-Marking @ 26.896###HEAP committed: 0x02e00000-0x0fe00000 reserved:0x02e00000-0x12e00000 region-size: 1048576 Cleanup phase of the concurrent-marking cycle started at 26.896 secsfrom the start of the process and this live data information isbeing printed after the marking phase. Committed G1 heap ranges from0x02e00000 to 0x0fe00000 and the total G1 heap reserved by JVM isfrom 0x02e00000 to 0x12e00000. Each region in the G1 heap is of size1048576 bytes. ### type address-range used prev-live next-live gc-eff### (bytes) (bytes) (bytes) (bytes/ms) This is the header of the output that tells us about the type of theregion, address-range of the region, used space in the region, livebytes in the region with respect to the previous marking cycle, livebytes in the region with respect to the current marking cycle and theGC efficiency of that region. ### FREE 0x02e00000-0x02f00000 0 0 0 0.0 This is a Free region. ### OLD 0x02f00000-0x03000000 1048576 1038592 1038592 0.0 Old region with address-range from 0x02f00000 to 0x03000000. Totalused space in the region is 1048576 bytes, live bytes as per theprevious marking cycle are 1038592 and live bytes with respect to thecurrent marking cycle are also 1038592. The GC efficiency has beencomputed as 0. ### EDEN 0x03400000-0x03500000 20992 20992 20992 0.0 This is an Eden region. ### HUMS 0x0ae00000-0x0af00000 1048576 1048576 1048576 0.0### HUMC 0x0af00000-0x0b000000 1048576 1048576 1048576 0.0### HUMC 0x0b000000-0x0b100000 1048576 1048576 1048576 0.0### HUMC 0x0b100000-0x0b200000 1048576 1048576 1048576 0.0### HUMC 0x0b200000-0x0b300000 1048576 1048576 1048576 0.0### HUMC 0x0b300000-0x0b400000 1048576 1048576 1048576 0.0### HUMC 0x0b400000-0x0b500000 1001480 1001480 1001480 0.0 These are the continuous set of regions called Humongous regions forstoring a large object. HUMS (Humongous starts) marks the start ofthe set of humongous regions and HUMC (Humongous continues) tags thesubsequent regions of the humongous regions set. ### SURV 0x09300000-0x09400000 16384 16384 16384 0.0 This is a Survivor region. ###SUMMARY capacity: 208.00 MB used: 150.16 MB / 72.19 % prev-live:149.78 MB / 72.01 % next-live: 142.82 MB / 68.66 % At the end, a summary is printed listing the capacity, the used spaceand the change in the liveness after the completion of concurrentmarking. In this case, G1 heap capacity is 208MB, total used space is150.16MB which is 72.19% of the total heap size, live data in theprevious marking was 149.78MB which was 72.01% of the total heap sizeand the live data as per the current marking is 142.82MB which is68.66% of the total heap size. Option-XX:+G1PrintHeapRegions G1PrintHeapRegions optionlogs the regions related events when regions are committed, allocatedinto or are reclaimed. COMMIT/UNCOMMIT events G1HR COMMIT[0x6e900000,0x6ea00000]G1HR COMMIT [0x6ea00000,0x6eb00000] Here, the heap is being initialized or expanded and theregion (with bottom: 0x6eb00000 and end: 0x6ec00000) is being freshlycommitted. COMMIT events are always generated in order i.e. the nextCOMMIT event will always be for the uncommitted region with thelowest address. G1HR UNCOMMIT[0x72700000,0x72800000]G1HR UNCOMMIT [0x72600000,0x72700000] Opposite to COMMIT. The heap got shrunk at the end of aFull GC and the regions are being uncommitted. Like COMMIT, UNCOMMITevents are also generated in order i.e. the next UNCOMMIT event willalways be for the committed region with the highest address. GC Cycle events G1HR #StartGC 7G1HR CSET0x6e900000G1HR REUSE 0x70500000G1HR ALLOC(Old)0x6f800000G1HR RETIRE 0x6f800000 0x6f821b20G1HR #EndGC 7 This shows start and end of an Evacuation pause. Thisevent is followed by a GC counter tracking both evacuation pauses andFull GCs. Here, this is the 7th GC since the start of the process. G1HR #StartFullGC 17G1HRUNCOMMIT [0x6ed00000,0x6ee00000]G1HR POST-COMPACTION(Old)0x6e800000 0x6e854f58G1HR #EndFullGC 17 Shows start and end of a Full GC. This event is alsofollowed by the same GC counter as above. This is the 17th GC sincethe start of the process. ALLOC events G1HR ALLOC(Eden) 0x6e800000 The region with bottom 0x6e800000 just started beingused for allocation. In this case it is an Eden region and allocatedinto by a mutator thread. G1HR ALLOC(StartsH) 0x6ec000000x6ed00000G1HR ALLOC(ContinuesH) 0x6ed00000 0x6e000000 Regions being used for the allocation of Humongousobject. The object spans over two regions. G1HR ALLOC(SingleH) 0x6f9000000x6f9eb010 Single region being used for the allocation ofHumongous object. G1HR COMMIT[0x6ee00000,0x6ef00000]G1HR COMMIT [0x6ef00000,0x6f000000]G1HRCOMMIT [0x6f000000,0x6f100000]G1HR COMMIT[0x6f100000,0x6f200000]G1HR ALLOC(StartsH) 0x6ee000000x6ef00000G1HR ALLOC(ContinuesH) 0x6ef00000 0x6f000000G1HRALLOC(ContinuesH) 0x6f000000 0x6f100000G1HR ALLOC(ContinuesH)0x6f100000 0x6f102010 Here, Humongous object allocation request could not besatisfied by the free committed regions that existed in the heap, sothe heap needed to be expanded. Thus new regions are committed andthen allocated into for the Humongous object. G1HR ALLOC(Old) 0x6f800000 Old region started being used for allocation during GC. G1HR ALLOC(Survivor) 0x6fa00000 Region being used for copying old objects into during aGC. Note that Eden and Humongous ALLOC events are generatedoutside the GC boundaries and Old and Survivor ALLOC events aregenerated inside the GC boundaries. Other Events G1HR RETIRE 0x6e800000 0x6e87bd98 Retire and stop using the region having bottom0x6e800000 and top 0x6e87bd98 for allocation. Note that most regions are full when they are retiredand we omit those events to reduce the output volume. A region isretired when another region of the same type is allocated or we reachthe start or end of a GC(depending on the region). So for Edenregions: For example: 1. ALLOC(Eden) Foo2. ALLOC(Eden) Bar3. StartGC At point 2, Foo has just been retired and it was full.At point 3, Bar was retired and it was full. If they were not fullwhen they were retired, we will have a RETIRE event: 1. ALLOC(Eden) Foo2. RETIRE Foo top3.ALLOC(Eden) Bar4. StartGC G1HR CSET 0x6e900000 Region (bottom: 0x6e900000) is selected for theCollection Set. The region might have been selected for thecollection set earlier (i.e. when it was allocated). However, wegenerate the CSET events for all regions in the CSet at the start ofa GC to make sure there's no confusion about which regions are partof the CSet. G1HR POST-COMPACTION(Old)0x6e800000 0x6e839858 POST-COMPACTION event is generated for each non-emptyregion in the heap after a full compaction. A full compaction movesobjects around, so we don't know what the resulting shape of the heapis (which regions were written to, which were emptied, etc.). To dealwith this, we generate a POST-COMPACTION event for each non-emptyregion with its type (old/humongous) and the heap boundaries. At thispoint we should only have Old and Humongous regions, as we havecollapsed the young generation, so we should not have eden andsurvivors. POST-COMPACTION events are generated within the Full GCboundary. G1HR CLEANUP 0x6f400000G1HRCLEANUP 0x6f300000G1HR CLEANUP 0x6f200000 These regions were found empty after remark phase ofConcurrent Marking and are reclaimed shortly afterwards. G1HR #StartGC 5G1HR CSET0x6f400000G1HR CSET 0x6e900000G1HR REUSE 0x6f800000 At the end of a GC we retire the old region we areallocating into. Given that its not full, we will carry on allocatinginto it during the next GC. This is what REUSE means. In the abovecase 0x6f800000 should have been the last region with an ALLOC(Old)event during the previous GC and should have been retired before theend of the previous GC. G1HR ALLOC-FORCE(Eden) 0x6f800000 A specialization of ALLOC which indicates that we havereached the max desired number of the particular region type (in thiscase: Eden), but we decided to allocate one more. Currently it's onlyused for Eden regions when we extend the young generation because wecannot do a GC as the GC-Locker is active. G1HR EVAC-FAILURE 0x6f800000 During a GC, we have failed to evacuate an object fromthe given region as the heap is full and there is no space left tocopy the object. This event is generated within GC boundaries andexactly once for each region from which we failed to evacuateobjects. When Heap Regions are reclaimed? It is also worth mentioning when the heap regions inthe G1 heap are reclaimed. All regions that are inthe CSet (the ones that appear in CSET events) are reclaimed at theend of a GC. The exception to that are regions with EVAC-FAILUREevents. All regions withCLEANUP events are reclaimed. After a Full GC some regions get reclaimed (theones from which we moved the objects out). But that is not shownexplicitly, instead the non-empty regions that are left in the heapare printed out with the POST-COMPACTION events.

The purpose of this post is to explain the meaning of GC logs generated with some tracing and diagnostic options for G1 GC. We will take a look at the output generated with PrintGCDetails which is apro...

Diagnosis of a JRockit Deadlock

Recently I came across an interesting JRockit JVM deadlock. I am sharing the details of that deadlock, its diagnosis, and how to workaround that deadlock, which might be useful until the fix for that is available in a future JRockit release. This deadlock occurred between an application Java thread and the JVM's Code Generation thread. The call traces for both the threads looked like this: "[ACTIVE] ExecuteThread: '0' for queue:  'weblogic.kernel.Default (self-tuning)'" id=15 idx=0x54 tid=27249 prio=5 alive, native_waiting,daemonat <unknown>(???.c)@0xffffe410at eventTimedWaitNoTransitionImpl+79(event.c:90)@0xf7c910a0at syncWaitForSignalNoTransition+81(synchronization.c:28)@0xf7e0d8a2at innerNativeDoWait+894(nativelock.c:614)@0xf7d9e8cfat nativeWait+71(nativelock.c:721)@0xf7d9ec28at cbrCompileInCodeGenThread+451(compilerqueue.c:339)@0xf7c71b94at dispatch_compile_request+78(compilerbroker.c:511)@0xf7c64eafat cbrGeableCodtRunneInfo+154(compilerbroker.c:580)@0xf7c6516bat stubsCallJava+77(stubcall.c:112)@0xf7e061ceat stubsCallJavaV+344(stubcall.c:276)@0xf7e065c9at javaInvokeStaticVoidMethod+39(javacalls.c:178)@0xf7cd6098at clsEnsureInitialized+485(class.c:256)@0xf7c4c446at check_flags_and_clinit+28(compilerbroker.c:302)@0xf7c641fdat cbrGetRunnableCodeInfo+37(compilerbroker.c:564)@0xf7c650f6at stubsCallJava+77(stubcall.c:112)@0xf7e061ceat javaInvokeMethod+280(javacalls.c:1128)@0xf7cd62a9 "(Code Generation Thread 1)" id=4 idx=0x30 tid=27235 prio=5 alive,native_waiting, daemonat <unknown>(???.c)@0xffffe410at eventTimedWaitNoTransitionImpl+79(event.c:90)@0xf7c910a0at syncWaitForSignalNoTransition+81(synchronization.c:28)@0xf7e0d8a2at innerNativeDoWait+894(nativelock.c:614)@0xf7d9e8cfat nativeWait+71(nativelock.c:721)@0xf7d9ec28at clsEnsureInitialized+334(class.c:219)@0xf7c4c3afat check_flags_and_clinit+28(compilerbroker.c:302)@0xf7c641fdat compileit+273(compilerbroker.c:317)@0xf7c64992at cbrCompileRequest+16(compilerbroker.c:537)@0xf7c651b1at cg_thread+876(compilerqueue.c:223)@0xf7c7168dat thread_stub+318(lifecycle.c:808)@0xf7d5205fat start_thread+225(:0)@0x64a832at __clone+93(:0)@0x5cee0e The above stack traces and the examination of the core-dump file revealed that the Java Thread (tid=27249) was initializing a class and was in the process of invoking 'clinit' method of that class. Method 'clinit' was not compiled, so it invoked dispatch_compile_request() to compile that method, which sent the compilation request to the Code Generation thread. The Code Generation thread accepted that request and got stuck in waiting for the initialization of the class of 'clinit' to complete. Now, function dispatch_compile_request() checks if the thread has enough (>64K) stack space available for code generation. If yes, then it compiles the method on the same thread otherwise passes the compilation request to the Code Generation (Compiler) thread. if (!enough_stack) {...res = cbrCompileInCodeGenThread(req, TRUE);} else {res = compileit(req, req->method);} In this case, stack space available with Java thread (tid=27249) was around 63K and that was the cause of the problem. Here's what was happening:- (i) While compiling a method, the Code Generation thread wants the class of that method to be initialized, and if it is not, it waits for the class to get initialized.(ii) A Java thread which is in the middle of initializing a class requests Code Generation thread to compile a method of that class because it does not have enough stack space to do the compilation itself and waits for the Code Generation thread to finish the compilation. The above scenario causes a deadlock. A simple solution to avoid the above situation is to increase the stack size for the application Java threads so that there is always enough space on the stack that the compilation can be done on the same thread itself and the need to pass the compilation requests to the Code Generation thread does not arise at least for the uninitialized classes. The fix for this bug is progress and will be available in a future JRockit patchset release.

Recently I came across an interesting JRockit JVM deadlock. I am sharing the details of that deadlock, its diagnosis, and how to workaround that deadlock, which might be useful until the fix for that...

Sun

Adplus configuration

While working on a Java Plugin(on Windows) issue, I found one useful feature of Adplus. I was having a problem with LoadLibraryEx() and I was trying to load a dll into another process' address space but it was not getting loaded. Adplus report was showing DLL_Load and DLL_Unload First Chance Exceptions for the attempts of loading and then unloading the dll. I wanted to find why the dll was getting unloaded immediately after it was attempted to get loaded. And for this, I wanted to obtain the stack trace or crash dump for this First Chance unloading Exception. The default action for this event is to just log the details. Adplus report: DLL_Load [ld] return: GN GN 1st chance: Log 2nd chance: Log DLL_UnLoad [ud] return: GN GN 1st chance: Log 2nd chance: Log Process_Shut_Down [epr] return: VOID VOID 1st chance: Log;Time;EventLog;Stacks;FullDump 2nd chance: Then I found a way on how to change the actions for these exceptions. Adplus can accept a configuration file where in we can specify the actions for Exceptions. I created a conf file 'conf.txt' with following contents:   <ADPlus> <Settings> <ProcessID>4856</ProcessID> <RunMode>CRASH</RunMode> <OutputDir>d:\\poonam</OutputDir> </Settings> <Exceptions> <Config> <Code>AllExceptions</Code> <Actions1>MiniDump;Stack;Log;EventLog</Actions1> </Config> </Exceptions> </ADPlus> and ran adplus: # adplus -c conf.txt With this I could get the stack trace and crash dump of DLL_Unload event. And adplus log contained: DLL_Load [ld] return: GN GN 1st chance: MiniDump;Stack;Log;EventLog 2nd chance: Log DLL_UnLoad [ud] return: GN GN 1st chance: MiniDump;Stack;Log;EventLog 2nd chance: Log Process_Shut_Down [epr] return: VOID VOID 1st chance: MiniDump;Stack;Log;EventLog 2nd chance: Details on Adplus configuration here: http://msdn.microsoft.com/en-us/library/cc390932.aspx Also, it is possible to define the actions for a specific Exception provided you know the ExceptionCode. I could not find the code for DLL_UnLoad exception so I used 'AllExceptions'. <Code> { ExceptionCode | AllExceptions } </Code>

While working on a Java Plugin(on Windows) issue, I found one useful feature of Adplus. I was having a problem with LoadLibraryEx() and I was trying to load a dll intoanother process' address space...

Sun

Important CMS Fixes

In this entry, I would like to talk about some CMS (Concurrent Mark Sweep) issues, their workarounds and the releases these are fixed in. \* 6558100: CMS crash following parallel work queue overflow.This crash is seen when -XX:+ParallelRefProcEnabled is set.Workaround is to use -XX:-ParallelRefProcEnabled. This is fixed in 1.4.2_17, 5.0u14 and 6u4\* 6578335: CMS: BigApps failure with -XX:CMSInitiatingOccupancyFraction=1-XX:+CMSMarkStackOverflowALot.For clarity sake, this issue was broken into three separate bugs 6722112, 6722113 and 6722116.\* 6722112: CMS: Incorrect encoding of overflown ObjectArrays during concurrent precleaning.Workaround is to use -XX:-CMSPrecleaningEnabled and also increasing the size of the marking stack via -XX:CMSMarkStackSize{,Max} would reduce the probability of hitting this bug.This is fixed in 1.4.2_19-rev-b09, 5.0u18-rev-b03, 6u7-rev-b15 and 6u12.\* 6722113: CMS: Incorrect overflow handling during Precleaning of Reference lists.Workaround is to use options -XX:-CMSPrecleanRefLists1 and -XX:-CMSPrecleanRefLists2This is fixed in 6u14, 5.0u18-rev-b05 and 6u13-rev-b05.\* 6722116: CMS: Incorrect overflow handling when using parallel concurrent marking. Workaround is to switch off parallel concurrent marking with -XX:-CMSConcurrentMTEnabled. Also increasing the CMS marking stack size (-XX:CMSMarkStackSize, -XX:CMSMarkStackSizeMax) would reduce the probability of hitting this bug.This is fixed in 6u7-rev-b15 and 6u12.So, if you face any of these above crashes, please upgrade to the JDK version in which it is fixed. And if upgrade is not possible, workaround can be used to avoid the issue.Please note that Java SE for Business support contract is required for using Revision Releases (e.g. 1.4.2_19-rev-b09).

In this entry, I would like to talk about some CMS (Concurrent Mark Sweep) issues, their workarounds and the releases these are fixed in. \* 6558100: CMS crash following parallel work queue overflow.Th...

Sun

More on Windows Crash Dumps for Java Processes...

User Mode Process DumperThere is another very good tool 'User Mode Process Dumper' that can be used to collect user dumps for crashing Java processes.You can get it and install it from here: http://www.microsoft.com/downloads/details.aspx?FamilyID=E089CA41-6A87-40C8-BF69-28AC08570B7E&displaylang=enAfter installation, run it from the Control Panel by clicking 'Process Dumper'. Add the application name to be monitored; java.exe in our case.Set the process monitoring rules by clicking on 'Rules' button. Here, specify the folder where dump should get created when the process crashes. Select 'Access Violation' exception to create dump when any access violation exception happens in the process.Now, let's run the same test program.D:\\demo>java testYou will see this message box creating the crash dump.And then a hs_err log file will also be written:# A fatal error has been detected by the Java Runtime Environment:## EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x10001032, pid=8112, tid=6788## Java VM: OpenJDK Client VM (14.0-b05-internal-debug mixed mode windows-x86 )# Problematic frame:# C [test.dll+0x1032]## An error report file with more information is saved as:# D:\\demo\\hs_err_pid8112.log## If you would like to submit a bug report, please visit:# http://java.sun.com/webapps/bugreport/crash.jsp# The crash happened outside the Java Virtual Machine in native code.# See problematic frame for where to report the bug.#So using this tool, we get both the crash dump as well as the hs_err log file for the crash. :) And the crash dump thus created shows the crash in test.f() native method.OnError JVM optionThere is a JVM option 'OnError' that can be used to perform any action or invoke any tool at the occurrence of fatal error in VM.For example:-XX:OnError="drwtsn32 -p %p" -XX:OnError=”userdump -p %p”This will invoke drwtsn32/userdump whenever any fatal error occurs in VM.UseOSErrorReporting JVM optionThere is a new option UseOSErrorReporting in jdk7 that passes the exception to OS after handling and generating hs_err log file which invokes the Default System Debugger. So for example, If Dr. Watson is set as the default debugger, then with this option, after hs_err file is written, Dr. Watson would be invoked to create the crash dump for the exception.This work is done under CR 6227246: Improve Windows unhandled structured exception reporting

User Mode Process Dumper There is another very good tool 'User Mode Process Dumper' that can be used to collect user dumps for crashing Java processes. You can get it and install it from here: http://w...

Sun

Windows crash dumps for Java Processes

Windows Crash Dump is memory dump of a process running on a Windows system. These dumps can be very useful for debugging Java process crashes. In this entry I discuss how to collect sane Crash Dumps for Java process crashes on Windows machines that can later be analyzed using Windbg or other 'Debugging Tools For Windows'.I have a simple java class test which uses native library test.dll using JNI. test.dll implements a 'native' method where it accesses a null pointer and causes a crash. Complete source of this crashing program is hereWindows NT, 2000 and XPLet's first run this program on a Windows NT/2000/XP machine:D:\\demo>java test## An unexpected error has been detected by Java Runtime Environment:## EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x10011f68, pid=2020, tid=640## Java VM: Java HotSpot(TM) Client VM (10.0-b19 mixed mode, sharing windows-x86)# Problematic frame:# C [test.dll+0x11f68]## An error report file with more information is saved as:# D:\\demo\\hs_err_pid2020.log## If you would like to submit a bug report, please visit:# http://java.sun.com/webapps/bugreport/crash.jsp# The crash happened outside the Java Virtual Machine in native code.# See problematic frame for where to report the bug.#Running this program created an hs_err log file in the same folder. Error log file contains the following stack trace:C [test.dll+0x1032]j test.f()V+0j test.main([Ljava/lang/String;)V+19v ~StubRoutines::call_stubV [jvm.dll+0x873ed]V [jvm.dll+0xdfb96]V [jvm.dll+0x872be]V [jvm.dll+0x8e501]C [java.exe+0x14c5]C [java.exe+0x69cd]C [kernel32.dll+0x16fd7]Now, let's run it with -XX:+ShowMessageBoxOnError JVM option. I get the following message box: Attaching Visual Studio or Windbg to this process or collecting a crash dump with Dr Watson and opening that crash dump with Windbg shows the following call trace:ntdll!DbgBreakPointjvm!VMError::show_message_box+0x7fjvm!VMError::report_and_die+0xe7jvm!report_error+0x2djvm!topLevelExceptionFilter+0x54djvm!os::os_exception_wrapper+0x7dmsvcr71!except_handler3+0x61jvm!JavaCalls::call+0x23jvm!jni_invoke_static+0xb1jvm!jni_CallStaticVoidMethod+0x86java+0x209ejava+0x898fkernel32!GetModuleFileNameA+0x1b4This shows JVM's error handling frames and does not show that the crash happened in function test.f().This is because, by default, the First Chance Exceptions are not sent to the System Debugger. And Debuggers receive only the Second Chance Exceptions. The exception in test.f() was a first Chance Exception that was hanlded by JVM. Please see details on First and Second chance exceptions: http://support.microsoft.com/kb/286350So how can we collect crash dumps that contain the correct stack trace of the crash. Let's try 'adplus' to collect the crash dumps.Start adplus in crash mode:D:\\windbg>adplus -crash -pn java.exeand then start your java process with -XX:+ShowMessageBoxOnErrorBy default, adplus creates mini dumps on First Chance Exceptions and full memory dumps on Second Chance Exceptions. It can be changed; details here: http://support.microsoft.com/kb/286350'adplus' would create dump files in a folder like Crash_Mode__Date_08-12-2008__Time_15-12-56PM. Using Windbg, open the dump created at First Chance Exception and it shows the crashing frame as:test!Java_test_f+0x22Ah! that's what I was looking for.Windows 2008 and Windows VistaDr. Watson is not available on Windows 2008 and Windows Vista Starting with Windows Server 2008 and Windows Vista Service Pack1 (SP1), Windows has new error reporting mechanism called 'Windows Error Reporting' or WER. WER can be configured so that full user-mode dumps are collected and stored locally after a user-mode application crashes. This feature is not enabled by default. Enabling this feature requires administrator privileges. To enable and configure the feature, we need to use the following registry values under theHKEY_LOCAL_MACHINE\\Software\\Microsoft\\Windows\\Windows Error Reporting\\LocalDumps key. Details here:http://msdn.microsoft.com/en-us/library/bb787181(VS.85).aspx And yes, here also we can use 'adplus' to collect Crash Dumps for First Chance and Second Chance Exceptions.Enjoy Debugging !

Windows Crash Dump is memory dump of a process running on a Windows system. These dumps can be very useful for debugging Java process crashes. In this entry I discuss how to collect sane Crash...

Sun

How to implement an interface using Reflection

I was trying to use classes and methods of an existing jar using Reflection. And there was an Interface in that jar which I had to implement. Now how to do that with Reflection ??We can achieve this by using two classes in java.lang.reflect package; Proxy and InvocationHandler.java.lang.reflect.Proxy class accomplishes implementation of interfaces by dynamically creating a class that implements a set of given interfaces. This dynamic class creation is accomplished with the static getProxyClass and newProxyInstance factory methods. Instance created with newProxyInstance() represents the proxy instance for interface(s) we want to implement.While creating a Proxy instance, we need to supply it an invocation handler which handles the method calls for this proxy instance. This is accomplished by implementing java.lang.reflect.InvocationHandler. InvocationHandler interface has a method invoke that needs to be implemented A proxy instance forwards method calls to its invocation handler by calling invoke. Here is the example:public class ProxyListener implements java.lang.reflect.InvocationHandler { public ProxyListener() { } public Object invoke(Object proxy, Method m, Object[] args) throws Throwable { Object result = null; try { // Prints the method being invoked System.out.print("begin method "+ m.getName() + "("); for(int i=0; i0) System.out.print(","); System.out.print(" " + args[i].toString()); } System.out.println(" )"); // if the method name equals some method's name then call your method if (m.getName().equals("someMethod")) { result = myMethod(args[0]); } } catch (Exception e) { throw new RuntimeException("unexpected invocation exception: " + e.getMessage()); } finally { System.out.println("end method " + m.getName()); } return result; } Object myMethod(Object o) {......... }Now we use newProxyInstance to create an instance of, say interface SomeInterface, passing it the invocation handler.Proxy.newProxyInstance(SomeInterface.getClassLoader(), Class[]{SomeInterface.class} , new ProxyListener());and you get the proxy instance for SomeInterface. Use it wherever you need an object of SomeInterface.And that's about it.

I was trying to use classes and methods of an existing jar using Reflection. And there was an Interface in that jar which I had to implement. Now how to do that with Reflection ??We can achieve this...

Sun

How to create VC++ project for HotSpot workspace

I am sure very few people would know that on Windows platform, we can create a VC++ project for the HotSpot workspace in JDK sources. It is very useful as it gives me the ability to view and browse HotSpot source code and also build it at a simple click from Visual Studio IDE. It is also very helpful in debugging hotspot issues which can be reproduced on Windows with a simple testcase(and not just at customer site :) )So let's see how we can create this project for OpenJDK hotspot workspace on 32bit platform and open it in Visual Studio.There is a batch file 'create.bat' in \\build\\windows\\ folder which creates the VC++ project for hotspot workspace on Windows. Before we run this batch, we need to set two environment variables.- The 32-bit OpenJDK Windows build requires Microsoft Visual Studio .NET 2003 (VS2003) Professional Edition compiler. Once the compiler is installed, we need to run VCVARS32.BAT to set the compiler environment variables e.g.D:\\openjdk7\\openjdk\\hotspot\\build\\windows>d:\\Progra~1\\Micros~1.NET\\Common7\\Tools\\vsvars32.batSetting environment for using Microsoft Visual Studio .NET 2003 tools.(If you have another version of Visual Studio or Visual C++ installed and wishto use its tools from the command line, run vcvars32.bat for that version.)- Set the Path to include installed jdk bin folder (jdk6 or jdk7)e.g.set PATH=D:\\Java\\jdk1.6.0_03\\bin;%PATH%Now, run create.bat---------------------D:\\openjdk7\\openjdk\\hotspot\\build\\windows>create.batUsage: create HotSpotWorkSpace HotSpotBuildSpace HotSpotJDKDistThis is the interactive build setup script (as opposed to the batchbuild execution script). It creates HotSpotBuildSpace if necessary,copies the appropriate files out of HotSpotWorkSpace into it, andbuilds and runs MakeDeps in it. This has the side-effect of creatingthe file in the build space, which is then used in Visual C++.The HotSpotJDKDist defines place where JVM binaries should be placed.Environment variable FORCE_MSC_VER allows to override MSVC version autodetection.The generated project file depends upon the include databases. Ifthose are changed then MakeDeps is rerun.NOTE that it is now NOT safe to modify any of the files in the buildspace, since they may be overwritten whenever this script is run ornmake is run in that directory.-----------------------Passing those required arguments:D:\\openjdk7\\openjdk\\hotspot\\build\\windows>create.bat D:\\openjdk7\\openjdk\\hotspot d:\\hotspot\\build d:\\hotspot\\bin\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*Will generate VC7 project vm.vcproj\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*NOTE: Using the following settings: HotSpotWorkSpace=D:\\openjdk7\\openjdk\\hotspot HotSpotBuildSpace=d:\\hotspot\\build HotSpotJDKDist=d:\\hotspot\\bin javac -g -d d:\\hotspot\\build\\jvmtifiles D:\\openjdk7\\openjdk\\hotspot/src/share/vm/prims/jvmtiGen.javaGenerating d:\\hotspot\\build\\jvmtifiles/jvmtiEnv.hppGenerating d:\\hotspot\\build\\jvmtifiles/jvmtiEnter.cpp.......... cut the output here ......... creating c1_ValueType.cpp writing grand include file writing dependencies file..................................................... Writing .vcproj file... Done. rm -f ad_x86_32.cpp ad_x86_32.hpp ad_x86_32_clone.cpp ad_x86_32_expand.cpp ad_x86_d_x86_32_peephole.cpp ad_x86_32_pipeline.cpp adGlobals_x86_32.hpp dfa_x86_32.cpp adlc -q -T -U_LP64 x86_32.ad\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*This creates vm.vcproj file in d:\\hotspot\\build folder.Open this in Visual Studio .Net and have fun!

I am sure very few people would know that on Windows platform, we can create a VC++ project for the HotSpot workspace in JDK sources. It is very useful as it gives me the ability to view and...

Sun

Debugging JVM hang with 'dbx'

Recently worked on a JVM hang problem, so posting here the steps followed in debugging this issue with dbx.Customer was facing hard hang on a Solaris-x86 machine with jdk 1.5.0_08 and the process was not even responding to kill -3. They sent us a core file of the hung process.For dbx to have the debug information, I re-built the product version of 1.5.0_08 libjvm.so with -g flag and loaded and used this new libjvm.so with dbx. With that, dbx was able to get all the debug information for the core file that was generated with a libjvm.so without any debug info.The pstack on the core file showed that VMThread is trying to acquire Threads_lock, main thread is waiting on a condition on Threads_lock and another thread 3992 was also trying to grab Threads_lock, so this lock seemed to be causing the deadlock.----------------- lwp# 1 / thread# 1 -------------------- fef4009b lwp_park (0, 0, 0) fef3a909 cond_wait_queue (807c540, 807c528, 0, 0) + 3b fef3ae02 _cond_wait (807c540, 807c528) + 66 fef3ae44 cond_wait (807c540, 807c528) + 21 fe92fc64 __1cHMonitorEwait6Mil_i_ (807c4d0, 0, 0) + 2a4 fecf526b __1cHThreadsKdestroy_vm6F_i_ (8073fb9, 0, 806dc14, fee4d33c, fee4a2a0, 10004) + 7b feb66ea3 jni_DestroyJavaVM (fee43560) + 123 08051f8e main (2, 807017c, 80432b4) + bfb 080512fa ???????? (86, 8043468, 804346d, 8043494, 80434a8, 80434c6)----------------- lwp# 11 / thread# 11 -------------------- fef4009b lwp_park (0, 0, 0) fef399bb slow_lock (fbc92000, 807c528, 0) + 3d fef39ab1 mutex_lock_impl (807c528, 0) + ec fef39bbd mutex_lock (807c528) + 1a fe8c9a00 __1cFMutexElock6MpnGThread__v_ (807c4d0, 8261480) + c0 fe8cc1fe __1cFMutexElock6M_v_ (807c4d0) + 4e fe996295 __1cUSafepointSynchronizeFbegin6F_v_ (fee493fc, 8261480, fedee000, f8199b74, 3, f8199bbc) + 85 fea659c4 __1cIVMThreadEloop6M_v_ (8261480) + 134 fea66478 __1cIVMThreadDrun6M_v_ (8261480) + 88 fecbe0f2 __1cG_start6Fpv_0_ (8261480) + d2 fef3fd52 _thr_setup (fbc92000) + 4e fef40040 _lwp_start (fbc92000, 0, 0, f8199ff8, fef40040, fbc92000)----------------- lwp# 3992 / thread# 3992 -------------------- fef4009b lwp_park (0, 0, 0) fef399bb slow_lock (6c173c00, 807c528, 0) + 3d fef39ab1 mutex_lock_impl (807c528, 0) + ec fef39bbd mutex_lock (807c528) + 1a fe8ea95e __1cFMutexbClock_without_safepoint_check6M_v_ (807c4d0) + 7e fe95c56e __1cUSafepointSynchronizeFblock6FpnKJavaThread__v_ (a27f780) + ee fecb6825 __1cGParkerEpark6Mix_v_ (a27f908, 0, d964b198, 45) + 1e5 fed0963d Unsafe_Park (a27f840, 6807aba4, 0, d964b198, 45, 9480bcb8) + 1dd f876f2f9 ???????? (0, 0, a27c330, 0, 9ae69a8, 0) 00000000 ???????? (fecf6330, fea09d40, fea03c80, fe964f40, fe91cc40, fe939c50) 00000000 ???????? (fffffd2c, 3badd9be, f468fe16, e78b7254, fe1dbbcc, 0) 00000000 ???????? ()Now let's look at the Threads_lock in dbx.(dbx) print -fx Threads_lockThreads_lock = 0x807c4d0(dbx) print -r \*((Monitor\*)0x807c4d0)\*((class Monitor \*) 0x807c4d0) = { Monitor::Mutex::_lock_count = 0 Monitor::Mutex::_lock_event = 0x807c500 Monitor::Mutex::_suppress_signal = 0 Monitor::Mutex::_owner = 0x97b0978 [1] __lwp_park(0x0, 0x0), at 0xfef4009b [2] mutex_lock_queue(0x67366400, 0x0, 0x88a0598, 0x0), at 0xfef3911f [3] slow_lock(0x67366400, 0x88a0598, 0x0), at 0xfef399bb [4] mutex_lock_impl(0x88a0598, 0x0), at 0xfef39ab1 [5] __mutex_lock(0x88a0598), at 0xfef39bbd [6] Mutex::wait_for_lock_blocking_implementation(0xa27f908, 0x97b0978), at 0xfe9d93ba [7] Mutex::lock(0xa27f908, 0x97b0978), at 0xfe8c99ea [8] Mutex::lock(0xa27f908), at 0xfe8cc1fe [9] Parker::unpark(0xa27f908), at 0xfecb69bb [10] os::interrupt(0xa27f780), at 0xfecbf6bb [11] Thread::interrupt(0xa27f780), at 0xfecf2ed9 [12] JVM_Interrupt(0x97b0a38, 0x65c923fc, 0x65c923d0, 0x0, 0x65c923fc, 0xf4873020, 0x0, 0xf482f600, 0x65c923fc, 0x65c92424, 0xf8202b6b, 0x0, 0xf8206399, 0x9593fdc0, 0x1, 0x0, 0x65c92400, 0xf482db6b, 0x65c92438, 0xf4873020), at 0xfeb92255 [13] 0xf820843a(0x0, 0xf8206399, 0x9593fdc0, 0x1, 0x0, 0x65c92400), at 0xf820843a [14] 0xf8202b6b(0x0, 0x0, 0x97f59c18, 0x9593fdc0, 0x65c9243c, 0xf5746e95), at 0xf8202b6b [15] 0xf8202b6b(0x967a0c40, 0x9, 0x968f6eb8, 0x65c92464, 0xf57472be, 0x65c92498), at 0xf8202b6b [16] 0xf8202b6b(0x0, 0x968f6eb8, 0x967a0c40, 0x65c9249c, 0xf5845a0c, 0x65c924c4), at 0xf8202b6b [17] 0xf8202b6b(0x1b58, 0x967a0c40, 0x65c924c8, 0xf5845674, 0x65c92524, 0xf58a1f78), at 0xf8202b6b [18] 0xf8202b6b(0x7624c168, 0x7624c138, 0x7624c108, 0x7624c0d8, 0x7624bee8, 0x7624bd00), at 0xf8202b6bIt is trying to acquire Monitor 0xa27f908Now, look at this Monitor:(dbx) print -r \*((Monitor\*)0xa27f908)\*((class Monitor \*) 0xa27f908) = { Monitor::Mutex::_lock_count = 0 Monitor::Mutex::_lock_event = 0x88a0570 1\*((class os::Solaris::Event \*) 0x88a0570) = { Event::_count = 0 Event::_nParked = 0 Event::CachePad = (-6.7529205832009e-205, -6.6220952168053e-205, -1.2786650622506e-204, -1.9668306807887e-204) Event::_mutex = ( { Event::_lwp_mutex::flags = { Event::_lwp_mutex::flag1 = 4U Event::_lwp_mutex::flag2 = '\\0' Event::_lwp_mutex::ceiling = '\\0' Event::_lwp_mutex::mbcp_type_un = { Event::_lwp_mutex::bcptype = 0 Event::_lwp_mutex::mtype_rcount = { Event::_lwp_mutex::count_type1 = '\\0' Event::_lwp_mutex::count_type2 = '\\0' } } Event::_lwp_mutex::magic = 19800U } Event::_lwp_mutex::lock = { Event::_lwp_mutex::lock64 = { Event::_lwp_mutex::pad = "" } Event::_lwp_mutex::lock32 = { Event::_lwp_mutex::ownerpid = 0 Event::_lwp_mutex::lockword = 16842752U } Event::_lwp_mutex::owner64 = 72339069014638592ULL } Event::_lwp_mutex::data = 1813462016ULL }) Event::_cond = ( { Event::_lwp_cond::flags = { Event::_lwp_cond::flag = "" Event::_lwp_cond::type = 0 Event::_lwp_cond::magic = 17238U } Event::_lwp_cond::data = 0 }) Event::FreeNext = (nil) Event::Immortal = 0}Here _lwp_mutex->data which is 0x6C173C00 is the owner thread (ulwp_t)looking at it:(dbx) x 0x6C173C00/30X0x6c173c00: 0x6c173c00 0x00000000 0x00000000 0x000000000x6c173c10: 0x00000000 0x00000000 0x00000000 0x000000000x6c173c20: 0x00000000 0x00000000 0x00000000 0xfef6b7400x6c173c30: 0x00000000 0x00000000 0x6c174000 0x6c1738000x6c173c40: 0x00000000 0x00000000 0x00000000 0x6803b0000x6c173c50: 0x00040000 0x00000000 0x6807b000 0x000400000x6c173c60: 0x6803b000 0x00040000 0x00000000 0x000003980x6c173c70: 0x00000f98 0x0000007f0x00000f98 (which is 3992) is the thread id holding this Event::mutex Now looking at thread 3992:(dbx) thread t@3992t@3992 (l@3992) stopped in __lwp_park at 0xfef4009b0xfef4009b: __lwp_park+0x000b: jae __lwp_park+0x19 [ 0xfef400a9, .+0xe ](dbx) wherecurrent thread: t@3992=>[1] __lwp_park(0x0, 0x0), at 0xfef4009b [2] mutex_lock_queue(0x6c173c00, 0x0, 0x807c528, 0x0), at 0xfef3911f [3] slow_lock(0x6c173c00, 0x807c528, 0x0), at 0xfef399bb [4] mutex_lock_impl(0x807c528, 0x0), at 0xfef39ab1 [5] __mutex_lock(0x807c528), at 0xfef39bbd [6] Mutex::lock_without_safepoint_check(0x807c4d0), at 0xfe8ea95e [7] SafepointSynchronize::block(0xa27f780), at 0xfe95c56e [8] Parker::park(0xa27f908, 0x0, 0xd964b198, 0x45), at 0xfecb6825 [9] Unsafe_Park(0xa27f840, 0x6807aba4, 0x0, 0xd964b198, 0x45, 0x9480bcb8), at 0xfed0963dIt is waiting to lock Threads_lock.So threads 11982 and 3992 have a deadlock.Thread 11982 – holds Thread_lock and waiting to acquire Monitor 0xa27f908Thread 3992 – holds lock on 0xa27f908 and waiting to acquire Threads_lockThis problem has been fixed with 6601725 in 5.0u15 and mustang.

Recently worked on a JVM hang problem, so posting here the steps followed in debugging this issue with dbx.Customer was facing hard hang on a Solaris-x86 machine with jdk 1.5.0_08 and the process was...

Sun

Building OpenJDK on Windows with NetBeans

Trying to build OpenJDK on Windows ? Here are some simple steps that may help...Here are the softwares required for the build.- Download OpenJDK from http://download.java.net/openjdk/jdk7/ and unzip the contents- Download and install jdk 6.0 from http://java.sun.com/javase/downloads/index.jsp and jdk 7.0 from http://download.java.net/jdk7/binaries- Download and install openjdk binary plugs from http://download.java.net/openjdk/jdk7/- Install Microsoft Visual Studio .NET 2003 Professional- Install Cygwin from http://www.cygwin.com. Make sure you install it in dos/text mode. Along with the default installation, we need to install Devel, Interpreters and Utils pakages. For the build, we need make 3.80, so if the cygwin make in not 3.80, download make bundle from http://cygwin.paracoda.com/release/make/make-3.80-1.tar.bz2 and untar it in a separate folder.- Download and install findbugs from http://findbugs.sourceforge.net/downloads.html.- Download and install Ant from http://ant.apache.org/bindownload.cgi- Install Microsoft DirectX 9.0 SDK- Download and install Microsoft Unicode library- Install Freetype 2.3.4 from http://sourceforge.net/project/showfiles.php?group_id=3157- Install NetBeans 6.0 from http://www.netbeans.org/downloads/To build OpenJDK with NetBeans, open 'jdk' project in openjdk/jdk/make/netbeans/ with NetBeans. But first open a command window (cmd.exe) and set the path for following installed softwares:set PATH=d:/utilities/usr/bin;d:\\devtools\\cygwin\\bin;D:\\devtools\\findbugs-1.3.0\\bin;D:\\devtools\\apache-ant-1.7.0\\bin;%PATH%Here, d:/utilities/usr/bin contains make 3.80. Also, it is setting the path for cygwin, FindBugs and ant.then run vsvars32.bat of Microsoft Visual Studio .NET:d:\\Progra~1\\Micros~1.NET\\Common7\\Tools\\vsvars32.bat Now launch Netbeans from this command window.In Netbeans, click on File->Open Project. Browse to openjdk/jdk/make/netbeans/ and select 'jdk'.In openjdk/jdk/make/netbeans/common/make.xml file, change the location of bin/make to your 3.80 make.<target name="-pre-init.windows" if="os.windows"> <property name="platform" value="windows"/> <property name="make" value="d:/utilities/usr/bin/make"/></target>In build.properties file, set the following environment variables:bootstrap.jdk=d:/devtools/jdk1.7.0make.options=\\ ALT_BOOTDIR=D:/Java/jdk1.6.0_03 \\ ALT_BINARY_PLUGS_PATH=D:/devtools/openjdk-binary-plugs \\ ALT_JDK_IMPORT_PATH=d:/devtools/jdk1.7.0 \\ ALT_DXSDK_PATH=d:/devtools/dxsdk9 \\ ALT_COMPILER_PATH=D:/Progra~1/Micros~1.NET/Vc7/bin \\ ALT_MSDEVTOOLS_PATH= D:/Progra~1/Micros~1.NET/Common7/Tools/Bin \\ ALT_MSVCR71_DLL_PATH= D:/Progra~1/Micros~1.NET/SDK/v1.1/Bin \\ ALT_FREETYPE_LIB_PATH=d:/devtools/freetype-2.3.4/lib \\ ALT_FREETYPE_HEADERS_PATH=d:/devtools/freetype-2.3.4/include \\ ALT_UNICOWS_LIB_PATH=d:/devtools/unicows \\ ALT_UNICOWS_DLL_PATH=d:/devtools/unicows \\ LD_LIBRARY_PATH= \\ CLASSPATH= \\ JAVA_HOME= \\ SHLVL=1 \\ OPENJDK=trueAnd that's all we need to do. Start the build (press F11 or right click on jdk project and click Build)

Trying to build OpenJDK on Windows ? Here are some simple steps that may help... Here are the softwares required for the build. - Download OpenJDK from http://download.java.net/openjdk/jdk7/and unzip...

Sun

How to programmatically obtain GC information

Here's a small program which uses GarbageCollectorMXBean MBean to programmaticallyobtain the GC information of the running java process. Call it's printGCInfo in your applcation whenever you want to get the last GC information.import com.sun.management.GcInfo;import javax.management.MBeanServer;import java.lang.management.ManagementFactory;import com.sun.management.GarbageCollectorMXBean;import java.lang.management.MemoryUsage;import java.util.Iterator;import java.util.Map;import java.util.Set;public class GCInformation { private static final String GC_BEAN_NAME = "java.lang:type=GarbageCollector,name=ConcurrentMarkSweep"; private static volatile GarbageCollectorMXBean gcMBean; /\*\* Creates a new instance of GCInformation \*/ public GCInformation() { } // initialize the GC MBean field private static void initGCMBean() { if (gcMBean == null) { synchronized (GCInformation.class) { if (gcMBean == null) { gcMBean = getGCMBean(); } } } } // get the GarbageCollectorMXBean MBean from the // platform MBean server private static GarbageCollectorMXBean getGCMBean() { try { MBeanServer server = ManagementFactory.getPlatformMBeanServer(); GarbageCollectorMXBean bean = ManagementFactory.newPlatformMXBeanProxy(server, GC_BEAN_NAME, GarbageCollectorMXBean.class); return bean; } catch (RuntimeException re) { throw re; } catch (Exception exp) { throw new RuntimeException(exp); } } /\*\* \* Call this method from your application whenever you \* want to get the last gc info \* \*/ static boolean printGCInfo() { // initialize GC MBean initGCMBean(); try { GcInfo gci = gcMBean.getLastGcInfo(); long id = gci.getId(); long startTime = gci.getStartTime(); long endTime = gci.getEndTime(); long duration = gci.getDuration(); if (startTime == endTime) { return false; // no gc } System.out.println("GC ID: "+id); System.out.println("Start Time: "+startTime); System.out.println("End Time: "+endTime); System.out.println("Duration: "+duration); Map mapBefore = gci.getMemoryUsageBeforeGc(); Map mapAfter = gci.getMemoryUsageAfterGc(); System.out.println("Before GC Memory Usage Details...."); Set memType = mapBefore.keySet(); Iterator it = memType.iterator(); while(it.hasNext()) { String type = (String)it.next(); System.out.println(type); MemoryUsage mu1 = mapBefore.get(type); System.out.print("Initial Size: "+mu1.getInit()); System.out.print(" Used: "+ mu1.getUsed()); System.out.print(" Max: "+mu1.getMax()); System.out.print(" Committed: "+mu1.getCommitted()); System.out.println(" "); } System.out.println("After GC Memory Usage Details...."); memType = mapAfter.keySet(); it = memType.iterator(); while(it.hasNext()) { String type = (String)it.next(); System.out.println(type); MemoryUsage mu2 = mapAfter.get(type); System.out.print("Initial Size: "+mu2.getInit()); System.out.print(" Used: "+ mu2.getUsed()); System.out.print(" Max: "+mu2.getMax()); System.out.print(" Committed: "+mu2.getCommitted()); System.out.println(" "); } } catch (RuntimeException re) { throw re; } catch (Exception exp) { throw new RuntimeException(exp); } return true; } /\*\* \* @param args the command line arguments \*/ public static void main(String[] args) { // Print the last gc information boolean ret = printGCInfo(); } }Note that the GarbageCollector name used here is "ConcurrentMarkSweep" because I was running my appication with Concurrent Mark Sweep collector. Please use the appropriate Collector name from the list of Collector names I had posted in my previous entry.

Here's a small program which uses GarbageCollectorMXBean MBean to programmatically obtain the GC information of the running java process. Call it's printGCInfo inyour applcation whenever you want to...

Sun

JVMTI agent to print reference paths

To get started on JVMTI please read JVMTI reference guide JVMTI reference guide and a very good article on JVMTI Programming here Here I will briefly describe how I used JVMTI to write an agent which prints the reference paths of instances of a given class in the running process. The global data structure used in this agent: /\* Global agent data structure \*/typedef struct { /\* JVMTI Environment \*/ jvmtiEnv \*jvmti; /\* Data access Lock \*/ jrawMonitorID lock; /\* Fields to store the Options passed to the agent\*/ char\* classname; int max_count; /\* boolen to indicate if dump is in progress \*/ jboolean dumpInProgress; JavaVM\* jvm; jclass klass; jlong klassTag;} GlobalAgentData; This agent prints these reference paths when a SIGQUIT signal is sent to the process. For this, In Agent_OnLoad() function, set the callback for DataDumpRequest and enable the event notification for JVMTI_EVENT_DATA_DUMP_REQUEST event. JNIEXPORT jint JNICALL Agent_OnLoad(JavaVM \*jvm, char \*options, void \*reserved){ .... callbacks.DataDumpRequest = &dataDumpRequest; jvmti->SetEventNotificationMode(JVMTI_ENABLE, JVMTI_EVENT_DATA_DUMP_REQUEST, NULL); ....} With the above code, when the process receives SIGQUIT (ctrl+\\ on solaris and ctrl+break on windows) signal, dataDumpRequest() function of this agent would get invoked. Let's see how this function looks: static void JNICALL dataDumpRequest(jvmtiEnv \*jvmti){ enter_critical_section(jvmti); { if ( !gdata->dumpInProgress ) { gdata->dumpInProgress = JNI_TRUE; gdata->klassTag = 1; gdata->jvmti->SetTag(gdata->klass, gdata->klassTag); jint count = 0; void\* user_data = NULL; // iterate over all the reachable objects in heap jvmti->IterateOverReachableObjects(&heap_root_callback, &stack_ref_callback, &object_ref_callback, user_data); // print ref paths RefPaths\* list = ref_paths; int max = gdata->max_count; printf("Reference paths of instances of %s ....\\n", gdata->classname); while ((list != NULL) && (max >= 0) ) { ObjectInfo\* object = (ObjectInfo\*)list->path; printf("\\n\\nReference Path:"); dfsPrintRefPaths(object); list = list->next; max--; } // unset tags jvmti->IterateOverReachableObjects(&heap_root_callback, &stack_ref_callback, &object_ref_clean_callback, user_data); // delete object info list ObjectInfoList\* list1 = objList; while (list1) { ObjectInfoList\* node = list1; list1 = list1->next; DeallocateObject(node->obj); delete(node); } objList = NULL; // delete ref paths list list = ref_paths; RefPaths\* path; while (list != NULL) { path = list; list = list->next; delete(path); } ref_paths = NULL; gdata->klassTag = 1; gdata->dumpInProgress = JNI_FALSE; } } exit_critical_section(jvmti);}Here, we first set the tag of the class gdata->klass which was set to the classname passed as parameter to the agent. Then we call IterateOverReachableObjects function to go over all the reachable objects in heap. IterateOverReachableObjects function iterates over the root objects and all objects that are directly and indirectly reachable from the root objects. In dataDumpRequest we are making two calls to IterateOverReachableObjects, first one to create a list of reachable objects and their referrers and the second one to unset the tags set in the first call. IterateOverReachableObjects accepts three callbacks, callback which gets called when any root object is visited, callback which gets called when any stack object is visited and a callback when any object reference is visited. This sample agent does not do anything in the root and stack callbacks. Now let's see what the object reference callback does: static jvmtiIterationControl JNICALLobject_ref_callback(jvmtiObjectReferenceKind reference_kind,jlong class_tag, jlong size, jlong\* tag_ptr,jlong referrer_tag, jint referrer_index, void \*user_data){ ObjectInfo\* obj_info = NULL; // if this object's tag is set which can be for the class we want to create // reference paths for or if we are visiting this object again. if (\*tag_ptr != NULL) { if (gdata->klassTag == 1) { if (\*tag_ptr == gdata->klassTag) { obj_info = new ObjectInfo();memset(obj_info, 0 , sizeof(ObjectInfo));obj_info->size = size;obj_info->visited = 1;obj_info->kind = reference_kind;\*tag_ptr = (jlong)(ptrdiff_t)(void\*)obj_info;gdata->klassTag = \*tag_ptr; } } else { obj_info = (ObjectInfo\*)\*tag_ptr; if (obj_info->visited == 1)return JVMTI_ITERATION_CONTINUE; } } // if tag is not present, then create ObjectInfo and set it as it's tag. else { obj_info = new ObjectInfo(); memset(obj_info, 0 , sizeof(ObjectInfo)); obj_info->size = size; obj_info->visited = 1; obj_info->kind = reference_kind; \*tag_ptr = (jlong)(ptrdiff_t)(void\*)obj_info; //Add the new ObjectInfo to ObjectInfo's list if (objList == NULL) { objList = new ObjectInfoList(); objList->obj = obj_info; objList->next = NULL; } else { ObjectInfoList\* list = objList; while (list->next != NULL) { list = list->next; } ObjectInfoList\* objinfo = new ObjectInfoList(); objinfo->obj = obj_info; objinfo->next = NULL; list->next = objinfo; } } // If this object has the referrer then put it in the referrers list if (referrer_tag != NULL) { if (obj_info->referrers == NULL) { obj_info->referrers = new Referrer(); obj_info->referrers->tag = referrer_tag; obj_info->referrers->refereeTag = \*tag_ptr; obj_info->referrers->next = NULL; } else { Referrer\* referrer = obj_info->referrers; while (referrer->next != NULL) { referrer = referrer->next; } Referrer\* ref = new Referrer(); ref->tag = referrer_tag; ref->refereeTag = \*tag_ptr; ref->next = NULL; referrer->next = ref; } } if (class_tag == gdata->klassTag) { AddToPathsList(obj_info); } return JVMTI_ITERATION_CONTINUE;} Here the ObjectInfo class represents an object in the heap. We tag every visited reference with the ObjectInfo pointer and when it's refree is visited, the referer_tag contains this ObjectInfo pointer. So by using tag_ptr and referer_tag, this callback creates list of reference paths (RefPaths) of all the instances of the given class. After returning from the callback, function dfsPrintRefPaths prints prints these reference paths. Then we make another call to IterateOverReachableObjects to unset the tags we had set in the first iteration. The full code of this agent can be downloaded from here. How this works:----------------- Build ref_paths.cpp into a shared library. Copy the library refpaths.dll or refpaths.so in the current working directory or set the LD_LIBRARY_PATH on solaris and PATH env variable on Windows to the loaction of this library. Start your java program with options: java -agentlib:refpaths=classname="java/lang/String",max=40 TestClass where -agentlib:refpaths specifies that 'refpaths' is the jvmti based shared library and following that are the arguments passed to this agent. o classname - name of the class for which we want to print the ref-paths o max - the maximum number of instances The above commnad will print the 40 ref-paths of instances of java/lang/String class. To print the ref-paths at any point, send Sigquit signal to the running process and it will print the paths though which the requested instances are reachable. The output of ref-paths printed by this agent looks like this: Reference Path: - Instance Field: /E:/jre1.5.0_10/lib/ext/dnsns.jar - Array Element: file:/E:/jre1.5.0_10/lib/ext/dnsns.jar - Instance Field: [Ljava.lang.Object;@1c78e57 - Instance Field: [file:/E:/jre1.5.0_10/lib/ext/dnsns.jar, file:/E:/jre1.5.0_10/lib/ext/localedata.jar, file:/E:/jre1.5.0_10/lib/ext/sunjce_provider.jar, file:/E:/jre1.5.0_10/lib/ext/sunpkcs11.jar] - Instance Field: sun.misc.URLClassPath@5224ee - Instance Field: sun.misc.Launcher$ExtClassLoader@92e78c - ClassLoader: sun.misc.Launcher$AppClassLoader@a39137 - class TestClass Reference Path: - Instance Field: file:/E:/jre1.5.0_10/lib/ext/sunpkcs11.jar!/ - Instance Field: jar:file:/E:/jre1.5.0_10/lib/ext/sunpkcs11.jar!/ - Array Element: sun.misc.URLClassPath$JarLoader@f6a746 - Instance Field: [Ljava.lang.Object;@15ff48b - Instance Field: [sun.misc.URLClassPath$JarLoader@affc70, sun.misc.URLClassPath $JarLoader@1e63e3d,sun.misc.URLClassPath$JarLoader@1004901,sun.misc.URLClassPath$JarLoader@f6a746] - Instance Field: sun.misc.URLClassPath@5224ee - Instance Field: sun.misc.Launcher$ExtClassLoader@92e78c - ClassLoader: sun.misc.Launcher$AppClassLoader@a39137 - class TestClass where any entry is reachable through the entry below it.

To get started on JVMTI please read JVMTI reference guide JVMTI reference guide and a very good article on JVMTI Programming hereHere I will briefly describe how I used JVMTI to write an agent which...

Sun

Understanding CMS GC Logs

CMS GC with -XX:+PrintGCDetails and -XX:+PrintGCTimeStamps prints a lot of information. Understanding this information can help in fine tuning various parameters of the application and CMS to achieve best performance.Let's have a look at some of the CMS logs generated with 1.4.2_10:39.910: [GC 39.910: [ParNew: 261760K->0K(261952K), 0.2314667 secs] 262017K->26386K(1048384K), 0.2318679 secs]Young generation (ParNew) collection. Young generation capacity is 261952K and after the collection its occupancy drops down from 261760K to 0. This collection took 0.2318679 secs.40.146: [GC [1 CMS-initial-mark: 26386K(786432K)] 26404K(1048384K), 0.0074495 secs]Beginning of tenured generation collection with CMS collector. This is initial Marking phase of CMS where all the objects directly reachable from roots are marked and this is done with all the mutator threads stopped. Capacity of tenured generation space is 786432K and CMS was triggered at the occupancy of 26386K.40.154: [CMS-concurrent-mark-start]Start of concurrent marking phase. In Concurrent Marking phase, threads stopped in the first phase are started again and all the objects transitively reachable from the objects marked in first phase are marked here. 40.683: [CMS-concurrent-mark: 0.521/0.529 secs]Concurrent marking took total 0.521 seconds cpu time and 0.529 seconds wall time that includes the yield to other threads also.40.683: [CMS-concurrent-preclean-start]Start of precleaning. Precleaning is also a concurrent phase. Here in this phase we look at the objects in CMS heap which got updated by promotions from young generation or new allocations or got updated by mutators while we were doing the concurrent marking in the previous concurrent marking phase. By rescanning those objects concurrently, the precleaning phase helps reduce the work in the next stop-the-world “remark” phase.40.701: [CMS-concurrent-preclean: 0.017/0.018 secs]Concurrent precleaning took 0.017 secs total cpu time and 0.018 wall time.40.704: [GC40.704: [Rescan (parallel) , 0.1790103 secs]40.883: [weak refs processing, 0.0100966 secs] [1 CMS-remark: 26386K(786432K)] 52644K(1048384K), 0.1897792 secs]Stop-the-world phase. This phase rescans any residual updated objects in CMS heap, retraces from the roots and also processes Reference objects. Here the rescanning work took 0.1790103 secs and weak reference objects processing took 0.0100966 secs. This phase took total 0.1897792 secs to complete.40.894: [CMS-concurrent-sweep-start]Start of sweeping of dead/non-marked objects. Sweeping is concurrent phase performed with all other threads running.41.020: [CMS-concurrent-sweep: 0.126/0.126 secs]Sweeping took 0.126 secs.41.020: [CMS-concurrent-reset-start]Start of reset.41.147: [CMS-concurrent-reset: 0.127/0.127 secs]In this phase, the CMS data structures are reinitialized so that a new cycle may begin at a later time. In this case, it took 0.127 secs.This was how a normal CMS cycle runs. Now let us look at some other CMS log entries:197.976: [GC 197.976: [ParNew: 260872K->260872K(261952K), 0.0000688 secs]197.976: [CMS197.981: [CMS-concurrent-sweep: 0.516/0.531 secs] (concurrent mode failure): 402978K->248977K(786432K), 2.3728734 secs] 663850K->248977K(1048384K), 2.3733725 secs]This shows that a ParNew collection was requested, but it was not attempted because it was estimated that there was not enough space in the CMS generation to promote the worst case surviving young generation objects. We name this failure as “full promotion guarantee failure”.Due to this, Concurrent Mode of CMS is interrupted and a Full GC is invoked at 197.981. This mark-sweep-compact stop-the-world Full GC took 2.3733725 secs and the CMS generation space occupancy dropped from 402978K to 248977K.The concurrent mode failure can either be avoided by increasing the tenured generation size or initiating the CMS collection at a lesser heap occupancy by setting CMSInitiatingOccupancyFraction to a lower value and setting UseCMSInitiatingOccupancyOnly to true. The value for CMSInitiatingOccupancyFraction should be chosen appropriately because setting it to a very low value will result in too frequent CMS collections.Sometimes we see these promotion failures even when the logs show that there is enough free space in tenured generation. The reason is 'fragmentation' - the free space available in tenured generation is not contiguous, and promotions from young generation require a contiguous free block to be available in tenured generation. CMS collector is a non-compacting collector, so can cause fragmentation of space for some type of applications. In his blog, Jon talks in detail on how to deal with this fragmentation problem:http://blogs.sun.com/roller/page/jonthecollector?entry=when_the_sum_of_theStarting with 1.5, for the CMS collector, the promotion guarantee check is done differently. Instead of assuming that the promotions would be worst case i.e. all of the surviving young generation objects would get promoted into old gen, the expected promotion is estimated based on recent history of promotions. This estimation is usually much smaller than the worst case promotion and hence requires less free space to be available in old generation. And if the promotion in a scavenge attempt fails, then the young generation is left in a consistent state and a stop-the-world mark-compact collection is invoked. To get the same functionality with UseSerialGC you need to explicitly specify the switch -XX:+HandlePromotionFailure.283.736: [Full GC 283.736: [ParNew: 261599K->261599K(261952K), 0.0000615 secs] 826554K->826554K(1048384K), 0.0003259 secs]GC locker: Trying a full collection because scavenge failed283.736: [Full GC 283.736: [ParNew: 261599K->261599K(261952K), 0.0000288 secs]Stop-the-world GC happening when a JNI Critical section is released. Here again the young generation collection failed due to “full promotion guarantee failure” and then the Full GC is being invoked.CMS can also be run in incremental mode (i-cms), enabled with -XX:+CMSIncrementalMode. In this mode, CMS collector does not hold the processor for the entire long concurrent phases but periodically stops them and yields the processor back to other threads in application. It divides the work to be done in concurrent phases in small chunks(called duty cycle) and schedules them between minor collections. This is very useful for applications that need low pause times and are run on machines with small number of processors.Some logs showing the incremental CMS.2803.125: [GC 2803.125: [ParNew: 408832K->0K(409216K), 0.5371950 secs] 611130K->206985K(1048192K) icms_dc=4 , 0.5373720 secs]2824.209: [GC 2824.209: [ParNew: 408832K->0K(409216K), 0.6755540 secs] 615806K->211897K(1048192K) icms_dc=4 , 0.6757740 secs]Here, the scavenges took respectively 537 ms and 675 ms. In between these two scavenges, iCMS ran for a brief period as indicated by the icms_dc value, which indicates a duty-cycle. In this case the duty cycle was 4%. A simple calculation shows that the iCMS incremental step lasted for 4/100 \* (2824.209 - 2803.125 - 0.537) = 821 ms, i.e. 4% of the time between the two scavenges.Starting with 1.5, CMS has one more phase – concurrent abortable preclean. Abortable preclean is run between a 'concurrent preclean' and 'remark' until we have the desired occupancy in eden. This phase is added to help schedule the 'remark' phase so as to avoid back-to-back pauses for a scavenge closely followed by a CMS remark pause. In order to maximally separate a scavenge from a CMS remark pause, we attempt to schedule the CMS remark pause roughly mid-way between scavenges.There is a second reason why we do this. Immediately following a scavenge there are likely a large number of grey objects that need rescanning. The abortable preclean phase tries to deal with such newly grey objects thus reducing a subsequent CMS remark pause.The scheduling of 'remark' phase can be controlled by two jvm options CMSScheduleRemarkEdenSizeThreshold and CMSScheduleRemarkEdenPenetration. The defaults for these are 2m and 50% respectively. The first parameter determines the Eden size below which no attempt is made to schedule the CMS remark pause because the pay off is expected to be minuscule. The second parameter indicates the Eden occupancy at which a CMS remark is attempted. After 'concurrent preclean' if the Eden occupancy is above CMSScheduleRemarkEdenSizeThreshold, we start 'concurrent abortable preclean' and continue precleanig until we have CMSScheduleRemarkEdenPenetration percentage occupancy in eden, otherwise we schedule 'remark' phase immediately.7688.150: [CMS-concurrent-preclean-start]7688.186: [CMS-concurrent-preclean: 0.034/0.035 secs]7688.186: [CMS-concurrent-abortable-preclean-start]7688.465: [GC 7688.465: [ParNew: 1040940K->1464K(1044544K), 0.0165840 secs] 1343593K->304365K(2093120K), 0.0167509 secs]7690.093: [CMS-concurrent-abortable-preclean: 1.012/1.907 secs]7690.095: [GC[YG occupancy: 522484 K (1044544 K)]7690.095: [Rescan (parallel) , 0.3665541 secs]7690.462: [weak refs processing, 0.0003850 secs] [1 CMS-remark: 302901K(1048576K)] 825385K(2093120K), 0.3670690 secs]In the above log, after a preclean, 'abortable preclean' starts. After the young generation collection, the young gen occupancy drops down from 1040940K to 1464K. When young gen occupancy reaches 522484K which is 50% of the total capacity, precleaning is aborted and 'remark' phase is started. Note that in 1.5, young generation occupancy also gets printed in the final remark phase.For more detailed information and tips on GC tuning, please refer to the following documents:http://java.sun.com/docs/hotspot/gc5.0/gc_tuning_5.htmlhttp://java.sun.com/docs/hotspot/gc1.4.2/

CMS GC with -XX:+PrintGCDetails and -XX:+PrintGCTimeStamps prints a lot of information. Understanding this information can help in fine tuning various parameters of the application and CMS to...

Oracle

Integrated Cloud Applications & Platform Services