[SERVER-11480] printMemInfo std::cout hangs Created: 30/Oct/13  Updated: 06/Dec/22  Resolved: 14/Sep/18

Status: Closed
Project: Core Server
Component/s: MMAPv1
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Jeffrey Yemin Assignee: Backlog - Storage Execution Team
Resolution: Won't Fix Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

[jenkins@ip-10-118-21-122 ec2-user]$ cat /etc/*release
Amazon Linux AMI release 2013.03
[jenkins@ip-10-118-21-122 ec2-user]$ mongod --version
db version v2.5.4-pre-
2013-10-30T16:33:41.267+0000 git version: 45178f5933e1104083d790fe6a901db7a3291423 modules: subscription
2013-10-30T16:33:41.268+0000 OpenSSL version: OpenSSL 1.0.1e-fips 11 Feb 2013


Assigned Teams:
Storage Execution
Operating System: ALL
Steps To Reproduce:

I don't have a simple script to reproduce this, but it happens consistently on Jenkins with the Java driver 3.0.x tests with this release, and the same tests pass consistently with 2.4.

Participants:

 Description   

Java driver tests consistently hang on multiple Jenkins slaves. The test that hangs is inserting 10 documents, and it will hang for over 30 minutes waiting for a getlasterror response.

> db.currentOp()
{
	"inprog" : [
		{
			"opid" : 11662,
			"active" : false,
			"op" : "query",
			"ns" : "",
			"query" : {
				"expireAfterSeconds" : {
					"$exists" : true
				}
			},
			"client" : "0.0.0.0:0",
			"desc" : "TTLMonitor",
			"threadId" : "0x7fa3dae2e700",
			"locks" : {
				"^DriverTest-406368717001567" : "R"
			},
			"waitingForLock" : true,
			"numYields" : 0,
			"lockStats" : {
				"timeLockedMicros" : {
 
				},
				"timeAcquiringMicros" : {
 
				}
			}
		},
		{
			"opid" : 11629,
			"active" : true,
			"secs_running" : 835,
			"op" : "insert",
			"ns" : "DriverTest-406368717001567.com.mongodb.DBCursorTest406374021052232",
			"insert" : {
 
			},
			"client" : "127.0.0.1:52879",
			"desc" : "conn41",
			"threadId" : "0x7fa3d1429700",
			"connectionId" : 41,
			"locks" : {
				"^" : "w",
				"^DriverTest-406368717001567" : "W"
			},
			"waitingForLock" : false,
			"msg" : "index: (1/3) external sort",
			"numYields" : 0,
			"lockStats" : {
				"timeLockedMicros" : {
 
				},
				"timeAcquiringMicros" : {
					"r" : NumberLong(0),
					"w" : NumberLong(6)
				}
			}
		}
	]
}

[jenkins@ip-10-118-21-122 ec2-user]$ grep conn41 mongo.log | tail
2013-10-30T16:20:05.627+0000 [conn41] CMD: drop DriverTest-406368717001567.com.mongodb.DBCursorTest406373994841307
2013-10-30T16:20:05.627+0000 [conn41] dropCollection: DriverTest-406368717001567.com.mongodb.DBCursorTest406373994841307
2013-10-30T16:20:05.627+0000 [conn41]   d->nIndexes was 1
2013-10-30T16:20:05.627+0000 [conn41] 	 dropIndexes done
2013-10-30T16:20:05.627+0000 [conn41] command DriverTest-406368717001567.$cmd command: { drop: "com.mongodb.DBCursorTest406373994841307" } ntoreturn:1 keyUpdates:0 locks(micros) w:509 reslen:129 0ms
2013-10-30T16:20:05.631+0000 [conn41] Database::_addNamespaceToCatalog ns: DriverTest-406368717001567.com.mongodb.DBCursorTest406374021052232
2013-10-30T16:20:05.631+0000 [conn41] ExtentManager::increaseStorageSize ns:DriverTest-406368717001567.com.mongodb.DBCursorTest406374021052232 desiredSize:4096 fromFreeList: 1 eloc: 0:31000
2013-10-30T16:20:05.631+0000 [conn41] _reuse extent was:DriverTest-406368717001567.com.mongodb.DBCursorTest406373994841307 now:DriverTest-406368717001567.com.mongodb.DBCursorTest406374021052232
2013-10-30T16:20:05.631+0000 [conn41] creating index with info @ 0:3d558
2013-10-30T16:20:05.631+0000 [conn41] build index on: DriverTest-406368717001567.com.mongodb.DBCursorTest406374021052232 properties: { "v" : 1, "key" : { "_id" : 1 }, "name" : "_id_", "ns" : "DriverTest-406368717001567.com.mongodb.DBCursorTest406374021052232" }

(gdb) info threads
  16 Thread 0x7fa3dee36700 (LWP 19687)  0x00007fa3eae2a627 in do_sigwait () from /lib64/libpthread.so.0
  15 Thread 0x7fa3de635700 (LWP 19688)  0x00007fa3eae2a15d in nanosleep () from /lib64/libpthread.so.0
  14 Thread 0x7fa3dde34700 (LWP 19689)  0x00007fa3eae268ec in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  13 Thread 0x7fa3dd633700 (LWP 19691)  0x00007fa3eae268ec in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  12 Thread 0x7fa3dce32700 (LWP 19692)  0x00007fa3eae268ec in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  11 Thread 0x7fa3dc631700 (LWP 19693)  0x00007fa3eae2a15d in nanosleep () from /lib64/libpthread.so.0
  10 Thread 0x7fa3dbe30700 (LWP 19694)  0x00007fa3eae2a15d in nanosleep () from /lib64/libpthread.so.0
  9 Thread 0x7fa3db62f700 (LWP 19695)  0x00007fa3eae2a15d in nanosleep () from /lib64/libpthread.so.0
  8 Thread 0x7fa3dae2e700 (LWP 19696)  0x00007fa3eae268ec in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  7 Thread 0x7fa3da62d700 (LWP 19697)  0x00007fa3eae26c6b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  6 Thread 0x7fa3ec120700 (LWP 19838)  0x00007fa3eae28b80 in sem_wait () from /lib64/libpthread.so.0
  5 Thread 0x7fa3d562b700 (LWP 19954)  0x00007fa3eae29d7c in recv () from /lib64/libpthread.so.0
  4 Thread 0x7fa3c9328700 (LWP 19957)  0x00007fa3eae29d7c in recv () from /lib64/libpthread.so.0
  3 Thread 0x7fa3c9126700 (LWP 19958)  0x00007fa3eae29d7c in recv () from /lib64/libpthread.so.0
  2 Thread 0x7fa3d1429700 (LWP 19961)  0x00007fa3e9b9394d in write () from /lib64/libc.so.6
* 1 Thread 0x7fa3ec22ac40 (LWP 19686)  0x00007fa3e9b997b3 in select () from /lib64/libc.so.6
(gdb) thread 2
[Switching to thread 2 (Thread 0x7fa3d1429700 (LWP 19961))]#0  0x00007fa3e9b9394d in write () from /lib64/libc.so.6
(gdb) bt
#0  0x00007fa3e9b9394d in write () from /lib64/libc.so.6
#1  0x00007fa3e9b32333 in _IO_new_file_write () from /lib64/libc.so.6
#2  0x00007fa3e9b321fa in new_do_write () from /lib64/libc.so.6
#3  0x00007fa3e9b33825 in _IO_new_do_write () from /lib64/libc.so.6
#4  0x00007fa3e9b32870 in _IO_new_file_sync () from /lib64/libc.so.6
#5  0x00007fa3e9b2792b in fflush () from /lib64/libc.so.6
#6  0x00007fa3ea37a28e in std::basic_ostream<char, std::char_traits<char> >::flush() () from /usr/lib64/libstdc++.so.6
#7  0x0000000000eae75f in mongo::printMemInfo(char const*) ()
#8  0x0000000000a8286c in mongo::BtreeBasedBuilder::fastBuildIndex(char const*, mongo::NamespaceDetails*, mongo::IndexDetails&, bool, int) ()
#9  0x00000000008d17c3 in mongo::buildAnIndex(mongo::Collection*, mongo::IndexDetails&, bool) ()
#10 0x00000000008cbafa in mongo::IndexCatalog::createIndex(mongo::BSONObj, bool) ()
#11 0x00000000008cc92a in mongo::IndexCatalog::ensureHaveIdIndex() ()
#12 0x0000000000b908dc in mongo::ensureIdIndexForNewNs(mongo::Collection*) ()
#13 0x0000000000b92c5a in mongo::DataFileMgr::insert(char const*, void const*, int, bool, bool, bool, bool*) ()
#14 0x0000000000b9306c in mongo::DataFileMgr::insertWithObjMod(char const*, mongo::BSONObj&, bool, bool) ()
#15 0x0000000000aad213 in mongo::checkAndInsert(char const*, mongo::BSONObj&) ()
#16 0x0000000000ab4421 in mongo::receivedInsert(mongo::Message&, mongo::CurOp&) ()
#17 0x0000000000ab8b52 in mongo::assembleResponse(mongo::Message&, mongo::DbResponse&, mongo::HostAndPort const&) ()
#18 0x000000000079789f in mongo::MyMessageHandler::process(mongo::Message&, mongo::AbstractMessagingPort*, mongo::LastError*) ()
#19 0x0000000000ebab09 in mongo::PortMessageServer::handleIncomingMsg(void*) ()
#20 0x00007fa3eae22c6b in start_thread () from /lib64/libpthread.so.0
#21 0x00007fa3e9ba05ed in clone () from /lib64/libc.so.6



 Comments   
Comment by Eric Milkie [ 30/Oct/13 ]

This is because fastBuildIndex() is calling printMemInfo(), which uses cout() to print some memory stuff.
This is only logged at debug log level 2 or higher, and these tests were recently changed to use debug log level 4.
Fast workaround will be to lower the log level back down. But we should fix printMemInfo not to use cout.

Generated at Thu Feb 08 03:25:54 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.