[SERVER-17681] Secondary freeze while sync Created: 21/Mar/15  Updated: 23/Mar/15  Resolved: 23/Mar/15

Status: Closed
Project: Core Server
Component/s: Replication, WiredTiger
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Tal Rasha Assignee: Unassigned
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Participants:

 Description   

when there is a lot of inserts(about 4Kops/s), it happens randomly, i think there's a deadlock.

Here's the state:

rs1|_id:1's cpu usage is 0, and it will sync as expected if I restart it.

rs1:SECONDARY> rs.status()
{
	"set" : "rs1",
	"date" : ISODate("2015-03-21T02:16:27.794Z"),
	"myState" : 2,
	"syncingTo" : "172.16.1.1:39017",
	"members" : [
		{
			"_id" : 0,
			"name" : "172.16.1.1:39017",
			"health" : 1,
			"state" : 1,
			"stateStr" : "PRIMARY",
			"uptime" : 247160,
			"optime" : Timestamp(1426904187, 172),
			"optimeDate" : ISODate("2015-03-21T02:16:27Z"),
			"lastHeartbeat" : ISODate("2015-03-21T02:16:27.382Z"),
			"lastHeartbeatRecv" : ISODate("2015-03-21T02:16:26.859Z"),
			"pingMs" : 0,
			"electionTime" : Timestamp(1426657027, 1),
			"electionDate" : ISODate("2015-03-18T05:37:07Z"),
			"configVersion" : 1
		},
		{
			"_id" : 1,
			"name" : "172.16.1.2:39017",
			"health" : 1,
			"state" : 2,
			"stateStr" : "SECONDARY",
			"uptime" : 247288,
			"optime" : Timestamp(1426892223, 518),
			"optimeDate" : ISODate("2015-03-20T22:57:03Z"),
			"syncingTo" : "172.16.1.1:39017",
			"configVersion" : 1,
			"self" : true
		},
		{
			"_id" : 2,
			"name" : "172.16.1.3:39017",
			"health" : 1,
			"state" : 2,
			"stateStr" : "SECONDARY",
			"uptime" : 247040,
			"optime" : Timestamp(1426904187, 169),
			"optimeDate" : ISODate("2015-03-21T02:16:27Z"),
			"lastHeartbeat" : ISODate("2015-03-21T02:16:27.375Z"),
			"lastHeartbeatRecv" : ISODate("2015-03-21T02:16:26.357Z"),
			"pingMs" : 0,
			"syncingTo" : "172.16.1.1:39017",
			"configVersion" : 1
		}
	],
	"ok" : 1
}
 
rs1:SECONDARY> db.currentOp()
{
	"inprog" : [
		{
			"desc" : "repl writer worker 9",
			"threadId" : "0x3b79480",
			"opid" : 16975002,
			"active" : true,
			"secs_running" : 11995,
			"microsecs_running" : NumberLong("11995253803"),
			"op" : "none",
			"ns" : "device.labels",
			"query" : {
				
			},
			"numYields" : 0,
			"locks" : {
				"Global" : "w",
				"Database" : "w",
				"Collection" : "w"
			},
			"waitingForLock" : false,
			"lockStats" : {
				"Global" : {
					"acquireCount" : {
						"w" : NumberLong(1)
					}
				},
				"Database" : {
					"acquireCount" : {
						"w" : NumberLong(1)
					}
				},
				"Collection" : {
					"acquireCount" : {
						"w" : NumberLong(1)
					}
				}
			}
		}
	]
}

mongod is started by:
numactl --interleave=all mongod --fork --dbpath /data01/dmp-data/ --logpath /home/hadoop/dmp-data/logs/data1.log --storageEngine wiredTiger --wiredTigerCacheSizeGB 8 --port 39017 --replSet rs1 --shardsvr



 Comments   
Comment by Sam Kleinman (Inactive) [ 23/Mar/15 ]

Thanks for this information.

MongoDB+MMAP did not (typically) use the full CPU and IO capacity of a system, and as a result many deployments used an approach with multiple mongod instances on a single host connected to RAID arrays with high-throughput in order to use resources more efficiently. MongoDB+WiredTiger in 3.0, is, however, able to effectively use more CPU and IO resources because of it's overall increased efficiency and compression features: as a result, running multiple mongod instances on a single host may cause a situation where the mongod instances are contending for the same resources. In one of these situations we would expect to see exactly what you describe here: some mongod instances will appear to freeze when the operating system schedules other processes.

I would recommend lowering the number of mongod instances on each host until the observed contention rate during initial sync is less that the total capacity of the system.

