[SERVER-18231] Primary is unable to be reached when secondary does fullSync Created: 28/Apr/15  Updated: 29/Apr/15  Resolved: 29/Apr/15

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

Type: Bug Priority: Major - P3
Reporter: Maziyar Panahi Assignee: Ramon Fernandez Marina
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-17424 WiredTiger uses substantially more me... Closed
Operating System: ALL
Steps To Reproduce:

Shutdown the Secondary
Remove all the files from dataPath
start the replica set by this command for a fullSync:
sudo mongod --storageEngine wiredTiger --dbpath /data/ --replSet rs0 --fork --logpath /var/log/mongodb/fork.log
Wait for a day or more and the primary unable to be reached

Participants:

 Description   

Hello,

I have a replica set with three nodes (Primary, secondary and arbiter). MongoDB version is 3.0.2 and I started my replica set by this command:

sudo mongod --storageEngine wiredTiger --dbpath /data/ --replSet rs0 --fork --logpath /var/log/mongodb/fork.log

This is a db.stats():

rs0:PRIMARY> db.stats()
{
        "db" : "test",
        "collections" : 52,
        "objects" : 1697582895,
        "avgObjSize" : 745.3563943956916,
        "dataSize" : 1265304265805,
        "storageSize" : 647557865472,
        "numExtents" : 0,
        "indexes" : 176,
        "indexSize" : 22991790080,
        "ok" : 1
}

And this is how it looks like while I am syncing the Secondary on mongostat:

root@mongodb-replica1:/data# mongostat --discover
 
                       insert query update delete getmore command % dirty % used flushes vsize   res qr|qw ar|aw netIn netOut conn set repl     time
       localhost:27017     56     6     13     *0       6     8|0     0.0   80.0       0 31.9G 31.3G   0|2   2|2   49k   214k   58 rs0  PRI 09:49:24
mongodb-replica1:27017     56     6     13     *0       6     4|0     0.0   80.0       0 31.9G 31.3G   0|0   2|0   52k   213k   58 rs0  PRI 09:49:24
mongodb-replica2:27017     *0    *0     *0     *0       0     1|0     1.2    1.3       0 31.9G 29.5G   0|1   1|0   79b    15k    5 rs0  UNK 09:49:24
 
       localhost:27017     26     6      8     *0       5     5|0     0.0   80.0       0 31.9G 31.3G   0|0   1|0   37k   634k   58 rs0  PRI 09:49:25
mongodb-replica1:27017     27     6      8     *0       5     5|0     0.0   80.0       0 31.9G 31.3G   0|0   1|0   34k   633k   58 rs0  PRI 09:49:25
mongodb-replica2:27017     *0    *0     *0     *0       0     7|0     1.2    1.4       0 31.9G 29.5G   0|1   1|0  596b   147k    5 rs0  UNK 09:49:25
 
       localhost:27017     35     3      8     *0       5    20|0     0.0   80.0       0 31.9G 31.3G   0|0   2|0   39k   146k   58 rs0  PRI 09:49:26
mongodb-replica1:27017     34     3      8     *0       5    20|0     0.0   80.0       0 31.9G 31.3G   0|0   2|0   39k   146k   58 rs0  PRI 09:49:26
mongodb-replica2:27017     *0    *0     *0     *0       0     2|0     1.3    1.4       0 31.9G 29.5G   0|1   1|0  137b    16k    5 rs0  UNK 09:49:26
 
       localhost:27017     22     6     24     *0       4     5|0     0.0   80.0       0 31.9G 31.3G   0|0   2|0   54k   212k   58 rs0  PRI 09:49:27
mongodb-replica1:27017     22     6     24     *0       4     4|0     0.0   80.0       0 31.9G 31.3G   0|0   2|0   53k   197k   58 rs0  PRI 09:49:27
mongodb-replica2:27017     *0    *0     *0     *0       0     4|0     1.3    1.5       0 31.9G 29.5G   0|1   1|0  422b    16k    5 rs0  UNK 09:49:27

This is a second time I wanted to full sync my secondary and at the end when the storage is almost equal (650GB) and secondary is building indexes the Primary suddenly has a high cpu usage and eventually freezes. The SSH connection will drop and the machine is not accessible. By the look at alerts on both MMS and application level I can see that all the operations also blocked on Primary and there is no insert/update/and query.

I didn't wait to see what would've happened when the secondary finishes its building index as it was at 22% and I had to wait for a long time without primary but when I restarted the primary the secondary suddenly removed everything and started from the beginning.

The hardware spec is 10-core CPU with 80GB of memory and 3TB of storage on both Primary and Secondary. I don't have CPU profiling on MMS enabled as I remember I couldn't do it way back so let me know if you need more info or to log something for the next time.



 Comments   
Comment by Ramon Fernandez Marina [ 29/Apr/15 ]

Thanks for the update maziyar. In general I'd recommend to let WiredTiger choose the default size for the cache, but I gave you a lower limit to be on the safe side and help allow your system to complete the initial sync. I am going to close this ticket as a duplicate of SERVER-17424 – feel free to tune in to that ticket for updates, and when it gets resolved to re-test with a larger cache size if that may benefit your particular application.

