Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-24263

Order of log output across processes started by the mongo shell and resmoke.py depends on thread scheduling

    • Correctness
    • Fully Compatible
    • ALL

      In general, it is possible for the following sequence of events to occur:

      1. mongod on port 20010 writes log message A
      2. mongod on port 20011 writes log message B
      3. thread consuming output of mongod on port 20011 is scheduled and writes log message B (to stdout, logkeeper, etc.)
      4. thread consuming output of mongod on port 20010 is scheduled and writes log message A (to stdout, logkeeper, etc.)
      In the mongo shell

      Each thread acquires mongoProgramOutputMutex before writing a single line of output and flushing stdout.

      void ProgramOutputMultiplexer::appendLine(int port, ProcessId pid, const char* line) {
          stdx::lock_guard<stdx::mutex> lk(mongoProgramOutputMutex);
          uassert(28695, "program is terminating", !mongo::inShutdown());
          stringstream buf;
          string name = registry.programName(pid);
          if (port > 0)
              buf << name << port << "| " << line;
          else
              buf << name << pid << "| " << line;
          printf("%s\n", buf.str().c_str());  // cout << buf.str() << endl;
          fflush(stdout);  // not implicit if stdout isn't directly outputting to a console.
          _buffer << buf.str() << endl;
      }
      
      resmoke.py

      The wrapper around subprocess.Popen() used by resmoke.py specifies bufsize=0 to avoid contributing the to delay when a process. However, it may be the case that some non-zero buffer size would be more effective when there is CPU contention on the host machine.

      # Use unbuffered I/O pipes to avoid adding delay between when the subprocess writes output
      # and when the LoggerPipe thread reads it.
      buffer_size = 0
      
      # Close file descriptors in the child process before executing the program. This prevents
      # file descriptors that were inherited due to multiple calls to fork() -- either within one
      # thread, or concurrently from multiple threads -- from causing another subprocess to wait
      # for the completion of the newly spawned child process. Closing other file descriptors
      # isn't supported on Windows when stdout and stderr are redirected.
      close_fds = (sys.platform != "win32")
      
      with _POPEN_LOCK:
          self._process = subprocess.Popen(self.args,
                                           bufsize=buffer_size,
                                           stdout=subprocess.PIPE,
                                           stderr=subprocess.PIPE,
                                           close_fds=close_fds,
                                           env=self.env,
                                           creationflags=creation_flags)
      

            Assignee:
            Unassigned Unassigned
            Reporter:
            max.hirschhorn@mongodb.com Max Hirschhorn
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated: