Details
-
Bug
-
Resolution: Incomplete
-
Major - P3
-
None
-
3.0.6
-
None
-
ALL
Description
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