Regards,
Ramón.

Comment by Maziyar Panahi [ 29/Apr/15 ]

Well I started syncing yesterday right after my comment and now it's only been 358GB out of 650GB data on Primary. This is some insight of how resources are being used during syncing just in case if it's needed in future. My best guess is the fact that I ignored the startup warning that says do not run mongod as a root! and perhaps too much memory being used by Primary caused the problem. Which I decreased the wiredTigerCacheSizeGB as you suggested and run the mongod as regular user.

Primary:

 
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 3  1      0 426784 188848 70215328    0    0 11642    16 2720 3430 35  5 57  3  0
 6  0      0 417572 188820 70223504    0    0 12998  1074 2691 3064 34  4 59  3  0
 4  0      0 433552 188804 70208288    0    0 13920    58 3024 3394 32  3 62  3  0
 6  0      0 454880 188788 70188864    0    0 13307    18 2574 3192 30  2 65  3  0
 4  1      0 429060 188788 70212224    0    0 13121   202 2717 2763 34  2 60  3  0
 5  1      0 413684 188872 70228968    0    0 11874  2475 3140 3289 37  4 55  4  0
 5  0      0 442328 188860 70198496    0    0 10985   425 2784 2766 34  4 59  3  0
 1  0      0 432160 188864 70211632    0    0 11091    41 2817 2836 33  4 61  3  0
 4  1      0 437192 188860 70206720    0    0 10360   434 2429 2729 33  7 58  2  0
 4  0      0 427488 188852 70212080    0    0  9710   354 2567 2494 38  5 55  2  0
 2  1      0 446632 188844 70194432    0    0  4888    14 1753 1694 19  2 77  2  0
 0  1      0 419348 188844 70223944    0    0  5846    15 1819 1802 16  2 80  2  0
 3  0      0 432920 188836 70207016    0    0  5120   973 1685 2310 16  2 80  2  0

Secondary:

 
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 3  0  19952 1604100  69480 67690496    0    0     1 20594 1089  735  7 10 83  0  0
 2  0  19952 1471724  69504 67819792    0    0     0 20406 1051  602  7 10 82  0  0
 2  0  19952 1329192  69528 67958920    0    0     0 26870 1147  720  8 11 81  0  0
 2  0  19952 1196864  69568 68088496    0    0     0 53506 1096  784  8 10 81  1  0
 2  0  19952 1049364  69592 68230496    0    0     0 20499 1173  938  8 10 81  1  0
 2  0  19952 900780  69616 68377424    0    0     0 20496 1308  570  8 11 80  1  0
 1  0  19952 722564  69648 68546608    0    0     0 40988 1269  675  9 11 79  1  0

mongostat --discover:

 
                       insert query update delete getmore command % dirty % used flushes vsize   res qr|qw ar|aw netIn netOut conn set repl     time
       localhost:27017     60     3     12     *0       5     4|0     0.0   80.0       0 10.7G 10.1G   0|0   3|0   71k   132k   61 rs0  PRI 10:41:11
mongodb-replica1:27017     60     3     12     *0       5     3|0     0.0   80.0       0 10.7G 10.1G   0|0   2|0   71k   132k   61 rs0  PRI 10:41:11
mongodb-replica2:27017     *0    *0     *0     *0       0     5|0     6.7   72.4       0 10.9G 10.0G   0|1   1|0  394b    17k   27 rs0  UNK 10:41:11
 
       localhost:27017     55     6     10     *0       7     5|0     0.0   80.0       0 10.7G 10.1G   0|1   2|0   63k   244k   61 rs0  PRI 10:41:12
mongodb-replica1:27017     54     6     10     *0       7     5|0     0.0   80.0       0 10.7G 10.1G   0|0   2|0   63k   229k   61 rs0  PRI 10:41:12
mongodb-replica2:27017     *0    *0     *0     *0       0     7|0     5.8   71.5       0 10.9G 10.0G   0|1   1|0  510b    18k   27 rs0  UNK 10:41:12
 
       localhost:27017     50     6     10     *0       5     9|0     0.0   80.0       0 10.7G 10.1G   0|1   2|0   59k   230k   61 rs0  PRI 10:41:13
mongodb-replica1:27017     47     6     10     *0       5     8|0     0.0   80.0       0 10.7G 10.1G   0|0   2|0   56k   230k   61 rs0  PRI 10:41:13
mongodb-replica2:27017     *0    *0     *0     *0       0     3|0     5.0   70.7       0 10.9G 10.0G   0|1   1|0  275b    16k   27 rs0  UNK 10:41:13
 
       localhost:27017     50     6     39     *0       7     6|0     0.1   80.0       0 10.7G 10.1G   0|0   2|4   89k   230k   61 rs0  PRI 10:41:14
