[SERVER-58507] Performence Degrade after upgrading to mongo 4.4.2 Created: 14/Jul/21  Updated: 09/Aug/21  Resolved: 09/Aug/21

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

Type: Bug Priority: Major - P3
Reporter: Subhrajit Nandy Assignee: Edwin Zhou
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Participants:

 Description   

We have upgraded our database from mongo 2.6 to mongo 4.4.2. After upgrading to new database the queries which was taking 12 seconds in old version and now it is taking 41 seconds. We have revamped our code according to the new mongo 4.4.2 storage engine. Our mongo database is consists of 1 primary server and 2 secondary servers under replica set. Below are the whole details. We are using aws ec2 instances for all servers and Ubuntu 20.04.1 LTS OS. Please guide us to get rid of the issue

 

rs0:PRIMARY> rs.status()
{
"set" : "rs0",
"date" : ISODate("2021-07-14T05:25:57.294Z"),
"myState" : 1,
"term" : NumberLong(9),
"syncSourceHost" : "",
"syncSourceId" : -1,
"heartbeatIntervalMillis" : NumberLong(2000),
"majorityVoteCount" : 2,
"writeMajorityCount" : 2,
"votingMembersCount" : 3,
"writableVotingMembersCount" : 3,
"optimes" : {
"lastCommittedOpTime" :

{ "ts" : Timestamp(1626240350, 1), "t" : NumberLong(9) }

,
"lastCommittedWallTime" : ISODate("2021-07-14T05:25:50.983Z"),
"readConcernMajorityOpTime" :

{ "ts" : Timestamp(1626240350, 1), "t" : NumberLong(9) }

,
"readConcernMajorityWallTime" : ISODate("2021-07-14T05:25:50.983Z"),
"appliedOpTime" :

{ "ts" : Timestamp(1626240350, 1), "t" : NumberLong(9) }

,
"durableOpTime" :

{ "ts" : Timestamp(1626240350, 1), "t" : NumberLong(9) }

,
"lastAppliedWallTime" : ISODate("2021-07-14T05:25:50.983Z"),
"lastDurableWallTime" : ISODate("2021-07-14T05:25:50.983Z")
},
"lastStableRecoveryTimestamp" : Timestamp(1626240350, 1),
"electionCandidateMetrics" : {
"lastElectionReason" : "stepUpRequestSkipDryRun",
"lastElectionDate" : ISODate("2021-06-21T09:23:44.018Z"),
"electionTerm" : NumberLong(9),
"lastCommittedOpTimeAtElection" :

{ "ts" : Timestamp(1624267416, 1), "t" : NumberLong(8) }

,
"lastSeenOpTimeAtElection" :

{ "ts" : Timestamp(1624267416, 1), "t" : NumberLong(8) }

,
"numVotesNeeded" : 2,
"priorityAtElection" : 1,
"electionTimeoutMillis" : NumberLong(10000),
"priorPrimaryMemberId" : 1,
"numCatchUpOps" : NumberLong(0),
"newTermStartDate" : ISODate("2021-06-21T09:23:44.028Z"),
"wMajorityWriteAvailabilityDate" : ISODate("2021-06-21T09:23:46.211Z")
},
"members" : [
{
"_id" : 0,
"name" : "mongo-rs.follettdiscover.com:27017",
"health" : 1,
"state" : 1,
"stateStr" : "PRIMARY",
"uptime" : 1973082,
"optime" :

{ "ts" : Timestamp(1626240350, 1), "t" : NumberLong(9) }

,
"optimeDate" : ISODate("2021-07-14T05:25:50Z"),
"syncSourceHost" : "",
"syncSourceId" : -1,
"infoMessage" : "",
"electionTime" : Timestamp(1624267424, 1),
"electionDate" : ISODate("2021-06-21T09:23:44Z"),
"configVersion" : 1,
"configTerm" : 9,
"self" : true,
"lastHeartbeatMessage" : ""
},
{
"_id" : 1,
"name" : "mongo-rs1.follettdiscover.com:27017",
"health" : 1,
"state" : 2,
"stateStr" : "SECONDARY",
"uptime" : 54098,
"optime" :

{ "ts" : Timestamp(1626240350, 1), "t" : NumberLong(9) }

,
"optimeDurable" :

{ "ts" : Timestamp(1626240350, 1), "t" : NumberLong(9) }

,
"optimeDate" : ISODate("2021-07-14T05:25:50Z"),
"optimeDurableDate" : ISODate("2021-07-14T05:25:50Z"),
"lastHeartbeat" : ISODate("2021-07-14T05:25:57.260Z"),
"lastHeartbeatRecv" : ISODate("2021-07-14T05:25:56.187Z"),
"pingMs" : NumberLong(0),
"lastHeartbeatMessage" : "",
"syncSourceHost" : "mongo-rs.follettdiscover.com:27017",
"syncSourceId" : 0,
"infoMessage" : "",
"configVersion" : 1,
"configTerm" : 9
},
{
"_id" : 2,
"name" : "mongo-rs2.follettdiscover.com:27017",
"health" : 1,
"state" : 2,
"stateStr" : "SECONDARY",
"uptime" : 53847,
"optime" :

{ "ts" : Timestamp(1626240350, 1), "t" : NumberLong(9) }

,
"optimeDurable" :

{ "ts" : Timestamp(1626240350, 1), "t" : NumberLong(9) }

,
"optimeDate" : ISODate("2021-07-14T05:25:50Z"),
"optimeDurableDate" : ISODate("2021-07-14T05:25:50Z"),
"lastHeartbeat" : ISODate("2021-07-14T05:25:56.438Z"),
"lastHeartbeatRecv" : ISODate("2021-07-14T05:25:57.244Z"),
"pingMs" : NumberLong(1),
"lastHeartbeatMessage" : "",
"syncSourceHost" : "mongo-rs1.follettdiscover.com:27017",
"syncSourceId" : 1,
"infoMessage" : "",
"configVersion" : 1,
"configTerm" : 9
}
],
"ok" : 1,
"$clusterTime" : {
"clusterTime" : Timestamp(1626240350, 1),
"signature" :

{ "hash" : BinData(0,"jZiMVRAemCd6nhBWCTr2PdDc9Zk="), "keyId" : NumberLong("6976173241245106178") }

},
"operationTime" : Timestamp(1626240350, 1)
}

 

 

