Re: logging fixes for last pre-ZBB JDK7-TL snapshot (6977677, 7016208, 7041595)

[Daniel D. Daugherty]

First, no apology is needed. I very much appreciate
the catch on your part.

Second, it seems that the pendulum that is the Logging API
continues to swing back and forth: We fix a deadlock... we
introduce a race... we fix the race... we introduce a deadlock...
lather, rinse, repeat...

I'll file a bug tomorrow and have a test ready sometime
tomorrow also. Sigh...

My gut says that this race is not that critical because
in a properly functioning system one of the threads would
get an IllegalArgumentException. Please let me know if
I'm misunderstanding what you're saying here...

Dan



On 5/16/2011 8:00 PM, David Holmes wrote:

Dan,

I'm sorry this didn't come through in time ...

Mandy Chung said the following on 05/17/11 05:22:

Logger.java

Looks good. The removal of the synchronization required by Logger.getLogger fixes the deadlock issue.

But this method now has a race condition:

 372     // Synchronization is not required here. All synchronization for

373 // adding a new Logger object is handled by LogManager.addLogger(). 374 public static Logger getLogger(String name, String resourceBundleName) {

 375         LogManager manager = LogManager.getLogManager();
 376         Logger result = manager.demandLogger(name);
 377         if (result.resourceBundleName == null) {
 378             // Note: we may get a MissingResourceException here.
 379             result.setupResourceInfo(resourceBundleName);

380 } else if (!result.resourceBundleName.equals(resourceBundleName)) { 381 throw new IllegalArgumentException(result.resourceBundleName +

 382                                 " != " + resourceBundleName);
 383         }
 384         return result;
 385     }

Two threads calling this method with the same name but different resource bundle names can both see null at line 377 and install their different resource bundles. That section needs to be atomic.

David
-----

LogManager.java

Retrying in a while loop is one way to fix weak ref / gc timing issue.

    What about if you refactor the addLogger method to add a new private

private method equivalent to addLogger (say add(Logger)) that will return

    logger if added successfully or null if not.

The addLogger method will return add(logger) != logger. The synchronization

    will be done in the new add method.

Would this fix 7016208? It seems to me that addLogger returning boolean

    is the cause for this bug.

Mandy

On 05/15/11 11:40, Daniel D. Daugherty wrote:

Greetings,

The final pre-ZBB JDK7-TL snapshot is happening @ 1700 PT on
Monday, May 14, 2011. This snapshot is targeted for JDK7-B143
or JDK7-B144 (I'm not sure which). Yes, we're still trying to
figure out how to merge our JDK & HotSpot Express processes
with Oracle processes. Please be patient while we iron out the
wrinkles...

I have three bug fixes for the java.util.logging area:

   6977677 3/2 Deadlock on logging subsystem initialization
   7016208 4/3 null sometimes returned by java.util.logging.Logger.
               getLogger(String name) in -server -Xcomp
   7041595 4/4 add lost test for 6487638

6977677 is a deadlock between java.util.logging.Logger.getLogger()
and LogManager.<clinit> via a PlatformLogger. This fix involves:

   src/share/classes/java/util/logging/Logger.java
   test/java/util/logging/LoggingDeadlock4.java

Mandy, I would like your review of the above bug fix.

7016208 is an unexpected null return from Logger.getLogger() due to
the lack of a strong reference. This fix involves:

   src/share/classes/java/util/logging/LogManager.java

Tom R., I would like your review of the above bug fix.

7041595 is just pushing a Logging deadlock test that got lost a
long time ago. This fix involves:

   test/java/util/logging/LoggingDeadlock3.java
   test/java/util/logging/LoggingDeadlock3.props

Because I'm fixing a deadlock in 6977677, I wanted to make sure
that this Logging deadlock test was back in the mix.

Here is the webrev URL:

   http://cr.openjdk.java.net/~dcubed/logging-batch-20110515-webrev/0/

The comments that I added to the code changes should make the
reason(s) for the code changes pretty self explanatory.

These changes have been run through JPRT and pass the "jdk_util"
tests on all platforms. I have also run SDK/JDK logging tests
and the VM/NSK logging tests on the following configs:

   Solaris X86 * {Client VM, Server VM} product * {-Xmixed, -Xcomp}
   WinXP * {Client VM, Server VM} product * {-Xmixed, -Xcomp}

Here is the summary from Solaris X86:

Summary of Test Results (8 result dirs)
=========================================
   all executed: 2264  all passed: 2264  all ignored: 0  all failed: 0
   time: 0 hour(s) 17 minute(s)

Here is the partial summary (6 of 8) from WinXP:

Summary of Test Results (6 result dirs)
=========================================
   all executed: 1160  all passed: 1160  all ignored: 0  all failed: 0
   time: 1 hour(s) 0 minute(s)

The last two VM/NSK test runs are still going; yes, WinXP is slower than

Solaris X86...

Thanks, in advance, for any reviews.

Dan