United StatesChange Country, Oracle Worldwide Web Sites Communities I am a... I want to...
Bug ID: JDK-6367204 CMS: Poor garbage collection performance
JDK-6367204 : CMS: Poor garbage collection performance

Details
Type:
Bug
Submit Date:
2005-12-24
Status:
Resolved
Updated Date:
2010-05-11
Project Name:
JDK
Resolved Date:
2006-02-09
Component:
hotspot
OS:
windows_2003
Sub-Component:
gc
CPU:
x86
Priority:
P1
Resolution:
Fixed
Affected Versions:
5.0u6
Fixed Versions:

Related Reports
Backport:
Relates:
Relates:

Sub Tasks

Description
Operating System:  Windows 2003, 64-bit
OS version:  2003, 64-bit
Product Name:  Java 2SE (Java 5)
Product version:  1.5.0_03 through 1.5.0_06
Hardware platform:  Windows, Intel
Severity : 1

Short description : Poor garbage collection performance

Full problem description:
When using large Java heaps (1GB, 2GB, 4GB, 16GB, and 28GB) garbage collection performance is performing poorly.  CMS parallel rescans range in length from 2 to 75 minutes and can choke the entire server.

Hardware being used is:

Dell PowerEdge 6800 with 32GB physical memory and 4 HT-Xeon processors (8 logical processors) running on Windows 2003 Advanced Server 64-bit edition.  We have run the tests using Java 1.5.0_03 through 1.5.0_06 with similar results.
Incremental CMS does not help used recommendations from the Garbage Collection Tuning documentation at http://java.sun.com/docs/hotspot/gc5.0/gc_tuning_5.html.  When using incremental CMS, gc???s happen periodically; however, long full GC???s are triggered very early on:
Stock generation sizes yield unacceptable results (long ParNew collections ~1 to ~4 seconds every second), and all live objects are immediate tenured due to tiny 64K survivor pools.  System spends > 20% of processing time in young collections.  Also, the longer the server is running, the longer the CMS GC???s take.
The system uses a large number of softly and weakly referenced data in addition to a number of strong referenced data.
An average light load for the system results in allocation of 1GB of memory every 8 to 9 seconds, with 1-2% eventually being tenured.  A heavy load will be more than double that amount.  All of the log files below are from the lightly loaded scenarios with the exception of the 75 minute CMS GC (this was at the full load).

Additional Information :

1) The application deployed.
- This is a custom multi-tier collaboration engine.  It consists of one or more servers and many clients.  This issue is in regards to a two-tier configuration (a server and 150 to 350 users).  The system is written in Java 5, uses NIO for network communications and uses an embedded DBJE system for data persistence (DBJE is Sleepcat Software???s pure Java Berkley DB implementation).

2) If this problem is seen frequently.
- Yes.  All the time.

3) Is the application crashing or hanging.
- Yes, it is hanging.  If we do not throttle the JVM via the ParallelGCThreads flag, the server will hang until the parallel rescan is complete (or power is cycled on the server).  The application has not crashed, but it is completely unusable because of the extremely long stop-the-world GC???s.

4) Its good that the most latest version is being tried and have you collected the dumps and logs.
- We have approximately 20GB of log files collected.  More information can be provided, however, proprietary information would need to be removed.  If you can provide me with a list of things you would like to see, we can work to accommodate that request.

                                    

Comments
WORK AROUND

"Don't use very large object arrays that mutate or hold young references," said he,
after having carefully donned his flame suit.
                                     
2006-01-27
SUGGESTED FIX

here are the context-diffs in a mustang workspace:

*** src/share/vm/memory/space.cpp-      Mon Dec 19 10:20:53 2005
--- src/share/vm/memory/space.cpp       Thu Jan 26 23:30:06 2006

*** 1,7 ****
  #ifdef USE_PRAGMA_IDENT_SRC
! #pragma ident "@(#)space.cpp  1.199 05/12/14 14:12:18 JVM"
  #endif
  /*
   * Copyright 2006 Sun Microsystems, Inc.  All rights reserved.
   * SUN PROPRIETARY/CONFIDENTIAL.  Use is subject to license terms.
   */
--- 1,7 ----
  #ifdef USE_PRAGMA_IDENT_SRC
! #pragma ident "@(#)space.cpp  1.200 06/01/26 23:30:06 JVM"
  #endif
  /*
   * Copyright 2006 Sun Microsystems, Inc.  All rights reserved.
   * SUN PROPRIETARY/CONFIDENTIAL.  Use is subject to license terms.
   */

*** 485,503 ****
    // This assert will not work when we go from cms space to perm
    // space, and use same closure. Easy fix deferred for later. XXX YSR
    // assert(prev == NULL || contains(prev), "Should be within space");
  
    bool last_was_obj_array = false;
!   HeapWord* addr;
    size_t size;
    if (prev > mr.start()) {
      addr = prev;
    } else {
!     addr = block_start(mr.start());
    }
    HeapWord* end_addr = mr.end();
