# HG changeset patch # User dcubed # Date 1277229299 25200 # Node ID 0496aa46ae9f1c18aae35d505379de3d029293b2 # Parent 8c68030e27b108480b0036411c18f72776a9c365 6942989: 2/2 Memory leak of java.lang.ref.WeakReference objects Summary: Use ReferenceQueues to manage WeakReferences in LogManager and Logger. Reviewed-by: dholmes, alanb, emcmanus, tonyp Contributed-by: jeremymanson@google.com diff -r 8c68030e27b1 -r 0496aa46ae9f jdk/src/share/classes/java/util/logging/LogManager.java --- a/jdk/src/share/classes/java/util/logging/LogManager.java Mon Jun 21 15:02:47 2010 -0700 +++ b/jdk/src/share/classes/java/util/logging/LogManager.java Tue Jun 22 10:54:59 2010 -0700 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2000, 2007, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2000, 2010, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -29,6 +29,7 @@ import java.io.*; import java.util.*; import java.security.*; +import java.lang.ref.ReferenceQueue; import java.lang.ref.WeakReference; import java.beans.PropertyChangeListener; import java.beans.PropertyChangeSupport; @@ -154,10 +155,10 @@ = new PropertyChangeSupport(LogManager.class); private final static Level defaultLevel = Level.INFO; - // Table of known loggers. Maps names to Loggers. - private Hashtable> loggers = - new Hashtable>(); - // Tree of known loggers + // Table of named Loggers that maps names to Loggers. + private Hashtable namedLoggers = + new Hashtable(); + // Tree of named Loggers private LogNode root = new LogNode(null); private Logger rootLogger; @@ -417,6 +418,121 @@ }}); } + + // loggerRefQueue holds LoggerWeakRef objects for Logger objects + // that have been GC'ed. + private final ReferenceQueue loggerRefQueue + = new ReferenceQueue(); + + // Package-level inner class. + // Helper class for managing WeakReferences to Logger objects. + // + // LogManager.namedLoggers + // - has weak references to all named Loggers + // - namedLoggers keeps the LoggerWeakRef objects for the named + // Loggers around until we can deal with the book keeping for + // the named Logger that is being GC'ed. + // LogManager.LogNode.loggerRef + // - has a weak reference to a named Logger + // - the LogNode will also keep the LoggerWeakRef objects for + // the named Loggers around; currently LogNodes never go away. + // Logger.kids + // - has a weak reference to each direct child Logger; this + // includes anonymous and named Loggers + // - anonymous Loggers are always children of the rootLogger + // which is a strong reference; rootLogger.kids keeps the + // LoggerWeakRef objects for the anonymous Loggers around + // until we can deal with the book keeping. + // + final class LoggerWeakRef extends WeakReference { + private String name; // for namedLoggers cleanup + private LogNode node; // for loggerRef cleanup + private WeakReference parentRef; // for kids cleanup + + LoggerWeakRef(Logger logger) { + super(logger, loggerRefQueue); + + name = logger.getName(); // save for namedLoggers cleanup + } + + // dispose of this LoggerWeakRef object + void dispose() { + if (node != null) { + // if we have a LogNode, then we were a named Logger + // so clear namedLoggers weak ref to us + manager.namedLoggers.remove(name); + name = null; // clear our ref to the Logger's name + + node.loggerRef = null; // clear LogNode's weak ref to us + node = null; // clear our ref to LogNode + } + + if (parentRef != null) { + // this LoggerWeakRef has or had a parent Logger + Logger parent = parentRef.get(); + if (parent != null) { + // the parent Logger is still there so clear the + // parent Logger's weak ref to us + parent.removeChildLogger(this); + } + parentRef = null; // clear our weak ref to the parent Logger + } + } + + // set the node field to the specified value + void setNode(LogNode node) { + this.node = node; + } + + // set the parentRef field to the specified value + void setParentRef(WeakReference parentRef) { + this.parentRef = parentRef; + } + } + + // Package-level method. + // Drain some Logger objects that have been GC'ed. + // + // drainLoggerRefQueueBounded() is called by addLogger() below + // and by Logger.getAnonymousLogger(String) so we'll drain up to + // MAX_ITERATIONS GC'ed Loggers for every Logger we add. + // + // On a WinXP VMware client, a MAX_ITERATIONS value of 400 gives + // us about a 50/50 mix in increased weak ref counts versus + // decreased weak ref counts in the AnonLoggerWeakRefLeak test. + // Here are stats for cleaning up sets of 400 anonymous Loggers: + // - test duration 1 minute + // - sample size of 125 sets of 400 + // - average: 1.99 ms + // - minimum: 0.57 ms + // - maximum: 25.3 ms + // + // The same config gives us a better decreased weak ref count + // than increased weak ref count in the LoggerWeakRefLeak test. + // Here are stats for cleaning up sets of 400 named Loggers: + // - test duration 2 minutes + // - sample size of 506 sets of 400 + // - average: 0.57 ms + // - minimum: 0.02 ms + // - maximum: 10.9 ms + // + private final static int MAX_ITERATIONS = 400; + final synchronized void drainLoggerRefQueueBounded() { + for (int i = 0; i < MAX_ITERATIONS; i++) { + if (loggerRefQueue == null) { + // haven't finished loading LogManager yet + break; + } + + LoggerWeakRef ref = (LoggerWeakRef) loggerRefQueue.poll(); + if (ref == null) { + break; + } + // a Logger object has been GC'ed so clean it up + ref.dispose(); + } + } + /** * Add a named logger. This does nothing and returns false if a logger * with the same name is already registered. @@ -439,13 +555,16 @@ throw new NullPointerException(); } - WeakReference ref = loggers.get(name); + // cleanup some Loggers that have been GC'ed + drainLoggerRefQueueBounded(); + + LoggerWeakRef ref = namedLoggers.get(name); if (ref != null) { if (ref.get() == null) { - // Hashtable holds stale weak reference - // to a logger which has been GC-ed. - // Allow to register new one. - loggers.remove(name); + // It's possible that the Logger was GC'ed after the + // drainLoggerRefQueueBounded() call above so allow + // a new one to be registered. + namedLoggers.remove(name); } else { // We already have a registered logger with the given name. return false; @@ -454,7 +573,8 @@ // We're adding a new logger. // Note that we are creating a weak reference here. - loggers.put(name, new WeakReference(logger)); + ref = new LoggerWeakRef(logger); + namedLoggers.put(name, ref); // Apply any initial level defined for the new logger. Level level = getLevelProperty(name+".level", null); @@ -469,11 +589,11 @@ // Find the new node and its parent. LogNode node = findNode(name); - node.loggerRef = new WeakReference(logger); + node.loggerRef = ref; Logger parent = null; LogNode nodep = node.parent; while (nodep != null) { - WeakReference nodeRef = nodep.loggerRef; + LoggerWeakRef nodeRef = nodep.loggerRef; if (nodeRef != null) { parent = nodeRef.get(); if (parent != null) { @@ -489,6 +609,9 @@ // Walk over the children and tell them we are their new parent. node.walkAndSetParent(logger); + // new LogNode is ready so tell the LoggerWeakRef about it + ref.setNode(node); + return true; } @@ -572,7 +695,7 @@ * @return matching logger or null if none is found */ public synchronized Logger getLogger(String name) { - WeakReference ref = loggers.get(name); + LoggerWeakRef ref = namedLoggers.get(name); if (ref == null) { return null; } @@ -580,7 +703,7 @@ if (logger == null) { // Hashtable holds stale weak reference // to a logger which has been GC-ed. - loggers.remove(name); + namedLoggers.remove(name); } return logger; } @@ -594,7 +717,7 @@ * @return enumeration of logger name strings */ public synchronized Enumeration getLoggerNames() { - return loggers.keys(); + return namedLoggers.keys(); } /** @@ -942,7 +1065,7 @@ // Nested class to represent a node in our tree of named loggers. private static class LogNode { HashMap children; - WeakReference loggerRef; + LoggerWeakRef loggerRef; LogNode parent; LogNode(LogNode parent) { @@ -958,7 +1081,7 @@ Iterator values = children.values().iterator(); while (values.hasNext()) { LogNode node = values.next(); - WeakReference ref = node.loggerRef; + LoggerWeakRef ref = node.loggerRef; Logger logger = (ref == null) ? null : ref.get(); if (logger == null) { node.walkAndSetParent(parent); diff -r 8c68030e27b1 -r 0496aa46ae9f jdk/src/share/classes/java/util/logging/Logger.java --- a/jdk/src/share/classes/java/util/logging/Logger.java Mon Jun 21 15:02:47 2010 -0700 +++ b/jdk/src/share/classes/java/util/logging/Logger.java Tue Jun 22 10:54:59 2010 -0700 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2000, 2006, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2000, 2010, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -183,7 +183,7 @@ // We keep weak references from parents to children, but strong // references from children to parents. private volatile Logger parent; // our nearest parent. - private ArrayList> kids; // WeakReferences to loggers that have us as parent + private ArrayList kids; // WeakReferences to loggers that have us as parent private volatile Level levelObject; private volatile int levelValue; // current effective level value @@ -366,13 +366,8 @@ * * @return a newly created private Logger */ - public static synchronized Logger getAnonymousLogger() { - LogManager manager = LogManager.getLogManager(); - Logger result = new Logger(null, null); - result.anonymous = true; - Logger root = manager.getLogger(""); - result.doSetParent(root); - return result; + public static Logger getAnonymousLogger() { + return getAnonymousLogger(null); } /** @@ -401,6 +396,8 @@ */ public static synchronized Logger getAnonymousLogger(String resourceBundleName) { LogManager manager = LogManager.getLogManager(); + // cleanup some Loggers that have been GC'ed + manager.drainLoggerRefQueueBounded(); Logger result = new Logger(null, resourceBundleName); result.anonymous = true; Logger root = manager.getLogger(""); @@ -1380,14 +1377,18 @@ synchronized (treeLock) { // Remove ourself from any previous parent. + LogManager.LoggerWeakRef ref = null; if (parent != null) { // assert parent.kids != null; - for (Iterator> iter = parent.kids.iterator(); iter.hasNext(); ) { - WeakReference ref = iter.next(); + for (Iterator iter = parent.kids.iterator(); iter.hasNext(); ) { + ref = iter.next(); Logger kid = ref.get(); if (kid == this) { + // ref is used down below to complete the reparenting iter.remove(); break; + } else { + ref = null; } } // We have now removed ourself from our parents' kids. @@ -1396,9 +1397,14 @@ // Set our new parent. parent = newParent; if (parent.kids == null) { - parent.kids = new ArrayList>(2); + parent.kids = new ArrayList(2); } - parent.kids.add(new WeakReference(this)); + if (ref == null) { + // we didn't have a previous parent + ref = manager.new LoggerWeakRef(this); + } + ref.setParentRef(new WeakReference(parent)); + parent.kids.add(ref); // As a result of the reparenting, the effective level // may have changed for us and our children. @@ -1407,6 +1413,21 @@ } } + // Package-level method. + // Remove the weak reference for the specified child Logger from the + // kid list. We should only be called from LoggerWeakRef.dispose(). + final void removeChildLogger(LogManager.LoggerWeakRef child) { + synchronized (treeLock) { + for (Iterator iter = kids.iterator(); iter.hasNext(); ) { + LogManager.LoggerWeakRef ref = iter.next(); + if (ref == child) { + iter.remove(); + return; + } + } + } + } + // Recalculate the effective level for this node and // recursively for our children. @@ -1438,7 +1459,7 @@ // Recursively update the level on each of our kids. if (kids != null) { for (int i = 0; i < kids.size(); i++) { - WeakReference ref = kids.get(i); + LogManager.LoggerWeakRef ref = kids.get(i); Logger kid = ref.get(); if (kid != null) { kid.updateEffectiveLevel(); diff -r 8c68030e27b1 -r 0496aa46ae9f jdk/test/java/util/logging/AnonLoggerWeakRefLeak.java --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/jdk/test/java/util/logging/AnonLoggerWeakRefLeak.java Tue Jun 22 10:54:59 2010 -0700 @@ -0,0 +1,76 @@ +/* + * Copyright (c) 2010, Oracle and/or its affiliates. All rights reserved. + * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. + * + * This code is free software; you can redistribute it and/or modify it + * under the terms of the GNU General Public License version 2 only, as + * published by the Free Software Foundation. + * + * This code is distributed in the hope that it will be useful, but WITHOUT + * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or + * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License + * version 2 for more details (a copy is included in the LICENSE file that + * accompanied this code). + * + * You should have received a copy of the GNU General Public License version + * 2 along with this work; if not, write to the Free Software Foundation, + * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. + * + * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA + * or visit www.oracle.com if you need additional information or have any + * questions. + */ + +import java.util.logging.*; + +public class AnonLoggerWeakRefLeak { + public static int DEFAULT_LOOP_TIME = 60; // time is in seconds + + public static void main(String[] args) { + int loop_time = 0; + int max_loop_time = DEFAULT_LOOP_TIME; + + if (args.length == 0) { + System.out.println("INFO: using default time of " + + max_loop_time + " seconds."); + } else { + try { + max_loop_time = Integer.parseInt(args[0]); + } catch (NumberFormatException nfe) { + System.err.println("Error: '" + args[0] + + "': is not a valid seconds value."); + System.err.println("Usage: AnonLoggerWeakRefLeak [seconds]"); + System.exit(1); + } + } + + long count = 0; + long now = 0; + long startTime = System.currentTimeMillis(); + + while (now < (startTime + (max_loop_time * 1000))) { + if ((count % 1000) == 0) { + // Print initial call count to let caller know that + // we're up and running and then periodically + System.out.println("INFO: call count = " + count); + } + + for (int i = 0; i < 100; i++) { + // this Logger call is leaking a WeakReference in Logger.kids + java.util.logging.Logger.getAnonymousLogger(); + count++; + } + + try { + // delay for 1/10 of a second to avoid CPU saturation + Thread.sleep(100); + } catch (InterruptedException ie) { + // ignore any exceptions + } + + now = System.currentTimeMillis(); + } + + System.out.println("INFO: final loop count = " + count); + } +} diff -r 8c68030e27b1 -r 0496aa46ae9f jdk/test/java/util/logging/AnonLoggerWeakRefLeak.sh --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/jdk/test/java/util/logging/AnonLoggerWeakRefLeak.sh Tue Jun 22 10:54:59 2010 -0700 @@ -0,0 +1,246 @@ +# +# Copyright (c) 2010, Oracle and/or its affiliates. All rights reserved. +# DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. +# +# This code is free software; you can redistribute it and/or modify it +# under the terms of the GNU General Public License version 2 only, as +# published by the Free Software Foundation. +# +# This code is distributed in the hope that it will be useful, but WITHOUT +# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or +# FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License +# version 2 for more details (a copy is included in the LICENSE file that +# accompanied this code). +# +# You should have received a copy of the GNU General Public License version +# 2 along with this work; if not, write to the Free Software Foundation, +# Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. +# +# Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA +# or visit www.oracle.com if you need additional information or have any +# questions. +# + +# @test +# @bug 6942989 +# @summary Check for WeakReference leak in anonymous Logger objects +# @author Daniel D. Daugherty +# +# @run build AnonLoggerWeakRefLeak +# @run shell/timeout=180 AnonLoggerWeakRefLeak.sh + +# The timeout is: 2 minutes for infrastructure and 1 minute for the test +# + +if [ "${TESTJAVA}" = "" ] +then + echo "TESTJAVA not set. Test cannot execute. Failed." + exit 1 +fi + +if [ "${TESTSRC}" = "" ] +then + echo "TESTSRC not set. Test cannot execute. Failed." + exit 1 +fi + +if [ "${TESTCLASSES}" = "" ] +then + echo "TESTCLASSES not set. Test cannot execute. Failed." + exit 1 +fi + +JAVA="${TESTJAVA}"/bin/java +JMAP="${TESTJAVA}"/bin/jmap +JPS="${TESTJAVA}"/bin/jps + +set -eu + +TEST_NAME="AnonLoggerWeakRefLeak" +TARGET_CLASS="java\.lang\.ref\.WeakReference" + +is_cygwin=false +is_mks=false +is_windows=false + +case `uname -s` in +CYGWIN*) + is_cygwin=true + is_windows=true + ;; +Windows_*) + is_mks=true + is_windows=true + ;; +*) + ;; +esac + + +# wrapper for grep +# +grep_cmd() { + set +e + if $is_windows; then + # need dos2unix to get rid of CTRL-M chars from java output + dos2unix | grep "$@" + status="$?" + else + grep "$@" + status="$?" + fi + set -e +} + + +# MAIN begins here +# + +seconds= +if [ "$#" -gt 0 ]; then + seconds="$1" +fi + +# see if this version of jmap supports the '-histo:live' option +jmap_option="-histo:live" +set +e +"${JMAP}" "$jmap_option" 0 > "$TEST_NAME.jmap" 2>&1 +grep '^Usage: ' "$TEST_NAME.jmap" > /dev/null 2>&1 +status="$?" +set -e +if [ "$status" = 0 ]; then + echo "INFO: switching jmap option from '$jmap_option'\c" + jmap_option="-histo" + echo " to '$jmap_option'." +fi + +"${JAVA}" ${TESTVMOPTS} -classpath "${TESTCLASSES}" \ + "$TEST_NAME" $seconds > "$TEST_NAME.log" 2>&1 & +test_pid="$!" +echo "INFO: starting $TEST_NAME as pid = $test_pid" + +# wait for test program to get going +count=0 +while [ "$count" -lt 30 ]; do + sleep 2 + grep_cmd '^INFO: call count = 0$' < "$TEST_NAME.log" > /dev/null 2>&1 + if [ "$status" = 0 ]; then + break + fi + count=`expr $count + 1` +done + +if [ "$count" -ge 30 ]; then + echo "ERROR: $TEST_NAME failed to get going." >&2 + echo "INFO: killing $test_pid" + kill "$test_pid" + exit 1 +elif [ "$count" -gt 1 ]; then + echo "INFO: $TEST_NAME took $count loops to start." +fi + +if $is_cygwin; then + # We need the Windows pid for jmap and not the Cygwin pid. + # Note: '\t' works on Cygwin, but doesn't seem to work on Solaris. + jmap_pid=`"${JPS}"| grep_cmd "[ \t]$TEST_NAME$" | sed 's/[ \t].*//'` + if [ -z "$jmap_pid" ]; then + echo "FAIL: jps could not map Cygwin pid to Windows pid." >&2 + echo "INFO: killing $test_pid" + kill "$test_pid" + exit 2 + fi + echo "INFO: pid = $test_pid maps to Windows pid = $jmap_pid" +else + jmap_pid="$test_pid" +fi + +decreasing_cnt=0 +increasing_cnt=0 +loop_cnt=0 +prev_instance_cnt=0 + +while true; do + # Output format for 'jmap -histo' in JDK1.5.0: + # + # <#bytes> <#instances> + # + # Output format for 'jmap -histo:live': + # + # : <#instances> <#bytes> + # + set +e + "${JMAP}" "$jmap_option" "$jmap_pid" > "$TEST_NAME.jmap" 2>&1 + status="$?" + set -e + + if [ "$status" != 0 ]; then + echo "INFO: jmap exited with exit code = $status" + if [ "$loop_cnt" = 0 ]; then + echo "INFO: on the first iteration so no samples were taken." + echo "INFO: start of jmap output:" + cat "$TEST_NAME.jmap" + echo "INFO: end of jmap output." + echo "FAIL: jmap is unable to take any samples." >&2 + echo "INFO: killing $test_pid" + kill "$test_pid" + exit 2 + fi + echo "INFO: The likely reason is that $TEST_NAME has finished running." + break + fi + + instance_cnt=`grep_cmd "[ ]$TARGET_CLASS$" \ + < "$TEST_NAME.jmap" \ + | sed ' + # strip leading whitespace; does nothing in JDK1.5.0 + s/^[ ][ ]*// + # strip <#bytes> in JDK1.5.0; does nothing otherwise + s/^[1-9][0-9]*[ ][ ]*// + # strip : field; does nothing in JDK1.5.0 + s/^[1-9][0-9]*:[ ][ ]*// + # strip field + s/[ ].*// + '` + if [ -z "$instance_cnt" ]; then + echo "INFO: instance count is unexpectedly empty" + if [ "$loop_cnt" = 0 ]; then + echo "INFO: on the first iteration so no sample was found." + echo "INFO: There is likely a problem with the sed filter." + echo "INFO: start of jmap output:" + cat "$TEST_NAME.jmap" + echo "INFO: end of jmap output." + echo "FAIL: cannot find the instance count value." >&2 + echo "INFO: killing $test_pid" + kill "$test_pid" + exit 2 + fi + else + echo "INFO: instance_cnt = $instance_cnt" + + if [ "$instance_cnt" -gt "$prev_instance_cnt" ]; then + increasing_cnt=`expr $increasing_cnt + 1` + else + decreasing_cnt=`expr $decreasing_cnt + 1` + fi + prev_instance_cnt="$instance_cnt" + fi + + # delay between samples + sleep 5 + + loop_cnt=`expr $loop_cnt + 1` +done + +echo "INFO: increasing_cnt = $increasing_cnt" +echo "INFO: decreasing_cnt = $decreasing_cnt" + +echo "INFO: The instance count of" `eval echo $TARGET_CLASS` "objects" +if [ "$decreasing_cnt" = 0 ]; then + echo "INFO: is always increasing." + echo "FAIL: This indicates that there is a memory leak." >&2 + exit 2 +fi + +echo "INFO: is both increasing and decreasing." +echo "PASS: This indicates that there is not a memory leak." +exit 0 diff -r 8c68030e27b1 -r 0496aa46ae9f jdk/test/java/util/logging/LoggerWeakRefLeak.java --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/jdk/test/java/util/logging/LoggerWeakRefLeak.java Tue Jun 22 10:54:59 2010 -0700 @@ -0,0 +1,89 @@ +/* + * Copyright (c) 2010, Oracle and/or its affiliates. All rights reserved. + * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. + * + * This code is free software; you can redistribute it and/or modify it + * under the terms of the GNU General Public License version 2 only, as + * published by the Free Software Foundation. + * + * This code is distributed in the hope that it will be useful, but WITHOUT + * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or + * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License + * version 2 for more details (a copy is included in the LICENSE file that + * accompanied this code). + * + * You should have received a copy of the GNU General Public License version + * 2 along with this work; if not, write to the Free Software Foundation, + * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. + * + * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA + * or visit www.oracle.com if you need additional information or have any + * questions. + */ + +import java.util.logging.*; + +public class LoggerWeakRefLeak { + // AnonLoggerWeakRefLeak checks for one weak reference leak. + // LoggerWeakRefLeak checks for two weak reference leaks so + // this test runs twice as long, by default. + public static int DEFAULT_LOOP_TIME = 120; // time is in seconds + + public static void main(String[] args) { + int loop_time = 0; + int max_loop_time = DEFAULT_LOOP_TIME; + + if (args.length == 0) { + System.out.println("INFO: using default time of " + + max_loop_time + " seconds."); + } else { + try { + max_loop_time = Integer.parseInt(args[0]); + } catch (NumberFormatException nfe) { + System.err.println("Error: '" + args[0] + + "': is not a valid seconds value."); + System.err.println("Usage: LoggerWeakRefLeak [seconds]"); + System.exit(1); + } + } + + long count = 0; + int loggerCount = 0; + long now = 0; + long startTime = System.currentTimeMillis(); + + while (now < (startTime + (max_loop_time * 1000))) { + if ((count % 1000) == 0) { + // Print initial call count to let caller know that + // we're up and running and then periodically + System.out.println("INFO: call count = " + count); + } + + for (int i = 0; i < 100; i++) { + // This Logger call is leaking two different WeakReferences: + // - one in LogManager.LogNode + // - one in Logger.kids + java.util.logging.Logger.getLogger("logger-" + loggerCount); + count++; + if (++loggerCount >= 25000) { + // Limit the Logger namespace used by the test so + // the weak refs in LogManager.loggers that are + // being properly managed don't skew the counts + // by too much. + loggerCount = 0; + } + } + + try { + // delay for 1/10 of a second to avoid CPU saturation + Thread.sleep(100); + } catch (InterruptedException ie) { + // ignore any exceptions + } + + now = System.currentTimeMillis(); + } + + System.out.println("INFO: final loop count = " + count); + } +} diff -r 8c68030e27b1 -r 0496aa46ae9f jdk/test/java/util/logging/LoggerWeakRefLeak.sh --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/jdk/test/java/util/logging/LoggerWeakRefLeak.sh Tue Jun 22 10:54:59 2010 -0700 @@ -0,0 +1,246 @@ +# +# Copyright (c) 2010, Oracle and/or its affiliates. All rights reserved. +# DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. +# +# This code is free software; you can redistribute it and/or modify it +# under the terms of the GNU General Public License version 2 only, as +# published by the Free Software Foundation. +# +# This code is distributed in the hope that it will be useful, but WITHOUT +# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or +# FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License +# version 2 for more details (a copy is included in the LICENSE file that +# accompanied this code). +# +# You should have received a copy of the GNU General Public License version +# 2 along with this work; if not, write to the Free Software Foundation, +# Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. +# +# Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA +# or visit www.oracle.com if you need additional information or have any +# questions. +# + +# @test +# @bug 6942989 +# @summary Check for WeakReference leak in Logger objects +# @author Daniel D. Daugherty +# +# @run build LoggerWeakRefLeak +# @run shell/timeout=240 LoggerWeakRefLeak.sh + +# The timeout is: 2 minutes for infrastructure and 1 minute for the test +# + +if [ "${TESTJAVA}" = "" ] +then + echo "TESTJAVA not set. Test cannot execute. Failed." + exit 1 +fi + +if [ "${TESTSRC}" = "" ] +then + echo "TESTSRC not set. Test cannot execute. Failed." + exit 1 +fi + +if [ "${TESTCLASSES}" = "" ] +then + echo "TESTCLASSES not set. Test cannot execute. Failed." + exit 1 +fi + +JAVA="${TESTJAVA}"/bin/java +JMAP="${TESTJAVA}"/bin/jmap +JPS="${TESTJAVA}"/bin/jps + +set -eu + +TEST_NAME="LoggerWeakRefLeak" +TARGET_CLASS="java\.lang\.ref\.WeakReference" + +is_cygwin=false +is_mks=false +is_windows=false + +case `uname -s` in +CYGWIN*) + is_cygwin=true + is_windows=true + ;; +Windows_*) + is_mks=true + is_windows=true + ;; +*) + ;; +esac + + +# wrapper for grep +# +grep_cmd() { + set +e + if $is_windows; then + # need dos2unix to get rid of CTRL-M chars from java output + dos2unix | grep "$@" + status="$?" + else + grep "$@" + status="$?" + fi + set -e +} + + +# MAIN begins here +# + +seconds= +if [ "$#" -gt 0 ]; then + seconds="$1" +fi + +# see if this version of jmap supports the '-histo:live' option +jmap_option="-histo:live" +set +e +"${JMAP}" "$jmap_option" 0 > "$TEST_NAME.jmap" 2>&1 +grep '^Usage: ' "$TEST_NAME.jmap" > /dev/null 2>&1 +status="$?" +set -e +if [ "$status" = 0 ]; then + echo "INFO: switching jmap option from '$jmap_option'\c" + jmap_option="-histo" + echo " to '$jmap_option'." +fi + +"${JAVA}" ${TESTVMOPTS} -classpath "${TESTCLASSES}" \ + "$TEST_NAME" $seconds > "$TEST_NAME.log" 2>&1 & +test_pid="$!" +echo "INFO: starting $TEST_NAME as pid = $test_pid" + +# wait for test program to get going +count=0 +while [ "$count" -lt 30 ]; do + sleep 2 + grep_cmd '^INFO: call count = 0$' < "$TEST_NAME.log" > /dev/null 2>&1 + if [ "$status" = 0 ]; then + break + fi + count=`expr $count + 1` +done + +if [ "$count" -ge 30 ]; then + echo "ERROR: $TEST_NAME failed to get going." >&2 + echo "INFO: killing $test_pid" + kill "$test_pid" + exit 1 +elif [ "$count" -gt 1 ]; then + echo "INFO: $TEST_NAME took $count loops to start." +fi + +if $is_cygwin; then + # We need the Windows pid for jmap and not the Cygwin pid. + # Note: '\t' works on Cygwin, but doesn't seem to work on Solaris. + jmap_pid=`"${JPS}"| grep_cmd "[ \t]$TEST_NAME$" | sed 's/[ \t].*//'` + if [ -z "$jmap_pid" ]; then + echo "FAIL: jps could not map Cygwin pid to Windows pid." >&2 + echo "INFO: killing $test_pid" + kill "$test_pid" + exit 2 + fi + echo "INFO: pid = $test_pid maps to Windows pid = $jmap_pid" +else + jmap_pid="$test_pid" +fi + +decreasing_cnt=0 +increasing_cnt=0 +loop_cnt=0 +prev_instance_cnt=0 + +while true; do + # Output format for 'jmap -histo' in JDK1.5.0: + # + # <#bytes> <#instances> + # + # Output format for 'jmap -histo:live': + # + # : <#instances> <#bytes> + # + set +e + "${JMAP}" "$jmap_option" "$jmap_pid" > "$TEST_NAME.jmap" 2>&1 + status="$?" + set -e + + if [ "$status" != 0 ]; then + echo "INFO: jmap exited with exit code = $status" + if [ "$loop_cnt" = 0 ]; then + echo "INFO: on the first iteration so no samples were taken." + echo "INFO: start of jmap output:" + cat "$TEST_NAME.jmap" + echo "INFO: end of jmap output." + echo "FAIL: jmap is unable to take any samples." >&2 + echo "INFO: killing $test_pid" + kill "$test_pid" + exit 2 + fi + echo "INFO: The likely reason is that $TEST_NAME has finished running." + break + fi + + instance_cnt=`grep_cmd "[ ]$TARGET_CLASS$" \ + < "$TEST_NAME.jmap" \ + | sed ' + # strip leading whitespace; does nothing in JDK1.5.0 + s/^[ ][ ]*// + # strip <#bytes> in JDK1.5.0; does nothing otherwise + s/^[1-9][0-9]*[ ][ ]*// + # strip : field; does nothing in JDK1.5.0 + s/^[1-9][0-9]*:[ ][ ]*// + # strip field + s/[ ].*// + '` + if [ -z "$instance_cnt" ]; then + echo "INFO: instance count is unexpectedly empty" + if [ "$loop_cnt" = 0 ]; then + echo "INFO: on the first iteration so no sample was found." + echo "INFO: There is likely a problem with the sed filter." + echo "INFO: start of jmap output:" + cat "$TEST_NAME.jmap" + echo "INFO: end of jmap output." + echo "FAIL: cannot find the instance count value." >&2 + echo "INFO: killing $test_pid" + kill "$test_pid" + exit 2 + fi + else + echo "INFO: instance_cnt = $instance_cnt" + + if [ "$instance_cnt" -gt "$prev_instance_cnt" ]; then + increasing_cnt=`expr $increasing_cnt + 1` + else + decreasing_cnt=`expr $decreasing_cnt + 1` + fi + prev_instance_cnt="$instance_cnt" + fi + + # delay between samples + sleep 5 + + loop_cnt=`expr $loop_cnt + 1` +done + +echo "INFO: increasing_cnt = $increasing_cnt" +echo "INFO: decreasing_cnt = $decreasing_cnt" + +echo "INFO: The instance count of" `eval echo $TARGET_CLASS` "objects" +if [ "$decreasing_cnt" = 0 ]; then + echo "INFO: is always increasing." + echo "FAIL: This indicates that there is a memory leak." >&2 + exit 2 +fi + +echo "INFO: is both increasing and decreasing." +echo "PASS: This indicates that there is not a memory leak." +exit 0