During investigation of the following bug fix:
6977677 3/2 Deadlock on logging subsystem initialization
I did a detailed crawl through the uses of locking in LogManager.java
and Logger.java. I took detailed notes and dropped them into the code
in the form of comments. I also made some improvements to the code
that aren't related to locking, but I still thought they might be useful.
I'm attaching the "hg diff" output as locking_notes.diff.
The most important of the possible changes are in the use of
double-check locking during LogManager initialization:
diff -r 9861df231e9e src/share/classes/java/util/logging/LogManager.java
--- a/src/share/classes/java/util/logging/LogManager.java Mon May 16 12:58:48 2011 -0700
+++ b/src/share/classes/java/util/logging/LogManager.java Mon May 16 17:21:42 2011 -0600
@@ -161,13 +161,12 @@
private LogNode root = new LogNode(null);
private Logger rootLogger;
- // Have we done the primordial reading of the configuration file?
+ // Has a thread started the primordial reading of the configuration file?
// (Must be done after a suitable amount of java.lang.System
// initialization has been done)
- private volatile boolean readPrimordialConfiguration;
- // Have we initialized global (root) handlers yet?
- // This gets set to false in readConfiguration
- private boolean initializedGlobalHandlers = true;
+ private boolean isReadingOrHasReadPrimordialConfiguration;
+ // don't need to init global LoggerHandlers until config is read
+ private boolean needToInitGlobalHandlers = false;
// True if JVM death is imminent and the exit hook has been called.
private boolean deathImminent;
@@ -268,34 +284,83 @@
return manager;
}
- private void readPrimordialConfiguration() {
- if (!readPrimordialConfiguration) {
- synchronized (this) {
- if (!readPrimordialConfiguration) {
- // If System.in/out/err are null, it's a good
- // indication that we're still in the
- // bootstrapping phase
- if (System.out == null) {
- return;
- }
- readPrimordialConfiguration = true;
- try {
- AccessController.doPrivileged(new PrivilegedExceptionAction<Object>() {
- public Object run() throws Exception {
- readConfiguration();
+// - this method uses the double-check idiom which does not work with
+// non-volatile, non-primitive values; see Josh Bloch's "Effective Java",
+// Item 48: Synchronize access to share mutable data.
+// - added in JDK1.4.2-B05 as part of the fix for the following bug:
+// 4747357 4/3 Logging should be initialized lazily
+// when it was added, readPrimordialConfiguration was set to true at
+// the bottom of the synchronized block
+// - the doPrivileged() wrapper was added in JDK1.4.2-B05 by the fix for
+// the following bug:
+// 4761452 3/3 Logging API tests failing on latest TL 1.4.2
+// - the setting of readPrimordialConfiguration to true was moved before
+// the call to readConfiguration() in JDK1.4.2-B08 by the fix for the
+// following bug:
+// 4775066 4/4 NSK/LOGGING test readcfg003 fails in both client and server VM
+// the variable should have been renamed to reflect that fact that it
+// is now marks two different states; also, I don't like having a
+// field and a method with the same name
+// - because of the use of double-check locking, it is possible for a
+// racing thread to by-pass the synchronization check and observe
+// intermediate state in the non-volatile objects setup by
+// readConfiguration() or redirectPlatformLoggers()
+// Conclusion: needs synchronization on every call
- // Platform loggers begin to delegate to java.util.logging.Logger
- sun.util.logging.PlatformLogger.redirectPlatformLoggers();
+ // Synchronization is required on every call to this method. The
+ // first non-bootstrapping call will initialize non-volatile objects
+ // in addition to primitive types so double-check locking will not
+ // work here.
+ private synchronized void readPrimordialConfiguration() {
+ if (isReadingOrHasReadPrimordialConfiguration) {
+ // There are three reasons for being in this block:
+ // 1) The readConfiguration() or redirectPlatformLoggers()
+ // calls below can cause a recursive call to this method
+ // by the thread that is doing the primordial reading.
+ // This check catches that case and prevents infinite
+ // recursion. Reminder: monitors can be recursively
+ // entered by the same thread in Java which is why this
+ // block of code can see the "is reading" state.
+ // 2) A thread that is racing with the thread that is doing
+ // the primordial reading gets here after it acquires the
+ // monitor, but there is no work left to do. This is a
+ // case of the "has read" state.
+ // 3) A thread making a simple logging call gets here after
+ // it acquires the monitor, but there is no work to do.
+ // This is another "has read" state and is really the
+ // same as the previous case, but it is called out
+ // specifically to make it clear that every call has to
+ // go through this dance.
+ return;
+ }
- return null;
- }
- });
- } catch (Exception ex) {
- // System.err.println("Can't read logging configuration:");
- // ex.printStackTrace();
- }
+ // If System.in/out/err are null, it's a good indication that
+ // we're still in the bootstrapping phase
+ if (System.out == null) {
+ return;
+ }
+
+ // Only one thread needs to do the primordial reading of the
+ // configuration file so mark that the job is being done
+ isReadingOrHasReadPrimordialConfiguration = true;
+
+ try {
+ AccessController.doPrivileged(new PrivilegedExceptionAction<Object>() {
+ public Object run() throws Exception {
+ readConfiguration(); // can cause recursion
+
+ // Platform loggers begin to delegate to
+ // java.util.logging.Logger; can cause recursion
+ sun.util.logging.PlatformLogger.redirectPlatformLoggers();
+
+ return null;
}
- }
+ });
+ } catch (Exception ex) {
+ // We quietly suppress any exceptions during primordial config
+ // Uncomment the following for debugging purposes only:
+ // System.err.println("Can't read logging configuration:");
+ // ex.printStackTrace();
}
}
During the code review of the following bug fix:
6977677 3/2 Deadlock on logging subsystem initialization
Karen commented on the new DeadLocking4.java test:
> When we get to JDK8 I suspect that the LoggingDeadlock4.java test will
> need cleaning up so it doesn't depend on the awt package.
During the code review of the following bug fix:
7016208 4/3 null sometimes returned by java.util.logging.Logger.
getLogger(String name) in -server -Xcomp
some interesting comments arose and I want to record them here.
One of Tom's comments:
> You can drop newLogger completely and just use result as in
>
> result = new Logger(name, null);
>
> You can also just use a while loop instead of an if/do/while.
>
> Logger result = getLogger(name);
> while (result == null) {
> result = new Logger(name, null);
> if (addLogger(result)) {
> return result;
> }
> result = getLogger(name);
> }
> return result;
One of Mandy's comments:
> 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 the other logger if the logger's name
> already registered.
>
> 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.