Replica performance issues

Konstantin · December 15, 2020, 11:25am

Hi,

We using Mongo 4.4.2. The hidden replica has lag (10-180 minutes) during working hours.

One linux process at this time is always 100% busy on one processor core with. The stack trace of this process:

Thread 1 (process 3402):
#0  0x0000558dd3fc1758 in __tree_walk_internal ()
#1  0x0000558dd3ee2ff7 in __wt_evict_thread_run ()
#2  0x0000558dd3f45e89 in __thread_run ()
#3  0x00007f6436de1ea5 in start_thread () from /lib64/libpthread.so.0
#4  0x00007f6436b0a8dd in clone () from /lib64/libc.so.6

The perf top shows

  31.23%  mongod                        [.] __tree_walk_internal
   4.62%  mongod                        [.] __wt_row_search
   3.34%  mongod                        [.] snappy::internal::CompressFragment
   2.89%  libc-2.17.so                  [.] __memcpy_ssse3_back
   2.81%  mongod                        [.] tc_deletearray_aligned_nothrow
   2.10%  mongod                        [.] __wt_page_in_func
   1.87%  mongod                        [.] snappy::InternalUncompress<snappy::SnappyArrayWriter>
   1.58%  mongod                        [.] __wt_rec_row_leaf
   1.28%  mongod                        [.] __wt_row_leaf_key_work
   1.20%  mongod                        [.] __wt_search_insert
   1.15%  mongod                        [.] __wt_evict_thread_run
   1.01%  mongod                        [.] __wt_row_modify
   1.01%  libc-2.17.so                  [.] __strlen_sse2_pminub

There is correlation: the metric “eviction empty score” is more than 95 if there is a lag.

What could be the performance issue?

logwriter · December 15, 2020, 7:48pm

Hey Konstantin,

There are many factors that could cause a replication lag.

Can you provide more info about the topology of your replica set?
What is the RTT between the hidden member and its sync source?
Does the hidden member have the same CPU/MEM/Network/Disk config as others in the rs?

All the best,

– Rodrigo

kevinadi · December 15, 2020, 11:04pm

Hi @Konstantin welcome to the community!

Along with what @logwriter have asked, I would also ask for a couple of additional info:

What’s the output of your rs.status()
What’s the output of your rs.conf()

Best regards,
Kevin

Konstantin · December 16, 2020, 10:04am

Hi Rodrigo,

I will provide the configuration in the next post.

How can I measure RTT?

Yes.

Best regards,
Konstantin

Konstantin · December 16, 2020, 10:04am

Hi @kevinadi,

rs.conf()

