Re: Garbage collection race condition before final checks
On 11/15/11 10:20 AM, Gary Adams wrote: Added PlatformLoggingMXBeanTest to the 7067691 bug fix, e.g. instance variables for Logger variables to prevent premature weak reference collection. http://cr.openjdk.java.net/~gadams/7067691/ Gary, I have pushed your changeset: http://hg.openjdk.java.net/jdk8/tl/jdk/rev/3cd7dcf4a302 Mandy
Re: Garbage collection race condition before final checks
Gary: Please do not start discussing other bugs in this thread - please
keep them distinct.
Remi: please add any comments to the discussion threads on those other bugs.
Thanks
David
On 16/11/2011 12:30 AM, Rémi Forax wrote:
On 11/15/2011 01:26 PM, Gary Adams wrote:
Added PlatformLoggingMXBeanTest to the 7067691 bug fix,
e.g. instance variables for Logger variables to prevent premature
weak reference collection.
http://cr.openjdk.java.net/~gadams/7067691/
Hi Garry,
Fresh webrevs for the other work in progress bug fixes.
http://cr.openjdk.java.net/~gadams/6731620/
You can declare and initialize elapsed at the same place :
final long elapsed = System.currentTimeMillis() - start;
otherwise, it looks ok.
http://cr.openjdk.java.net/~gadams/6818464/
if you want to have a variable changed in an inner class, the usual idiom
is to use an array of one element.
public static void main (String[] args) throws Exception {
+ final Thread[] tdThread = new Thread[1];
Timer t = new Timer();
// Start a mean event that kills the timer thread
t.schedule(new TimerTask() {
public void run() {
+ tdThread[0] = Thread.currentThread();
throw new ThreadDeath();
}
}, 0);
// Wait for mean event to do the deed and thread to die.
try {
+ do {
Thread.sleep(100);
+ } while(tdThread[0] == null);
} catch(InterruptedException e) {
}
+ tdThread[0].join();
// Try to start another event
try {
// Timer thread is dead now
t.schedule(new TimerTask() {
http://cr.openjdk.java.net/~gadams/6860309/
This one is ok for me :)
http://cr.openjdk.java.net/~gadams/7084033/
Thumb up for this one too !
cheers,
Rémi
On 11/10/11 09:41 AM, Gary Adams wrote:
On 11/ 8/11 11:13 PM, Mandy Chung wrote:
Thanks for picking up this bug and fixing this intermittent issue.
PlatformLoggingMXBeanTest.java in the same directory has the same
issue. It'd be good to fix that with the same CR. These tests were
copied from test/java/util/logging/LoggingMXBeanTest.java. I haven't
looked in details but I wonder why the test/java/util/logging tests
don't have this intermittent issue and I suspect it holds a strong
reference.
I attempted to break PlatformLoggingMXBeanTest.java with a generous
application of
GC calls, but I could not get it to fail in the same manner as the
other test. It may be
failing due to a different condition.
Re: Garbage collection race condition before final checks
On 11/ 8/11 11:13 PM, Mandy Chung wrote: Thanks for picking up this bug and fixing this intermittent issue. PlatformLoggingMXBeanTest.java in the same directory has the same issue. It'd be good to fix that with the same CR. These tests were copied from test/java/util/logging/LoggingMXBeanTest.java. I haven't looked in details but I wonder why the test/java/util/logging tests don't have this intermittent issue and I suspect it holds a strong reference. I attempted to break PlatformLoggingMXBeanTest.java with a generous application of GC calls, but I could not get it to fail in the same manner as the other test. It may be failing due to a different condition.
Re: Garbage collection race condition before final checks
On 08/11/2011 15:35, Gary Adams wrote: Here's another intermittent bug that is attributed to the garbage collection of the loggers before the final static check can be applied in the test. CR#7067691 : java/lang/management/PlatformLoggingMXBean/LoggingMXBeanTest.java failing intermittently I agree with Mandy that it would be great to do a quick audit of the other logging (and PlatformLoggingMXBean) tests to see if we have similar issues. I should explain that one reason why these test failures may not have been observed in the past is because most people ran jtreg in its default mode (called othervm mode, where each tests runs in its own VM). Nowadays we run the tests via the make file or use jtreg -agentvm so that tests are running sequentially in an agent VM. Not all areas can run in agent VM mode yet but for the areas that do then we get a good speed up as the startup cost is eliminated and also it's possible to have a pool of agent VMs to make use of all cores when doing test runs (-agentvm -concurrency:auto for example). However agent VM makes things less predictable and for these tests it means that the GC will be unpredictable which is why this test was failing only very intermittently. Anyway, the changes look fine to me. I agree with Mandy that many logger1 and logger2 could be instance variables. I would suggest proxy or something more readable rather than testp for the LoggingMXBean proxy. I also agree with Mandy's comment about adding the @bug. -Alan.
Re: Garbage collection race condition before final checks
On 11/8/11 11:13 PM, Mandy Chung wrote:
Gary,
Thanks for picking up this bug and fixing this intermittent issue.
PlatformLoggingMXBeanTest.java in the same directory has the same
issue. It'd be good to fix that with the same CR. These tests were
copied from test/java/util/logging/LoggingMXBeanTest.java. I haven't
looked in details but I wonder why the test/java/util/logging tests
don't have this intermittent issue and I suspect it holds a strong
reference.
I'll take a look at the other tests to see if they suffer from the
same issue. I was able to force the intermittent bugs to reproduce quickly
with a strategic GC in the worst possible place.
A couple comment to the fix:
On 11/8/2011 7:35 AM, Gary Adams wrote:
diff --git
a/test/java/lang/management/PlatformLoggingMXBean/LoggingMXBeanTest.java
b/test/java/lang/management/PlatformLoggingMXBean/LoggingMXBeanTest.java
---
a/test/java/lang/management/PlatformLoggingMXBean/LoggingMXBeanTest.java
+++
b/test/java/lang/management/PlatformLoggingMXBean/LoggingMXBeanTest.java
Please add the CR number to @bug tag.
Will do.
@@ -42,6 +42,9 @@
static String LOGGER_NAME_1 = com.sun.management.Logger;
static String LOGGER_NAME_2 = com.sun.management.Logger.Logger2;
static String UNKNOWN_LOGGER_NAME = com.sun.management.Unknown;
+static Logger logger1;
+static Logger logger2;
It'd be good to add a comment why you want to keep a strong reference
to the logger. Minor nit: could make them as instance variables as
they are part of the LoggingMXBeanTest instance.
I'll give it a try.
+static LoggingMXBeanTest testp;
public static void main(String[] argv) throws Exception {
MBeanServer mbs = ManagementFactory.getPlatformMBeanServer();
@@ -51,7 +54,7 @@
LoggingMXBean.class);
// test LoggingMXBean proxy
-LoggingMXBeanTest p = new LoggingMXBeanTest(proxy);
+testp = new LoggingMXBeanTest(proxy);
Could we make checkAttributes as an instance method to
LoggingMXBeanTest object so that you don't need the static variable?
My preference is to leave a test as intact as possible
from how the original test was written. e.g. do the minimum
required to make the test reliable. These regression tests
are meant to confirm that a particular issue does not slip
back into the code base. Changing checkAttributes to be
an instance method is not essential to getting the test to
work properly. Better to get 10 intermittent tests to work reliably
rather than get 1 test polished to perfection. $.02
// check if the attributes implemented by PlatformLoggingMXBean
// and LoggingMXBean return the same value
@@ -59,14 +62,18 @@
ManagementFactory.getPlatformMXBean(mbs,
PlatformLoggingMXBean.class);
checkAttributes(proxy, mxbean);
+
+logger1 = null;
+logger2 = null;
+testp = null;
With the above suggested change, I think these 3 lines are not needed.
OK
}
// same verification as in java/util/logging/LoggingMXBeanTest2
public LoggingMXBeanTest(LoggingMXBean mbean) throws Exception {
-Logger logger1 = Logger.getLogger( LOGGER_NAME_1 );
+logger1 = Logger.getLogger( LOGGER_NAME_1 );
logger1.setLevel(Level.FINE);
-Logger logger2 = Logger.getLogger( LOGGER_NAME_2 );
+logger2 = Logger.getLogger( LOGGER_NAME_2 );
logger2.setLevel(null);
/*
@@ -207,6 +214,18 @@
// verify logger names
ListString loggers1 = mxbean1.getLoggerNames();
ListString loggers2 = mxbean2.getLoggerNames();
+
+// Print the two logger lists for diagnostic purposes
+System.out.println( : LoggingMXBean + loggers1);
+System.out.println( : PlatformLoggingMXBean + loggers2);
+
+// Print the list of logger level comparisons for diagnostic
purposes
+for (String logger : loggers1) {
+System.out.println (: Level ( + logger
++ , + mxbean1.getLoggerLevel(logger)
++ , + mxbean2.getLoggerLevel(logger) + ));
+}
It might be good to keep these diagnostic message to be printed only
when it throws an exception? Extra diagnostic information is good but
just want to keep the volume of traces reasonable not to make the
output harder to use.
We can probably delete the diagnostic output, now that the problem
is clearly identified.
Thanks again for fixing it.
Alan pointed out a pile of teststabilization bugs that have been tagged.
I'll see if any of those were suffering from the same issue found here.
Mandy
Re: Garbage collection race condition before final checks
Here's an updated diff :
- added current CR# to the @bug tag
- made logger1 and logger2 instance variables
- renamed test instance variable lmxbeantest
- removed excessive diagnostic print outs
--- a/test/java/lang/management/PlatformLoggingMXBean/LoggingMXBeanTest.java
+++ b/test/java/lang/management/PlatformLoggingMXBean/LoggingMXBeanTest.java
@@ -23,7 +23,7 @@
/*
* @test
- * @bug 7024172
+ * @bug 7024172 7067691
* @summary Test if proxy for PlatformLoggingMXBean is equivalent
* to proxy for LoggingMXBean
*
@@ -43,6 +43,13 @@
static String LOGGER_NAME_2 = com.sun.management.Logger.Logger2;
static String UNKNOWN_LOGGER_NAME = com.sun.management.Unknown;
+// These instance variables prevent premature logger garbage collection
+// See getLogger() weak reference warnings.
+Logger logger1;
+Logger logger2;
+
+static LoggingMXBeanTest lmxbeantest;
+
public static void main(String[] argv) throws Exception {
MBeanServer mbs = ManagementFactory.getPlatformMBeanServer();
LoggingMXBean proxy =
@@ -51,7 +58,7 @@
LoggingMXBean.class);
// test LoggingMXBean proxy
-LoggingMXBeanTest p = new LoggingMXBeanTest(proxy);
+lmxbeantest = new LoggingMXBeanTest(proxy);
// check if the attributes implemented by PlatformLoggingMXBean
// and LoggingMXBean return the same value
@@ -59,14 +66,16 @@
ManagementFactory.getPlatformMXBean(mbs,
PlatformLoggingMXBean.class);
checkAttributes(proxy, mxbean);
+
+lmxbeantest = null;
}
// same verification as in java/util/logging/LoggingMXBeanTest2
public LoggingMXBeanTest(LoggingMXBean mbean) throws Exception {
-Logger logger1 = Logger.getLogger( LOGGER_NAME_1 );
+logger1 = Logger.getLogger( LOGGER_NAME_1 );
logger1.setLevel(Level.FINE);
-Logger logger2 = Logger.getLogger( LOGGER_NAME_2 );
+logger2 = Logger.getLogger( LOGGER_NAME_2 );
logger2.setLevel(null);
/*
@@ -207,6 +216,7 @@
// verify logger names
ListString loggers1 = mxbean1.getLoggerNames();
ListString loggers2 = mxbean2.getLoggerNames();
+
if (loggers1.size() != loggers2.size())
throw new RuntimeException(LoggerNames: unmatched number of
entries);
ListString loggers3 = new ArrayList(loggers1);
@@ -219,7 +229,10 @@
if (!mxbean1.getLoggerLevel(logger)
.equals(mxbean2.getLoggerLevel(logger)))
throw new RuntimeException(
-LoggerLevel: unmatched level for + logger);
+LoggerLevel: unmatched level for ( + logger
++ , + mxbean1.getLoggerLevel(logger)
++ , + mxbean2.getLoggerLevel(logger) + ));
+
if (!mxbean1.getParentLoggerName(logger)
.equals(mxbean2.getParentLoggerName(logger)))
throw new RuntimeException(
On 11/ 9/11 04:08 AM, Alan Bateman wrote:
On 08/11/2011 15:35, Gary Adams wrote:
Here's another intermittent bug that is attributed
to the garbage collection of the loggers before the
final static check can be applied in the test.
CR#7067691 :
java/lang/management/PlatformLoggingMXBean/LoggingMXBeanTest.java failing
intermittently
I agree with Mandy that it would be great to do a quick audit of the other
logging (and PlatformLoggingMXBean) tests to see if we have similar issues. I
should explain that one reason why these test failures may not have been
observed in the past is because most people ran jtreg in its default mode
(called othervm mode, where each tests runs in its own VM). Nowadays we run
the tests via the make file or use jtreg -agentvm so that tests are running
sequentially in an agent VM. Not all areas can run in agent VM mode yet but
for the areas that do then we get a good speed up as the startup cost is
eliminated and also it's possible to have a pool of agent VMs to make use of
all cores when doing test runs (-agentvm -concurrency:auto for example).
However agent VM makes things less predictable and for these tests it means
that the GC will be unpredictable which is why this test was failing only very
intermittently.
Anyway, the changes look fine to me. I agree with Mandy that many logger1 and
logger2 could be instance variables. I would suggest proxy or something more
readable rather than testp for the LoggingMXBean proxy. I also agree with
Mandy's comment about adding the @bug.
-Alan.
Re: Garbage collection race condition before final checks
On 09/11/2011 19:26, Gary Adams wrote: Here's an updated diff : - added current CR# to the @bug tag - made logger1 and logger2 instance variables - renamed test instance variable lmxbeantest - removed excessive diagnostic print outs Looks fine to me except that we might find a better name than lmxbeantest, also the setting to null can be removed. One of us needs to push this, listing you as contributor. Mandy or Dan - are you taking it? -Alan.
Re: Garbage collection race condition before final checks
On 11/9/2011 1:18 PM, Alan Bateman wrote: On 09/11/2011 19:26, Gary Adams wrote: Here's an updated diff : - added current CR# to the @bug tag - made logger1 and logger2 instance variables - renamed test instance variable lmxbeantest - removed excessive diagnostic print outs Looks fine to me except that we might find a better name than lmxbeantest, also the setting to null can be removed. One of us needs to push this, listing you as contributor. Mandy or Dan - are you taking it? I will help take this one. Gary, can you also fix PlatformLoggingMXBeanTest.java? We should fix these 2 tests for this bug. Thanks Mandy
Re: Garbage collection race condition before final checks
Gary,
Thanks for picking up this bug and fixing this intermittent issue.
PlatformLoggingMXBeanTest.java in the same directory has the same
issue. It'd be good to fix that with the same CR. These tests were
copied from test/java/util/logging/LoggingMXBeanTest.java. I haven't
looked in details but I wonder why the test/java/util/logging tests
don't have this intermittent issue and I suspect it holds a strong
reference.
A couple comment to the fix:
On 11/8/2011 7:35 AM, Gary Adams wrote:
diff --git
a/test/java/lang/management/PlatformLoggingMXBean/LoggingMXBeanTest.java
b/test/java/lang/management/PlatformLoggingMXBean/LoggingMXBeanTest.java
---
a/test/java/lang/management/PlatformLoggingMXBean/LoggingMXBeanTest.java
+++
b/test/java/lang/management/PlatformLoggingMXBean/LoggingMXBeanTest.java
Please add the CR number to @bug tag.
@@ -42,6 +42,9 @@
static String LOGGER_NAME_1 = com.sun.management.Logger;
static String LOGGER_NAME_2 = com.sun.management.Logger.Logger2;
static String UNKNOWN_LOGGER_NAME = com.sun.management.Unknown;
+static Logger logger1;
+static Logger logger2;
It'd be good to add a comment why you want to keep a strong reference to
the logger. Minor nit: could make them as instance variables as they
are part of the LoggingMXBeanTest instance.
+static LoggingMXBeanTest testp;
public static void main(String[] argv) throws Exception {
MBeanServer mbs = ManagementFactory.getPlatformMBeanServer();
@@ -51,7 +54,7 @@
LoggingMXBean.class);
// test LoggingMXBean proxy
-LoggingMXBeanTest p = new LoggingMXBeanTest(proxy);
+testp = new LoggingMXBeanTest(proxy);
Could we make checkAttributes as an instance method to LoggingMXBeanTest
object so that you don't need the static variable?
// check if the attributes implemented by PlatformLoggingMXBean
// and LoggingMXBean return the same value
@@ -59,14 +62,18 @@
ManagementFactory.getPlatformMXBean(mbs,
PlatformLoggingMXBean.class);
checkAttributes(proxy, mxbean);
+
+logger1 = null;
+logger2 = null;
+testp = null;
With the above suggested change, I think these 3 lines are not needed.
}
// same verification as in java/util/logging/LoggingMXBeanTest2
public LoggingMXBeanTest(LoggingMXBean mbean) throws Exception {
-Logger logger1 = Logger.getLogger( LOGGER_NAME_1 );
+logger1 = Logger.getLogger( LOGGER_NAME_1 );
logger1.setLevel(Level.FINE);
-Logger logger2 = Logger.getLogger( LOGGER_NAME_2 );
+logger2 = Logger.getLogger( LOGGER_NAME_2 );
logger2.setLevel(null);
/*
@@ -207,6 +214,18 @@
// verify logger names
ListString loggers1 = mxbean1.getLoggerNames();
ListString loggers2 = mxbean2.getLoggerNames();
+
+// Print the two logger lists for diagnostic purposes
+System.out.println( : LoggingMXBean + loggers1);
+System.out.println( : PlatformLoggingMXBean + loggers2);
+
+// Print the list of logger level comparisons for diagnostic
purposes
+for (String logger : loggers1) {
+System.out.println (: Level ( + logger
++ , + mxbean1.getLoggerLevel(logger)
++ , + mxbean2.getLoggerLevel(logger) + ));
+}
It might be good to keep these diagnostic message to be printed only
when it throws an exception? Extra diagnostic information is good but
just want to keep the volume of traces reasonable not to make the output
harder to use.
Thanks again for fixing it.
Mandy