I don't see evidence of a bug, so I'm going to close this ticket because the SERVER project is for reporting bugs or feature suggestions for the MongoDB server.
For MongoDB-related support discussion please post on the mongodb-users group
or Stack Overflow with the mongodb tag.
A question like this involving more discussion would be best posted on the mongodb-users group.

Regards,
sam

Comment by Tal Rasha [ 23/Mar/15 ]

mongod --version
db version v3.0.0
git version: a841fd6394365954886924a35076691b4d149168
OpenSSL version: OpenSSL 1.0.1e-fips 11 Feb 2013

OS: CentOS 6.5
Hardware:
CPU: Intel(R) Xeon(R) CPU E5-2620 v3 @ 2.40GHz X2, 12 cores 24 threads
MEM: 64GB
HDD: 5TB raid mounted as /, and 4x 500GB ssd mounted as data01, data02, data03, data04

There are 3 same machines, each of them has a config server, a mongos instance, 4 mongod instances.
numactl --interleave=all mongod --configsvr --dbpath /home/hadoop/dmp-data/cfg --port 39000 --fork --logpath /home/hadoop/dmp-data/logs/cfg.log --storageEngine wiredTiger --wiredTigerCacheSizeGB 1
numactl --interleave=all mongod --fork --dbpath /data01/dmp-data/ --logpath /home/hadoop/dmp-data/logs/data1.log --storageEngine wiredTiger --wiredTigerCacheSizeGB 8 --port 39017 --replSet rs1 --shardsvr
numactl --interleave=all mongod --fork --dbpath /data02/dmp-data/ --logpath /home/hadoop/dmp-data/logs/data2.log --storageEngine wiredTiger --wiredTigerCacheSizeGB 8 --port 39027 --replSet rs2 --shardsvr
numactl --interleave=all mongod --fork --dbpath /data03/dmp-data/ --logpath /home/hadoop/dmp-data/logs/data3.log --storageEngine wiredTiger --wiredTigerCacheSizeGB 8 --port 39037 --replSet rs3 --shardsvr
numactl --interleave=all mongod --fork --dbpath /data04/dmp-data/ --logpath /home/hadoop/dmp-data/logs/data4.log --storageEngine wiredTiger --wiredTigerCacheSizeGB 8 --port 39047 --replSet rs4 --shardsvr
numactl --interleave=all mongos --configdb 172.16.1.1:39000,172.16.1.2:39000,172.16.1.3:39000 --port 27017 --fork --logpath /home/hadoop/dmp-data/logs/mongos.log

It seems there's no useful log just looks like the following
(I think i should use debug level to log more infomation. )
(I feel it's a bug that like SERVER-17416, how can i dump locker status? I updated to 3.0.1 today, and it happened again, no log.)
2015-03-21T05:10:43.045+0800 I NETWORK [conn15252] end connection 172.16.1.3:43913 (7 connections now open)
2015-03-21T05:10:43.045+0800 I NETWORK [initandlisten] connection accepted from 172.16.1.3:43921 #15254 (8 connections now open)
2015-03-21T05:10:44.291+0800 I NETWORK [conn15253] end connection 172.16.1.2:33507 (7 connections now open)
2015-03-21T05:10:44.291+0800 I NETWORK [initandlisten] connection accepted from 172.16.1.2:33516 #15255 (8 connections now open)
2015-03-21T05:11:02.022+0800 I REPL [ReplicationExecutor] changing sync target because current sync target's most recent OpTime is Mar 21 05:10:30 550c8cc6:8f which is
more than 30 seconds behind member 172.16.1.2:39027 whose most recent OpTime is Mar 21 05:11:01 550c8ce5:242
2015-03-21T05:11:02.022+0800 I REPL [ReplicationExecutor] syncing from: 172.16.1.2:39027
2015-03-21T05:11:02.023+0800 I REPL [SyncSourceFeedback] replset setting syncSourceFeedback to 172.16.1.2:39027
2015-03-21T05:11:13.054+0800 I NETWORK [conn15254] end connection 172.16.1.3:43921 (7 connections now open)
2015-03-21T05:11:13.054+0800 I NETWORK [initandlisten] connection accepted from 172.16.1.3:43931 #15256 (8 connections now open)
2015-03-21T05:11:14.297+0800 I NETWORK [conn15255] end connection 172.16.1.2:33516 (7 connections now open)

Comment by Asya Kamsky [ 21/Mar/15 ]

Could you provide the exact version you are running? (mongod --version ought to do it).

At the time you observe this, what is in the logs on the secondaries that "freeze"? Can you provide the log or at least the last dozen or so lines? How much RAM is on the machine this happens on? (I see you specify 8GB for wired tiger cache, out of how many is that?)

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