{
    "_id" : "testing",
    "version" : 86588,
    "term" : 155,
    "protocolVersion" : NumberLong(1),
    "writeConcernMajorityJournalDefault" : true,
    "members" : [
            {
                    "_id" : 5,
                    "host" : "mongo04:27017",
                    "arbiterOnly" : false,
                    "buildIndexes" : true,
                    "hidden" : true,
                    "priority" : 0,
                    "tags" : {

                    },
                    "slaveDelay" : NumberLong(0),
                    "votes" : 0
            },
            {
                    "_id" : 6,
                    "host" : "mongo15:27017",
                    "arbiterOnly" : false,
                    "buildIndexes" : true,
                    "hidden" : false,
                    "priority" : 10,
                    "tags" : {

                    },
                    "slaveDelay" : NumberLong(0),
                    "votes" : 1
            },
            {
                    "_id" : 7,
                    "host" : "mongo16:27017",
                    "arbiterOnly" : false,
                    "buildIndexes" : true,
                    "hidden" : false,
                    "priority" : 15,
                    "tags" : {

                    },
                    "slaveDelay" : NumberLong(0),
                    "votes" : 1
            },
            {
                "_id" : 8,
                "host" : "mongo14:27017",
                "arbiterOnly" : false,
                "buildIndexes" : true,
                "hidden" : false,
                "priority" : 3,
                "tags" : {

                },
                "slaveDelay" : NumberLong(0),
                "votes" : 1
        },
        {
                "_id" : 9,
                "host" : "mongo25:27017",
                "arbiterOnly" : false,
                "buildIndexes" : true,
                "hidden" : false,
                "priority" : 5,
                "tags" : {

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

        },
        "getLastErrorDefaults" : {
                "w" : 1,
                "wtimeout" : 0
        },
        "replicaSetId" : ObjectId("5d431b1658c69cd9030a7267")
}

rs.status()

{
    "set" : "testing",
    "date" : ISODate("2020-12-11T10:19:39.417Z"),
    "myState" : 2,
    "term" : NumberLong(155),
    "syncSourceHost" : "mongo15:27017",
    "syncSourceId" : 6,
    "heartbeatIntervalMillis" : NumberLong(2000),
    "majorityVoteCount" : 3,
    "writeMajorityCount" : 3,
    "votingMembersCount" : 4,
    "writableVotingMembersCount" : 4,
    "optimes" : {
            "lastCommittedOpTime" : {
                    "ts" : Timestamp(1607681977->2020-12-11 13:19:37, 2547),
                    "t" : NumberLong(155)
            },
            "lastCommittedWallTime" : ISODate("2020-12-11T10:19:37.601Z"),
            "readConcernMajorityOpTime" : {
                    "ts" : Timestamp(1607674381->2020-12-11 11:13:01, 4262),
                    "t" : NumberLong(155)
            },
            "readConcernMajorityWallTime" : ISODate("2020-12-11T08:13:01.529Z"),
            "appliedOpTime" : {
                    "ts" : Timestamp(1607674381->2020-12-11 11:13:01, 4262),
                    "t" : NumberLong(155)
            },
            "durableOpTime" : {
                    "ts" : Timestamp(1607674381, 4262),
                    "t" : NumberLong(155)
            },
            "lastAppliedWallTime" : ISODate("2020-12-11T08:13:01.529Z"),
            "lastDurableWallTime" : ISODate("2020-12-11T08:13:01.529Z")
    },
    "lastStableRecoveryTimestamp" : Timestamp(1607674103, 12186),
    "members" : [
            {
                    "_id" : 5,
                    "name" : "mongo04:27017",
                    "health" : 1,
                    "state" : 2,
                    "stateStr" : "SECONDARY",
                    "uptime" : 61502,
                    "optime" : {
                            "ts" : Timestamp(1607674381, 4262),
                            "t" : NumberLong(155)
                    },
                    "optimeDate" : ISODate("2020-12-11T08:13:01Z"),
                    "syncSourceHost" : "mongo15:27017",
                    "syncSourceId" : 6,
                    "infoMessage" : "",
                    "configVersion" : 86588,
                    "configTerm" : 155,
                    "self" : true,
                    "lastHeartbeatMessage" : ""
            },
            {
                    "_id" : 6,
                    "name" : "mongo15:27017",
                    "health" : 1,
                    "state" : 2,
                    "stateStr" : "SECONDARY",
                    "uptime" : 61483,
                    "optime" : {
                            "ts" : Timestamp(1607681977, 3467),
                            "t" : NumberLong(155)
                    },
                    "optimeDurable" : {
                            "ts" : Timestamp(1607681977, 3467),
                            "t" : NumberLong(155)
                    },
                    "optimeDate" : ISODate("2020-12-11T10:19:37Z"),
                    "optimeDurableDate" : ISODate("2020-12-11T10:19:37Z"),
                    "lastHeartbeat" : ISODate("2020-12-11T10:19:37.926Z"),
                    "lastHeartbeatRecv" : ISODate("2020-12-11T10:19:37.466Z"),
                    "pingMs" : NumberLong(0),
                    "lastHeartbeatMessage" : "",
                    "syncSourceHost" : "mongo16:27017",
                    "syncSourceId" : 7,
                    "infoMessage" : "",
                    "configVersion" : 86588,
                    "configTerm" : 155
            },
            {
                    "_id" : 7,
                    "name" : "mongo16:27017",
                    "health" : 1,
                    "state" : 1,
                    "stateStr" : "PRIMARY",
                    "uptime" : 61483,
                    "optime" : {
                            "ts" : Timestamp(1607681977, 2830),
                            "t" : NumberLong(155)
                    },
                    "optimeDurable" : {
                            "ts" : Timestamp(1607681977, 2448),
                            "t" : NumberLong(155)
                    },
                    "optimeDate" : ISODate("2020-12-11T10:19:37Z"),
                    "optimeDurableDate" : ISODate("2020-12-11T10:19:37Z"),
                    "lastHeartbeat" : ISODate("2020-12-11T10:19:37.657Z"),
                    "lastHeartbeatRecv" : ISODate("2020-12-11T10:19:37.762Z"),
                    "pingMs" : NumberLong(0),
                    "lastHeartbeatMessage" : "",
                    "syncSourceHost" : "",
                    "syncSourceId" : -1,
                    "infoMessage" : "",
                    "electionTime" : Timestamp(1607221044, 12),
                    "electionDate" : ISODate("2020-12-06T02:17:24Z"),
                    "configVersion" : 86588,
                    "configTerm" : 155
            },
            {
                    "_id" : 8,
                    "name" : "mongo14:27017",
                    "health" : 1,
                    "state" : 2,
                    "stateStr" : "SECONDARY",
                    "uptime" : 61483,
                    "optime" : {
                            "ts" : Timestamp(1607678728, 4808),
                            "t" : NumberLong(155)
                    },
                    "optimeDurable" : {
                            "ts" : Timestamp(1607678728, 4808),
                            "t" : NumberLong(155)
                    },
                    "optimeDate" : ISODate("2020-12-11T09:25:28Z"),
                    "optimeDurableDate" : ISODate("2020-12-11T09:25:28Z"),
                    "lastHeartbeat" : ISODate("2020-12-11T10:19:37.925Z"),
                    "lastHeartbeatRecv" : ISODate("2020-12-11T10:19:37.760Z"),
                    "pingMs" : NumberLong(0),
                    "lastHeartbeatMessage" : "",
                    "syncSourceHost" : "mongo16:27017",
                    "syncSourceId" : 7,
                    "infoMessage" : "",
                    "configVersion" : 86588,
                    "configTerm" : 155
            },
            {
                    "_id" : 9,
                    "name" : "mongo25:27017",
                    "health" : 1,
                    "state" : 2,
                    "stateStr" : "SECONDARY",
                    "uptime" : 61483,
                    "optime" : {
                            "ts" : Timestamp(1607681977, 1618),
                            "t" : NumberLong(155)
                    },
                    "optimeDurable" : {
                            "ts" : Timestamp(1607681977, 1618),
                            "t" : NumberLong(155)
                    },
                    "optimeDate" : ISODate("2020-12-11T10:19:37Z"),
                    "optimeDurableDate" : ISODate("2020-12-11T10:19:37Z"),
                    "lastHeartbeat" : ISODate("2020-12-11T10:19:37.657Z"),
                    "lastHeartbeatRecv" : ISODate("2020-12-11T10:19:37.432Z"),
                    "pingMs" : NumberLong(0),
                    "lastHeartbeatMessage" : "",
                    "syncSourceHost" : "mongo16:27017",
                    "syncSourceId" : 7,
                    "infoMessage" : "",
                    "configVersion" : 86588,
                    "configTerm" : 155
            }
    ],
    "ok" : 1,
    "$clusterTime" : {
            "clusterTime" : Timestamp(1607681978, 5249),
            "signature" : {
                    "hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
                    "keyId" : NumberLong(0)
            }
    },
    "operationTime" : Timestamp(1607674381->2020-12-11 11:13:01, 4262)
}

logwriter · December 16, 2020, 12:29pm

You can measure the network RTT by connecting to your hidden member (mongo04) and sending a ping to its sync source (mongo15).

Example:

PING 172.16.13.9 (172.16.13.9): 56 data bytes
64 bytes from 172.16.13.9: icmp_seq=0 ttl=64 time=0.882 ms
64 bytes from 172.16.13.9: icmp_seq=1 ttl=64 time=0.384 ms
64 bytes from 172.16.13.9: icmp_seq=2 ttl=64 time=0.570 ms
64 bytes from 172.16.13.9: icmp_seq=3 ttl=64 time=0.370 ms
64 bytes from 172.16.13.9: icmp_seq=4 ttl=64 time=0.502 ms
^C
--- 172.16.13.9 ping statistics ---
5 packets transmitted, 5 packets received, 0.0% packet loss
round-trip min/avg/max/stddev = 0.370/0.542/0.882/0.186 ms

In the example above, the average RTT is 0.542 ms.

All the best,

– Rodrigo

Konstantin · December 16, 2020, 12:33pm

ping mongo15

8 packets transmitted, 8 received, 0% packet loss, time 7005ms
rtt min/avg/max/mdev = 0.085/0.122/0.182/0.039 ms

logwriter · December 16, 2020, 1:16pm

Your RTT is awesome . With network out of the way, we have to investigate other parts of the stack.

Can you share the output of:

mongostat during working hours
few samples of db.serverStatus() from the primary, mongo15, and mongo04

All the best,

– Rodrigo

Konstantin · December 16, 2020, 2:14pm

mongostat

insert query update delete getmore command dirty  used flushes vsize  res  qrw arw net_in net_out conn        set repl                time
 *1071    *0 *11517    *12       0     6|0 20.6% 79.0%       0  237G 213G 0|16 1|0  2.21k   79.4k   10 testing  SEC Dec 16 16:38:19.899
  *761    *0  *6264    *14       0     3|0 20.6% 78.9%       0  237G 213G 0|16 1|0   996b   35.7k   10 testing  SEC Dec 16 16:38:21.188
  *970    *0 *13334    *33       0     6|0 20.6% 78.9%       0  237G 213G 0|16 1|0  2.13k   76.4k   10 testing  SEC Dec 16 16:38:21.791
  *897    *0  *5141    *24       0     3|0 20.6% 78.8%       0  237G 213G 0|16 1|0   998b   35.8k   10 testing  SEC Dec 16 16:38:23.078
  *956    *0  *9628    *19       0     5|0 20.6% 78.8%       0  237G 213G 0|15 1|0  1.67k   60.0k   10 testing  SEC Dec 16 16:38:23.846
  *540    *0  *3242    *16       0     2|0 20.6% 78.7%       0  237G 213G 0|16 1|0   687b   24.6k   10 testing  SEC Dec 16 16:38:25.715
  *529    *0  *3749     *9       0     3|0 20.6% 78.6%       0  237G 213G 0|15 1|0  1.15k   41.8k   10 testing  SEC Dec 16 16:38:26.832
 *1074    *0  *4582    *18       0     5|0 20.6% 78.6%       0  237G 213G 0|16 1|0  1.38k   48.9k   10 testing  SEC Dec 16 16:38:27.805
  *481    *0  *3802     *9       0     3|0 20.6% 78.5%       0  237G 213G 0|15 1|0  1.01k   36.2k   10 testing  SEC Dec 16 16:38:29.078
  *405    *0  *3827    *13       0     5|0 20.6% 78.5%       0  237G 213G 0|16 1|0  1.66k   38.4k   10 testing  SEC Dec 16 16:38:30.362

I noticed that if there is a lag, then the “qrw” is equal to “0|16”.

logwriter · December 16, 2020, 3:48pm

qrw is the number of clients waiting in a queue to read or write to the instance. The number on the left of the “|” is the number of clients waiting to read data; the number on the right of the “|” is the number of clients waiting to write data.

I’m going to look at all these data, and let you know if I find anything interesting.

logwriter · December 16, 2020, 10:47pm

Hey @Konstantin!

What is the replication lag between mongo15 and the primary during working hours?

It looks like your workload is predominant queries and updates:

opcounters	insert	query	update	delete	getmore	Total opcount	% insert	% query	% update	% delete	% getmore
mongo16	489,841,759	3,342,264,963	1,964,763,438	56,824,876	1,342,395,157	7,196,090,193	6.81%	46.45%	27.30%	0.79%	18.65%
mongo15	1,213,845	3,337,071,771	9,277,428	53,262	35,840,774	3,383,457,080	0.04%	98.63%	0.27%	0.00%	1.06%
mongo04	-	722,850	-	-	47,780	770,630	0.00%	93.80%	0.00%	0.00%	6.20%

At a glance, I noticed mongo15 (sync source for mongo04) has been busy serving queries (~98% of its total opcount), while also having to keep up with a heavy replication update workload (~79% of its opReplCount).

opcounterRepl	insert	query	update	delete	getmore	Total opcount	% insert	% query	% update	% delete
mongo16	1,635,305	-	9,709,525	174,284	-	11,519,114	14.20%	0.00%	84%	2%
mongo15	1,057,934,813	-	4,474,701,469	138,481,085	-	5,671,117,367	18.65%	0.00%	79%	2%
mongo04	355,496,844	0	1,512,312,845	33,000,800	-	1,900,810,489	18.70%	0.00%	80%	2%

Keep in mind, these counters are counting the number of operations since each instance has been started. That was the reason why I asked for a couple of db.serverStatus samples from each node, therefore we could calculate the difference between two positions in time. I only had one sample per server, so … cut me some slack with this ends up not making any sense.

First of all, a secondary main role should be to provide data availability in the cluster. With that being said, it’s ok to let the application query from a secondary if the query workload isn’t heavy and it isn’t causing any replication lag.

My guess: mongo15 is too busy serving queries and it’s causing a replication lag. Then, mongo04 is also suffering the consequences, because mongo15 is its sync source.

Make sense?

– Rodrigo

Konstantin · December 17, 2020, 6:36am

Hi @logwriter,

A few seconds.

According to mongostat, the number of clients waiting to write data is maximum (qw=16) when there is the lag. Could this mean that they are waiting for reading from mongo15 and not writing to mongo04?

I’ll try to do something with mongo15 and mongo04.

Thank you so much for your help!