5 Replies Latest reply on Sep 15, 2010 2:58 AM by 807557

    Boosted Mode

      Im having a difficult time determining what causes the gc to go into boosted mode. I was under the impression that if the free memory falls below a certain point than it would go into boosted mode. That was the ONLY condition. Or so that's what I've read.

      You have the option to set BoostedMinFreeBytes, which is the minimum amount of memory needed to stay in normal mode. I understand that formulas are calculated each cycle (which set the sliding value, and threshold for the next gc cycle).

      I was under the impression that the true indicator on whether the collector will go into boosted mode is the value set for "Next boosted threshold: " which is displayed for each cycle in the gc log file. However, I see the gc go into boosted mode when the amount of free memory is above this number. So I'm very confused on what is triggering the gc to go into boosted mode.

      Also, I havent been able to find any information on what the "End free bytes: " or "Min free bytes: " stands for in the gc log file.

      Any help would be greatly appreciated.

        • 1. Re: Boosted Mode

          First, concerning "end" and "min" free bytes, they come from the fact that the RTGC is concurrent.

          The RTGC starts trying to recycle memory when the free memory goes below a first threshold. While it is detecting objects that must survive, your application threads are still allocating memory. Hence, the free amount will continue to decrease. Once the RTGC has marked all the 'live' objects, it will gradually sweep the other ones. This increases the free memory (but the application may still decrease it concurrently). "Min" will be the minimum value during this whole process. This is the number that matters. If too low, applications threads may have to block wating for the RTGC to complete its current cycle and free some memory. "End" is the free memory when the RTGC goes back to sleep. Most users can ignore it.

          As stated above, "min" is the value that matters and that probably explains why you entered the boosted (or critical) mode.

          Note also that if a high priority thread calls System.gc(), the system takes into account its priority to decide in which mode to run the RTGC. Thus, it may directly go to boosted mode. This may also happen with a
          com.sun.rtsjx.FullyConcurrentGarbageCollector.startAsyncGC(int priority) call.

          Best regards,

          • 2. Re: Boosted Mode
            That's a really good point, I didnt think of that. Do you know of any good ways to profile the memory use? Yourkit unfortunately will not work and I've tried several versions (8.0 which works with Java 5.0 processes and 9.0 which works with Java 6 processes). I'd prefer not to use JProbe because the cost of a license is outrageous, and connecting it to a process is cumbersome.

            Thanks again for the pointers :)
            • 3. Re: Boosted Mode

              Depends on what you mean by profiling the memory use.

              Profilers that keep tracks of each allocation are very intrusive, disrupting the determinism. In addition, those that use JVMPI agents loaded in the JVM will automatically turn-off the RTGC. If you need this kind of profiling, it is often better to simulate your application on a non real-time JVM and benefit from the latest tools available on the market. If you are just looking for memory leaks, the memory dump provided by jmap might be sufficient to analyze your issue.

              On the other hand, we developed specific tools in JavaRTS to efficiently track down the amount of memory used (e.g. with very limited impact on the determinism). In addition to new memory management MBeans (accessible from instance from jconsole or VisualVM), we have added optimized DTrace probes to monitor per-thread memory consumption and/or quantum based notification: [http://download.oracle.com/javase/realtime/doc_2.2u1/release/JavaRTSDTraceProvider.html#RTGC|http://download.oracle.com/javase/realtime/doc_2.2u1/release/JavaRTSDTraceProvider.html#RTGC]

              For more information, have a look at the "Easily Tuning Your Real-Time Application" JavaOne 2009 technical session:

              • 4. Re: Boosted Mode
                First off, thank you so much for your helpful insight. I am getting much further in my quest to keep the collector out of boosted mode. From your earlier post, it sounds like it should not be possible for the collector to go into boosted mode if the "Min free bytes" value is greater than the previous cycle's "Next boosted threshold" value. Is that a true statement? I'm seeing cases where that is happening. The problem is I cannot afford to give up a second CPU to the garbage collector when the free memory level isnt really an issue. These cases where there seems to be adequate memory left yet we're jumping into boosted mode is a real mystery. Below are the stats of 2 cycles, you can see that Ive made the boosted threshold static at 4MB. I thought this may be too low of a number and it was being ignored so i increased it to 24MB, but still had the same issue of going into boosted.

                I would use DTrace but i believe that requires a Solaris box, which unfortunately I do not have. JMap would be very helpful, however I cannot determine when to collect a heap dump during the run. That's why a profiler would be ideal, I could record all the memory allocations for a section of time. I was thinking if I could run JConosle and then when the memory usage spikes collect a heap dump through JMap..but Im having issues running jconsole with my real-time java process. I think JConsole should work with RTJS because it's part of the JRE.

                GC cycle stats:
                RTGC completed in normal mode (1 CPUs at priority 11)
                End free bytes: 84995424 bytes
                Min free bytes: 104929312 bytes
                Next boosted threshold: 4194304 bytes
                Next normal threshold: 134217728 bytes
                Allocations during the GC:
                in deterministic mode: 0 bytes (worst 178544448 bytes, average 28817407 bytes)
                in boosted+deterministic modes: 0 bytes (worst 178544448 bytes, average 28817407 bytes)
                in normal+boosted+deterministic modes: 33092960 bytes (worst 221364928 bytes, average 218508 bytes)
                Total CPU cost: 2558771754 nanoseconds
                Pacing CPU cost: 174355 (0 %)
                Serial CPU cost: 65883197 (2 %)
                Parallel worker_0 CPU cost: 2175771165 (85 %)
                Parallel worker_1 CPU cost: 316669972 (12 %)
                Bytes allocated by critical threads:
                in deterministic mode: 0 bytes
                total for this cycle: 30748864 bytes
                grand total: 28216015808 bytes
                Minimum RTGCCriticalReservedBytes: 5888 bytes
                18619.167: [GC, 0.0000010 secs]
                18619.167: [GCPreMarking, GCPreMarking 1.036000/0.003000 CPU/elapsed milli secs]
                18619.167: [GCWhitening, GCWhitening 0.917000/0.003000 CPU/elapsed milli secs]
                18619.167: [GCActivatingStartGCBarrier, GCActivatingStartGCBarrier 0.862000/0.003000 CPU/elapsed milli secs]
                18619.168: [GCStartBlackening, GCStartBlackening 0.892000/0.003000 CPU/elapsed milli secs]
                18619.168: [GCPreStackWork, GCPreStackWork 0.880000/0.003000 CPU/elapsed milli secs]
                18619.205: [GCThreadsStartScan, GCThreadsStartScan 1.096000/0.003000 CPU/elapsed milli secs]
                18619.206: [GCBlackening, GCBlackening 6.677000/0.009000 CPU/elapsed milli secs]
                18620.592: [GCMarkingLateRoots, GCMarkingLateRoots 1.066000/0.003000 CPU/elapsed milli secs]
                18620.592: [GCCompleteMarking, GCCompleteMarking 0.911000/0.003000 CPU/elapsed milli secs]
                18620.592: [GCProcessingReferences, GCProcessingReferences 0.904000/0.003000 CPU/elapsed milli secs]
                18620.593: [GCSweeping, GCSweeping 1.083000/0.003000 CPU/elapsed milli secs]
                18620.935: [GCFinishing, GCFinishing 1.012000/0.003000 CPU/elapsed milli secs]
                18620.984: [GCZeroing, GCZeroing 1.240000/0.003000 CPU/elapsed milli secs]
                250738272->258681792(335544320, non-fragmented: current 76862528 / min 42120864 / worst 4190080, biggest 5504, blocked threads: max 0 / still blocked 0 requesting 0 byte
                s, dark matter: 43165600 in 626586 blocks smaller than 256) <boosted during 1159687 microseconds> {CPU load: 1.46 recycling / 1.45 since last GC}
                Mem drop statistics: 40M, avg 14M for last 8384 stable iterations, std_dev 7M, goal 16777216 => RTGC should start at 40894464

                GC cycle stats:
                RTGC completed in boosted mode (2 CPUs at priority 11)
                End free bytes: 76862528 bytes
                Min free bytes: 86939360 bytes
                Next boosted threshold: 4194304 bytes
                Next normal threshold: 134217728 bytes
                Allocations during the GC:
                in deterministic mode: 0 bytes (worst 178544448 bytes, average 28667322 bytes)
                in boosted+deterministic modes: 8856128 bytes (worst 178544448 bytes, average 28667322 bytes)
                in normal+boosted+deterministic modes: 44980064 bytes (worst 221364928 bytes, average 223780 bytes)
                Total CPU cost: 3107463968 nanoseconds
                Pacing CPU cost: 229649 (0 %)
                Serial CPU cost: 84014263 (2 %)
                Parallel worker_0 CPU cost: 1978377484 (63 %)
                Parallel worker_1 CPU cost: 1044841057 (33 %)
                Bytes allocated by critical threads:
                in deterministic mode: 0 bytes
                total for this cycle: 41958944 bytes
                grand total: 28258126976 bytes
                Minimum RTGCCriticalReservedBytes: 5888 bytes
                18621.305: [GC, 0.0000010 secs]
                18621.306: [GCPreMarking, GCPreMarking 0.881000/0.003000 CPU/elapsed milli secs]
                18621.306: [GCWhitening, GCWhitening 0.868000/0.003000 CPU/elapsed milli secs]
                18621.306: [GCActivatingStartGCBarrier, GCActivatingStartGCBarrier 0.850000/0.002000 CPU/elapsed milli secs]
                18621.306: [GCStartBlackening, GCStartBlackening 1.083000/0.003000 CPU/elapsed milli secs]
                18621.306: [GCPreStackWork, GCPreStackWork 0.857000/0.003000 CPU/elapsed milli secs]
                18621.344: [GCThreadsStartScan, GCThreadsStartScan 1.192000/0.004000 CPU/elapsed milli secs]
                18621.345: [GCBlackening, GCBlackening 1.018000/0.003000 CPU/elapsed milli secs]
                18622.893: [GCMarkingLateRoots, GCMarkingLateRoots 1.084000/0.003000 CPU/elapsed milli secs]
                18622.893: [GCCompleteMarking, GCCompleteMarking 1.006000/0.003000 CPU/elapsed milli secs]
                18622.894: [GCProcessingReferences, GCProcessingReferences 1.096000/0.003000 CPU/elapsed milli secs]
                18622.894: [GCSweeping, GCSweeping 1.108000/0.003000 CPU/elapsed milli secs]
                18623.345: [GCFinishing, GCFinishing 1.335000/0.004000 CPU/elapsed milli secs]
                18623.366: [GCZeroing, GCZeroing 1.556000/0.003000 CPU/elapsed milli secs]
                258690464->240059808(335544320, non-fragmented: current 95484512 / min 61505888 / worst 4190080, biggest 4288, blocked threads: max 0 / still blocked 0 requesting 0 bytes, dark matter: 46573056 in 543840 blocks smaller than 256) <completed without boosting> {CPU load: 1.11 recycling / 1.10 since last GC}
                Mem drop statistics: 14M, avg 14M for last 8385 stable iterations, std_dev 7M, goal 16777216 => RTGC should start at 40894464
                • 5. Re: Boosted Mode

                  Sorry for this late answer. We have been a bit busy preparing JavaOne and OracleWorld.

                  As stated in my initial e-mail, there are other reasons why the GC could go to boosted mode.
                  For instance, it happens when a high priority threads calls System.gc(). Thus, depending on
                  what your applications does, you may hit one of these logical boosting cases.

                  It is hard to be exhaustive about all these cases.

                  It seems that in your case there is a lot of fragmentation. The dark matter granularity was gradually decreased to 256 bytes and we still have a lot of dark matter (e.g. contiguous blocks of free memory smaller than this granularity). Now, if a high priority threads request a big chunk of memory and we have to split it, the GC might automatically boost the RTGC to try to recycle memory and avoid more splitting.

                  If your goal is to completely avoid boosting the GC over your application threads, then the simplest solution is to change the boosted priority of the RTGC so that it is equal to its normal priority. This will cause the boosting to have no effect on your application... but remember that we probably had good reasons to ask for a boost :-)