rs0:PRIMARY> rs.conf()
{
"_id" : "rs0",
"version" : 1,
"term" : 9,
"protocolVersion" : NumberLong(1),
"writeConcernMajorityJournalDefault" : true,
"members" : [
{
"_id" : 0,
"host" : "mongo-rs.follettdiscover.com:27017",
"arbiterOnly" : false,
"buildIndexes" : true,
"hidden" : false,
"priority" : 1,
"tags" : {

},
"slaveDelay" : NumberLong(0),
"votes" : 1
},
{
"_id" : 1,
"host" : "mongo-rs1.follettdiscover.com:27017",
"arbiterOnly" : false,
"buildIndexes" : true,
"hidden" : false,
"priority" : 1,
"tags" : {

},
"slaveDelay" : NumberLong(0),
"votes" : 1
},
{
"_id" : 2,
"host" : "mongo-rs2.follettdiscover.com:27017",
"arbiterOnly" : false,
"buildIndexes" : true,
"hidden" : false,
"priority" : 1,
"tags" : {

},
"slaveDelay" : NumberLong(0),
"votes" : 1
}
],
"settings" : {
"chainingAllowed" : true,
"heartbeatIntervalMillis" : 2000,
"heartbeatTimeoutSecs" : 10,
"electionTimeoutMillis" : 10000,
"catchUpTimeoutMillis" : -1,
"catchUpTakeoverDelayMillis" : 30000,
"getLastErrorModes" : {

},
"getLastErrorDefaults" :

{ "w" : 1, "wtimeout" : 0 }

,
"replicaSetId" : ObjectId("5ffd7bff262aededdee0a08f")
}
}

 

 

rs0:PRIMARY> rs.printReplicationInfo()
configured oplog size: 990MB
log length start to end: 1280085secs (355.58hrs)
oplog first event time: Tue Jun 29 2021 09:50:15 GMT+0000 (UTC)
oplog last event time: Wed Jul 14 2021 05:25:00 GMT+0000 (UTC)
now: Wed Jul 14 2021 05:25:04 GMT+0000 (UTC)

 

rs0:PRIMARY> rs.printSecondaryReplicationInfo()
source: mongo-rs1.follettdiscover.com:27017
syncedTo: Wed Jul 14 2021 05:25:30 GMT+0000 (UTC)
0 secs (0 hrs) behind the primary
source: mongo-rs2.follettdiscover.com:27017
syncedTo: Wed Jul 14 2021 05:25:30 GMT+0000 (UTC)
0 secs (0 hrs) behind the primary

 

 



 Comments   
Comment by Edwin Zhou [ 09/Aug/21 ]

Hi subhrajit.nandy@tcs.com,

We haven’t heard back from you for some time, so I’m going to close this ticket. If this is still an issue for you, please provide additional information and we will reopen the ticket.

Best,
Edwin

Comment by Edwin Zhou [ 02/Aug/21 ]

Hi subhrajit.nandy@tcs.com,

We still need additional information to diagnose the problem. If this is still an issue for you, would you please provide specifics about what operations you see taking longer, and narrow down when the performance change occurred?

Best,
Edwin

Comment by Eric Sedor [ 15/Jul/21 ]

Hi subhrajit.nandy@tcs.com,

A transition from 2.6 to 4.4.2 is a significant change. Can you provide specifics about what operations you see taking longer, and narrow down when the performance change occurred?

Thanks!

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