Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-6454585

3 minute hang at startup due to loopback connection created by PlainSocketImpl

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Duplicate
    • Icon: P3 P3
    • None
    • 6
    • core-libs
    • x86
    • linux

      FULL PRODUCT VERSION :
      java version "1.6.0-rc"
      Java(TM) SE Runtime Environment (build 1.6.0-rc-b92)
      Java HotSpot(TM) Client VM (build 1.6.0-rc-b92, mixed mode, sharing)


      ADDITIONAL OS VERSION INFORMATION :
      Linux DualCore 2.6.15-25-686 #1 SMP PREEMPT Wed Jun 14 11:34:19 UTC 2006 i686 GNU/Linux

      EXTRA RELEVANT SYSTEM CONFIGURATION :
      Dual core Intel CPU (D 820) with 2GB of RAM so -server is automatically enabled when running java.

      A DESCRIPTION OF THE PROBLEM :
      The class java.net.PlainSocketImpl spontaneously stalls for exactly 3 minutes and 9 seconds during class loading <clinit> about 0.5 % of the time on my dual core Linux box. I noticed the 3 minute nine second delays occuring in the middle of Drjava (see drjava.org) unit tests and recently isolated the problem solely as part of loading the class java.net.PlainSocketImpl. I filed an earlier bug report (internal number 740049 on 30 Jun 2006 to which I have received no response other beyond the initial form) identifying the problem as part of the RMI communication between a master and slave JVM, localizing the stall in the class java.net.PlainSocketImpl. But I now have a very short test program that proves the problem is purely within the class java.net.PlainSocketImpl. The test program repeatedly executes a Runtime.exec command that starts another JVM that does nothing but load the class java.net.PlainSocketImpl using Class.forName("java.net.PlainSocketImpl"). About once out of every 200 times, the stall occurs. The test program makes no reference to any RMI classes; none of the rmi packages are not imported.

      Note that this 3 minute stall has been reported with regard to the class java.net.PlainSocketImpl has been reported in the Java Developers forum in thread
      http://forum.java.sun.com/thread.jspa?threadID=586714&tstart=120

      STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
      If you are running a recent Mustang build, download the jar file http://www.cs.rice.edu/~cork/Java/Bugs/RMIBug.jar. If you are running some version of Java 5.0, download the jar file http://www.cs.rice.edu/~cork/Java/Bugs/RMIBugv5.jar.

      Put the jar file at the front of your shell CLASSPATH environment variable; otherwise the Runtime.exec(...) command cannot reliably find the target class file. The execute the command

      java -jar <path to jar file>

      and monitor the output to the log file MasterSlave.txt in the working directory. (I use the command

      tail -f MasterSlave.txt

      in a separate window.)



      EXPECTED VERSUS ACTUAL BEHAVIOR :
      EXPECTED -
      Teh program should run to completion in less than 2 minutes. (It takes a little over 1 minute on my dual Intel dual core 2Ghz MacBook.)
      ACTUAL -
      The test program stalls two or three times during 500 executions of Runtime.exec("java SlaveJVMRunner"). On my desktop, each stall lasts exactly 3 minutes 9 seconds. So total execution time is over 7 minutes.

      ERROR MESSAGES/STACK TRACES THAT OCCUR :
      No error messages are generated. But the stalls are clearly shown in the log file MasterSlave.txt.

      REPRODUCIBILITY :
      This bug can be reproduced always.

      ---------- BEGIN SOURCE ----------
      BTW, I think using raw text rather than attachments for this purpose is lame, but here goes:

      ************** File: TestRemoteJVM.java *********************

      import java.io.*;

      /** A class implementing the logic to invoke and control, via RMI, a second Java virtual machine. */
      public class TestRemoteJVM {
        
        public static final Log _log = new Log("MasterSlave.txt", true);
        
        /** Lock for accessing the critical state of TestRemoteJVM including _monitorThread. */
        protected final Object _masterJVMLock = new Object();

        /** The thread monitoring the Slave JVM, waiting for it to terminate. */
        private volatile Thread _monitorThread;

        /** Sets up the master JVM object, but does not actually invoke the slave JVM. */
        protected TestRemoteJVM() {
          _monitorThread = null;
          _log.log("Master object " + this + " CREATED");
        }
       
        /** Creates and invokes slave JVM. */
        protected final void invokeSlave() throws IOException {

          // Start a thread to wait for the slave to die, log its death, and terminate.
          _monitorThread = new Thread("Slave Monitor") {
            public void run() {
              try { /* Create the slave JVM. */
                
                String command = "java SlaveJVMRunner";
                final Process process = Runtime.getRuntime().exec(command);
                _log.log("Master object " + TestRemoteJVM.this + " executing '" + command + "' creating process " + process);
                
                int status = process.waitFor();
                _log.log(process + " DIED under control of " + asString() + " with status " + status);
                _monitorThread = null;
                synchronized(_masterJVMLock) {_masterJVMLock.notifyAll(); } // signal that Slave JVM died
              }
              catch(InterruptedException e) { throw new UnexpectedException(e); }
              catch(IOException e) { throw new UnexpectedException(e); }
            }
            private String asString() { return "SlaveMonitor@" + Integer.toHexString(hashCode()); }
          };

          _monitorThread.start();
          waitForSlaveDeath();
        }

        /** Waits until no slave JVM is running under control of "this" */
        public void waitForSlaveDeath() {
          try { synchronized(_masterJVMLock) { while (_monitorThread != null) _masterJVMLock.wait(); }}
          catch(InterruptedException e) { throw new UnexpectedException(e); }
        }

        public static void main(String[] args) throws IOException {
          for (int i = 0; i < 500; i++) new TestRemoteJVM().invokeSlave();
        }
      }

      **************** File SlaveJVMRunner.java ************************
      import java.io.*;

      /** This class is the root class for the Slave JVM. The Master JVM invokes the {@link #main} method of this class. */
      public final class SlaveJVMRunner {
        
        protected static final Log _log = new Log("MasterSlave.txt", true);

        /** The main method for invoking a slave JVM. */
        public static void main(String[] args) {
          
          _log.log("Slave JVM (short version) has started");

          try {
            
            /* Load the class that intermittently hung for 3 minutes and 9 seconds in DrJava unit tests. */
            Class psi = Class.forName("java.net.PlainSocketImpl");
            _log.log(psi + " successfully loaded");
          }
          catch (Exception e) { // IOException, ClassNotFoundException
            _log.log("SlaveJVMRunner (short version) could not load java.net.PlainSocketImpl; threw " + e);
            System.exit(2);
          }
          System.exit(0);
        }
      }

      ******************** File Log.java ********************************************

      import java.io.*;
      import java.util.Date;

      /** Logging class to record errors or unexpected behavior to a file. The file is created in the current directory, and
        * is only used if the log is enabled.
        */
      public class Log {

        /** Whether this particular log is enabled in development mode. */
        protected boolean _isEnabled;

        /** The filename of this log. */
        protected String _name;

        /** PrintWriter to print messages to a file. */
        protected PrintWriter _writer;

        /** Creates a new Log with the given name. If enabled is true, a file is created in the current directory
         * with the given name.
         * @param name File name for the log
         * @param enabled Whether to actively use this log
         */
        public Log(String name, boolean isEnabled) {
          _name = name;
          _isEnabled = isEnabled;
          _init();
        }

        /** Creates the log file, if enabled. */
        protected void _init() {
          if (_writer == null) {
            if (_isEnabled) {
              try {
                File f = new File(_name);
                FileWriter w = new FileWriter(f.getAbsolutePath(), true);
                _writer = new PrintWriter(w);

                log("Log '" + _name + "' opened: " + (new Date()));
              }
              catch (IOException ioe) {
                throw new RuntimeException("Could not create log: " + ioe);
              }
            }
          }
        }

        /** Sets whether this log is enabled. Only has an effect if the code is in development mode.
         * @param enabled Whether to print messages to the log file
         */
        public void setEnabled(boolean isEnabled) { _isEnabled = isEnabled; }

        /** Returns whether this log is currently enabled. */
        public boolean isEnabled() {
          return (_isEnabled);
        }

        /** Prints a message to the log, if enabled.
         * @param message Message to print.
         */
        public synchronized void log(String message) {
          if (isEnabled()) {
            if (_writer == null) {
              _init();
            }
            _writer.println((new Date()) + ": " + message);
            _writer.flush();
          }
        }

        /** Prints a message and exception stack trace to the log, if enabled.
         * @param s Message to print
         * @param t Throwable to log
         */
        public synchronized void log(String s, StackTraceElement[] trace) {
          if (isEnabled()) {
            StringBuilder traceImage = new StringBuilder();
            for (StackTraceElement e: trace) traceImage.append("\n" + e.toString());
            log(s + traceImage.toString());
          }
        }
        
        /** Prints a message and exception stack trace to the log, if enabled.
         * @param s Message to print
         * @param t Throwable to log
         */
        public synchronized void log(String s, Throwable t) {
          if (isEnabled()) {
            StringWriter sw = new StringWriter();
            PrintWriter pw = new PrintWriter(sw);
            t.printStackTrace(pw);
            log(s + "\n" + sw.toString());
          }
        }
      }

      ********************* File UnexpectedException.java **********************

      /** An unexpected exception signalling a coding error. */
      public class UnexpectedException extends RuntimeException {

        private Throwable _value;

         /** Constructs an unexpected exception with <code>value.toString()</code> as it's message. */
        public UnexpectedException(Throwable value) {
          super(value.toString());
          _value = value;
        }

        /** Constructs an unexpected exception for value with custom message string + <code>value.toString()</code>. */
        public UnexpectedException(Throwable value, String msg) {
          super(msg + ": " + value.toString());
          _value = value;
        }
        
        /** Constructs a new RuntimeException to report that unreachable point in code has been reached */
        public UnexpectedException() {
          this(new RuntimeException("Unreachable point in code has been reached!"));
        }

        /** Constructs a new RuntimeException to report specified message */
        public UnexpectedException(String msg) {
          this(new RuntimeException(msg));
        }

        /** Returns the contained exception. */
        public Throwable getCause() { return _value; }
      }
      ---------- END SOURCE ----------

      CUSTOMER SUBMITTED WORKAROUND :
      Use the Mac OS X VM when running on a multiprocessor.

            jccollet Jean-Christophe Collet (Inactive)
            ndcosta Nelson Dcosta (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

              Created:
              Updated:
              Resolved:
              Imported:
              Indexed: