[SERVER-24263] Order of log output across processes started by the mongo shell and resmoke.py depends on thread scheduling Created: 23/May/16  Updated: 23/Oct/23

Status: Open
Project: Core Server
Component/s: Shell, Testing Infrastructure
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Max Hirschhorn Assignee: [DO NOT ASSIGN] Backlog - DevProd Correctness
Resolution: Unresolved Votes: 0
Labels: dag, tig-mongorunner, tig-resmoke
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
is duplicated by SERVER-11257 Js test output can contain incorrectl... Closed
Related
Assigned Teams:
Correctness
Backwards Compatibility: Fully Compatible
Operating System: ALL
Participants:

 Description   

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)


Generated at Thu Feb 08 04:05:50 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.