!   MemRegion mr2(addr, end_addr);
    for (; addr < end_addr; addr += size) {
      size = block_size(addr);
      if (block_is_obj(addr)) {
        last_was_obj_array = cl->do_object_bm(oop(addr), mr2);
      } else {
--- 485,505 ----
    // This assert will not work when we go from cms space to perm
    // space, and use same closure. Easy fix deferred for later. XXX YSR
    // assert(prev == NULL || contains(prev), "Should be within space");
  
    bool last_was_obj_array = false;
!   HeapWord *addr, *addr2;
    size_t size;
    if (prev > mr.start()) {
+     addr2 = prev;
      addr  = prev;
    } else {
!     addr2 = mr.start();
!     addr  = block_start(addr2);
    }
    HeapWord* end_addr = mr.end();
!   MemRegion mr2(addr2, end_addr);
    for (; addr < end_addr; addr += size) {
      size = block_size(addr);
      if (block_is_obj(addr)) {
        last_was_obj_array = cl->do_object_bm(oop(addr), mr2);
      } else {

*** 522,540 ****
    // See comment above (in more general method above) in case you
    // happen to use this method.
    assert(prev == NULL || is_in_reserved(prev), "Should be within space");
  
    bool last_was_obj_array = false;
!   HeapWord* addr;
    size_t size;
    if (prev > mr.start()) {
      addr = prev;
    } else {
!     addr = block_start(mr.start());
    }
    HeapWord* end_addr = mr.end();
!   MemRegion mr2(addr, end_addr);
    for (; addr < end_addr; addr += size) {
      oop obj = oop(addr);
      size    = obj->size();
      last_was_obj_array = cl->do_object_bm(obj, mr2);
    }
--- 524,544 ----
    // See comment above (in more general method above) in case you
    // happen to use this method.
    assert(prev == NULL || is_in_reserved(prev), "Should be within space");
  
    bool last_was_obj_array = false;
!   HeapWord *addr, *addr2;
    size_t size;
    if (prev > mr.start()) {
+     addr2 = prev;
      addr  = prev;
    } else {
!     addr2 = mr.start();
!     addr  = block_start(addr2);
    }
    HeapWord* end_addr = mr.end();
!   MemRegion mr2(addr2, end_addr);
    for (; addr < end_addr; addr += size) {
      oop obj = oop(addr);
      size    = obj->size();
      last_was_obj_array = cl->do_object_bm(obj, mr2);
    }


------------------

here's the webrev (in a mustang workspace):

   http://analemma.sfbay.sun.com/net/spot/scratch/ysr/policy/webrev/
                                     
2006-01-27
EVALUATION

There was a coding error in space::object_iterate_m() which would
cause quadratic complexity when scanning large somewhat sparsely
dirty arrays (spanning many cards). In the case of this customer
there were some arrays that were many millions of cards large
(some were 36 MB large or larger). Correcting the coding error
allowed the dirty cards to be precisely scanned, and reduced
the rescan pauses to a more acceptable range (by more than
two orders of magnitude).

Any application with large object arrays (which mutate or hold
pointers to young gen) would be susceptible to
large remark pauses because of this bug.

The performance bug was inadvertently introduced when making the
fix in 4756801. Unfortunately, the performance tests performed
for that fix verification did not reveal the pathology because
the performance before the fix was bad and we seemed to have
simply traded one performance pathology (scanning entire
arrays) for another (repeatedly scanning prefixes of sparsely
dirty arrays).

Even with this performance fix there will be another performance
issue related to repeated BOT queries for sparsely dirty cards.
(This affects both CMS and scavenges.) That bug will be addressed
in a separate CR 6391214.
                                     
2006-01-27
SUGGESTED FIX

Job ID:                 20060131135728.ysr.policy
Original workspace:     neeraja:/net/spot/scratch/ysr/policy
Submitter:              ysr
Archived data:          /net/prt-archiver.sfbay/data/archived_workspaces/main/gc_baseline/2006/20060131135728.ysr.policy/
Webrev:                 http://analemma.sfbay.sun.com/net/prt-archiver.sfbay/data/archived_workspaces/main/gc_baseline/2006/20060131135728.ysr.policy/workspace/webrevs/webrev-2006.01.31/index.html

Fixed 6367204: CMS: Poor garbage collection performance

  Webrev: http://analemma.sfbay/net/spot/scratch/ysr/policy/webrev

The customer's application turned out to have some very
large arrays (some as large as 36 MB or larger) which
were subject to some mutation during the long marking phase
(due to the large heap) and the precleaning phase (due to the
mutation).

In 5.0u1 I had fixed 4756801, which was supposed to replace
the imprecise scanning of entire object arrays by the
precise scanning of the dirty portions thereof. When fixing
that bug, I had inadvertently introduced this error during
the course of some code clean-up. The performance issue
was not found then because we merely traded one performance
pathology for another. 

The problem can affect any application that has large object
arrays that are subject to some mutation.
Instead of scanning precisely the dirty cards of large arrays,
we ended up (repeatedly) scanning the entire prefix of
that array ending in the dirty card! Clearly, we were
doing O(n.k) work for scanning k dirty card (ranges) in
a large object of size n, instead of the intended O(k);
in the worst case this could be O(n2).

The fix, which has been tested on-site at
General Dynamics, showed a 245 x improvement in the
remark pause time. (More tuning is needed, but this
fixes the spectacularly bad results seen earlier;
further residual performance issues will be handled
under a separate CR.)

Thanks to Syed Rayadurg who was on-site with the customer
for running experiments and helping with the diagnosis;
to Vaibhav Kulkarni for helping with obtaining and
analyzing performance data from customer; to Poonam
Bajaj for the prompt backport to Tiger that allowed
prompt on-site fix verification.

Reviewed by: John Coomes, Peter Kessler, Jon Masamitsu
Approved by: Mustang Core Team (Penni Henry)

Fix Verified: yes

Verification Testing: 
   . customer ran with 28 GB heap and got a 245 x reduction in CMS remark
     pause times
 
Other testing: specjvm, PRT, refworkload, runThese quick (w/CMS)
   . Ashwin has been running big apps on the 5.0u7 avatar
     of this bug fix.
                                     
2006-02-04



Hardware and Software, Engineered to Work Together