mongodb-replica1:27017     54     6     35     *0       6     7|0     0.1   80.0       0 10.7G 10.1G   0|0   1|0   91k   230k   61 rs0  PRI 10:41:14
mongodb-replica2:27017     *0    *0     *0     *0       0     3|0     4.4   70.1       0 10.9G 10.0G   0|1   1|0  276b    16k   27 rs0  UNK 10:41:14

Comment by Maziyar Panahi [ 28/Apr/15 ]

Hi Ramon,

I am doing exactly what you said and will get back to you with the results.

Regards,
Maziyar

Comment by Ramon Fernandez Marina [ 28/Apr/15 ]

maziyar, I'm afraid we'll need more information to understand what's going. My first guess is that your primary uses too much memory to the point of thrashing and even hanging, and since the mongod process is run by root the OOM killer does not terminate this process before your interactive sessions become unresponsive. You mention 80GB of RAM, but how much swap do you have? Is your system allowed to degrade gracefully?

My first suggestion is that you run mongod as a regular user on all your replica members and then:

  • open a shell on your primary and run something that shows you memory consumption and/or load. Things like 'vmstat 5' or 'top' come to mind
  • re-try the initial sync. If the issue persists I'll ask you for primary and system logs

In addition, this could be the same issue as SERVER-17424, so I would also lower the size of the WiredTiger cache by adding --wiredTigerCacheSizeGB=10 to the command line used to launch mongod.

Cheers,
Ramón.

Comment by Maziyar Panahi [ 28/Apr/15 ]

I forgot to mention that I also tried to use scp to move all the files to the secondary to avoid stalling Primary but when I started my secondary I got this error:
WT_NOTFOUND item not found terminatingoq=WT_NOTFOUND

This is a frok.log beginning when I started my secondary:

2015-04-28T07:58:05.337+0200 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=39G,session_max=20000,eviction=(threads_max=4),statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
2015-04-28T07:58:05.430+0200 I CONTROL  [initandlisten] MongoDB starting : pid=1179 port=27017 dbpath=/data/ 64-bit host=mongodb-replica2
2015-04-28T07:58:05.430+0200 I CONTROL  [initandlisten] ** WARNING: You are running this process as the root user, which is not recommended.
2015-04-28T07:58:05.430+0200 I CONTROL  [initandlisten]
2015-04-28T07:58:05.430+0200 I CONTROL  [initandlisten] db version v3.0.2
2015-04-28T07:58:05.430+0200 I CONTROL  [initandlisten] git version: 6201872043ecbbc0a4cc169b5482dcf385fc464f
2015-04-28T07:58:05.430+0200 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.1f 6 Jan 2014
2015-04-28T07:58:05.430+0200 I CONTROL  [initandlisten] build info: Linux ip-10-229-1-2 3.13.0-24-generic #46-Ubuntu SMP Thu Apr 10 19:11:08 UTC 2014 x86_64 BOOST_LIB_VERSION=1_49
2015-04-28T07:58:05.430+0200 I CONTROL  [initandlisten] allocator: tcmalloc
2015-04-28T07:58:05.430+0200 I CONTROL  [initandlisten] options: { processManagement: { fork: true }, replication: { replSet: "rs0" }, storage: { dbPath: "/data/", engine: "wiredTiger" }, systemLog: { destination: "file", path: "/var/log/mongodb/fork.log" } }
2015-04-28T07:58:05.445+0200 I REPL     [initandlisten] Did not find local replica set configuration document at startup;  NoMatchingDocument Did not find replica set configuration document in local.system.replset
2015-04-28T07:58:05.458+0200 I NETWORK  [initandlisten] waiting for connections on port 27017
2015-04-28T07:58:05.613+0200 I NETWORK  [initandlisten] connection accepted from 10.0.0.4:40120 #1 (1 connection now open)
2015-04-28T07:58:05.647+0200 I NETWORK  [initandlisten] connection accepted from 10.0.0.6:58769 #2 (2 connections now open)
2015-04-28T07:58:05.689+0200 I REPL     [WriteReplSetConfig] Starting replication applier threads
2015-04-28T07:58:05.689+0200 I REPL     [rsSync] replSet warning did not receive a valid config yet, sleeping 5 seconds
2015-04-28T07:58:05.690+0200 I REPL     [ReplicationExecutor] New replica set config in use: { _id: "rs0", version: 4, members: [ { _id: 0, host: "mongodb-replica1:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 5.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 1, host: "mongodb-arbiter:30000", arbiterOnly: true, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 2, host: "mongodb-replica2:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatTimeoutSecs: 10, getLastErrorModes: {}, getLastErrorDefaults: { w: 1, wtimeout: 0 } } }
2015-04-28T07:58:05.690+0200 I REPL     [ReplicationExecutor] This node is mongodb-replica2:27017 in the config
2015-04-28T07:58:05.690+0200 I REPL     [ReplicationExecutor] transition to STARTUP2
2015-04-28T07:58:05.694+0200 I REPL     [ReplicationExecutor] Member mongodb-arbiter:30000 is now in state ARBITER

Thanks

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