Loading...

XML

Word

Printable

JSON

Type: Bug
Resolution: Incomplete
Priority: Major - P3
Fix Version/s: None
Affects Version/s: 3.0.6
Component/s: Admin
Labels:
None

Operating System:
ALL

I would like to report a strange behaviour here,
on MongoDB 3.0.6 with wiredTiger.

#Architecture
mongos: 3ea
config: 3ea
replicatSet: shard3
primary,secondary#1,secondary#2,new secondary#3(dump)

I do not understand why the connection increased and the service impact occurred.

Summary
rs.add Increased connection due to work impact, error occurred on app server side Service affected.

 # connection(primary:1.242k(avg)>7.192k(max), secondary#1:617k(avg)>0k)
 # app server(Unexpected exception occurred: com.mongodb.MongoSocketReadTimeoutException: Timeoutwhilereceiving message, message: Timeoutwhilereceiving message occurred)


//task config
rs.add( { _id: 3, "host": "secondary#3 (dump)", "priority": 0, "hidden": true } )


// new secondary#3(dump) mongod.log
2017-11-15T11:21:48.638+0900 I REPL     [rsSync] replSet warning did not receive a valid config yet, sleeping 5 seconds
2017-11-15T11:21:53.638+0900 I REPL     [rsSync] ******
2017-11-15T11:21:53.638+0900 I REPL     [rsSync] creating replication oplog of size: 50000MB...
2017-11-15T11:21:53.646+0900 I REPL     [rsSync] ******
2017-11-15T11:21:53.646+0900 I REPL     [rsSync] initial sync pending
2017-11-15T11:21:53.666+0900 I REPL     [rsSync] initial sync drop all databases
2017-11-15T11:21:53.666+0900 I REPL     [rsSync] initial sync clone all databases
2017-11-15T11:21:53.672+0900 I REPL     [rsSync] initial sync cloning db: admin
2017-11-15T11:21:53.723+0900 I REPL     [rsSync] initial sync cloning db: shop                              <<<<<<<<<<<<<<<<<<<<<<<<<<<<< connection(primary:1.242k(avg)>7.192k(max), secondary#1:617k(avg)>0k), app server( Timeout > reconnect > spike )

 D STORAGE  [rsSync] WT begin_transaction
 D STORAGE  [rsSync] WT commit_transaction
 D STORAGE  [rsSync] WT begin_transaction
 D STORAGE  [rsSync] WT commit_transaction
 D STORAGE  [rsSync] WT begin_transaction
 D STORAGE  [rsSync] WT commit_transaction
 D STORAGE  [rsSync] WT begin_transaction
 D STORAGE  [rsSync] WT commit_transaction
 D STORAGE  [rsSync] WT begin_transaction
 D STORAGE  [rsSync] WT commit_transaction
 D STORAGE  [rsSync] WT begin_transaction
 D STORAGE  [rsSync] WT commit_transaction
 D STORAGE  [rsSync] WT begin_transaction

2017-11-15T12:15:18.110+0900 I REPL     [rsSync] initial sync cloning db: test
2017-11-15T12:15:18.138+0900 I REPL     [rsSync] initial sync data copy, starting syncup
2017-11-15T12:15:18.139+0900 I REPL     [rsSync] oplog sync 1 of 3
2017-11-15T12:15:18.140+0900 D REPL     [rsSync] Applying oplog entries from Nov 15 11:21:48:1 until Nov 15 12:14:46:3
2017-11-15T12:15:18.931+0900 D REPL     [rsSync] replication batch size is 46
2017-11-15T12:15:18.965+0900 D REPL     [rsSync] replication batch size is 332
2017-11-15T12:15:19.003+0900 D REPL     [rsSync] SyncTail applied 378 entries (42714 bytes) and finished at opTime Nov 15 12:14:46:3
2017-11-15T12:15:19.003+0900 I REPL     [rsSync] oplog sync 2 of 3
2017-11-15T12:15:19.004+0900 I REPL     [rsSync] initial sync building indexes
2017-11-15T12:15:19.004+0900 I REPL     [rsSync] initial sync cloning indexes for : admin
2017-11-15T12:15:19.031+0900 I REPL     [rsSync] initial sync cloning indexes for : shop
2017-11-15T12:35:41.554+0900 I REPL     [rsSync] initial sync cloning indexes for : test
2017-11-15T12:35:41.569+0900 I REPL     [rsSync] oplog sync 3 of 3
2017-11-15T12:35:41.577+0900 D REPL     [rsSync] Applying oplog entries from Nov 15 12:14:46:3 until Nov 15 12:34:47:a
2017-11-15T12:35:41.577+0900 D REPL     [rsSync] replication batch size is 152
2017-11-15T12:35:41.884+0900 D REPL     [rsSync] SyncTail applied 152 entries (17176 bytes) and finished at opTime Nov 15 12:34:47:a
2017-11-15T12:35:41.898+0900 I REPL     [rsSync] initial sync finishing up
2017-11-15T12:35:41.898+0900 I REPL     [rsSync] replSet set minValid=5a0bb5d7:a
2017-11-15T12:35:41.919+0900 I REPL     [rsSync] initial sync done
2017-11-15T12:35:49.292+0900 D REPL     [rsSync] replication batch size is 1
2017-11-15T12:35:49.294+0900 D REPL     [rsSync] replication batch size is 6
2017-11-15T12:36:47.109+0900 D REPL     [rsSync] replication batch size is 1
2017-11-15T12:36:47.111+0900 D REPL     [rsSync] replication batch size is 7
2017-11-15T12:37:47.121+0900 D REPL     [rsSync] replication batch size is 1
2017-11-15T12:37:47.124+0900 D REPL     [rsSync] replication batch size is 7
2017-11-15T12:37:47.126+0900 D REPL     [rsSync] replication batch size is 2
2017-11-15T12:38:47.139+0900 D REPL     [rsSync] replication batch size is 1
2017-11-15T12:38:47.141+0900 D REPL     [rsSync] replication batch size is 8

Thanks for some feedback,
park hyeonghwa