[SERVER-38308] WiredTiger Initialize step takes lot of time Created: 29/Nov/18  Updated: 29/May/19  Resolved: 29/May/19

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

Type: Question Priority: Major - P3
Reporter: Ponraj Assignee: Eric Sedor
Resolution: Incomplete Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Zip Archive Node1.diagnostic.data.zip     Text File Node1.iostat.log     Zip Archive Node2.diagnostic.data.zip     Text File Node2.iostat.log     Zip Archive Node3.diagnostic.data.zip     Text File Node3.iostat.log     Text File WiredTiger_Initialize_issue.log     File diagnostic.tar.gz     Text File iostat.log     Text File mongodb.log    
Participants:

 Description   

Hi,

 

We are using MongoDB 3.4 with WiredTiger Storage Engine and as you can see in the logs the startup of Mongodb to open its port for connections takes lot of time (~16 Mins).

Does this usually take this time?

If yes, is there a way to optimize this?



 Comments   
Comment by Eric Sedor [ 29/May/19 ]

Hello,

We haven't heard from you in some time and unfortunately have not been able to determine a cause given the information available. So, we're going to close this ticket.

However, if you are able to collect more information we would like to continue to look. To do so, we'd like you to increase the verbosity of MongoDB's logging. When you restart the secondary, please do so with the -vv option (two vs for "log level 2"). Wait until the node enters the SECONDARY state, then provide all 3 of:

  • diagnostic data
  • iostat script output
  • mongod logs.

Given this information we can reopen the investigation.

Thanks again,
Eric

Comment by Eric Sedor [ 19/Apr/19 ]

Hi aishwary31,

I am very sorry for the delay here. We know you have had this issue for some time and we are still trying to determine if a bug could be responsible. We continue to appreciate your patience.

Unfortunately, we still need more information. We need a complete view of the whole time span of an incident, which will include all 3 of:

  • diagnostic data
  • iostat script output
  • mongod logs.

All of these data sources should cover a period of time from before the restart of the node and until the node enters the SECONDARY state.

Especially important this time will be to increase the verbosity of MongoDB's logging for this incident. When you restart the secondary, please do so with the -vv option (two vs for "log level 2").

Does this make sense?

Thank you in advance,
Eric

Comment by Aishwary Joshi [ 02/Apr/19 ]

eric.sedor From the server logs, for the time 2019-03-26T10:39:37 UTC I couldn't find the logs about the restart of mongod server, however I can see that the server was restarted at 2019-03-26T10:50:53, anyways for your reference i am attaching the server logs at time around 2019-03-26T10:39:37 }}and {{2019-03-26T10:50:53

2019-03-26T10:39:42.19406Z - mongod-server[rs2] 2019-03-26T10:39:39.905+0000 I -        [conn10471] end connection 10.0.73.0:40526 (199 connections now open)
2019-03-26T10:39:42.194065Z - mongod-server[rs2] 2019-03-26T10:39:39.905+0000 I -        [conn10445] end connection 10.0.73.0:35946 (199 connections now open)

2019-03-26T10:50:53.31079Z - mongod-server[rs2] 2019-03-26T10:50:52.837+0000 I CONTROL  [main] ***** SERVER RESTARTED *****
2019-03-26T10:50:53.310794Z - mongod-server[rs2] 2019-03-26T10:50:52.857+0000 I CONTROL  [initandlisten] MongoDB starting : pid=9101 port=27017 dbpath=/var/vcap/store/mongodb/data 64-bit host=06f17252-021b-406e-93cd-4292185108f5
2019-03-26T10:50:53.310803Z - mongod-server[rs2] 2019-03-26T10:50:52.857+0000 I CONTROL  [initandlisten] db version v3.4.19
2019-03-26T10:50:53.310804Z - mongod-server[rs2] 2019-03-26T10:50:52.857+0000 I CONTROL  [initandlisten] git version: a2d97db8fe449d15eb8e275bbf318491781472bf
2019-03-26T10:50:53.310812Z - mongod-server[rs2] 2019-03-26T10:50:52.857+0000 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.2g  1 Mar 2016
2019-03-26T10:50:53.310813Z - mongod-server[rs2] 2019-03-26T10:50:52.857+0000 I CONTROL  [initandlisten] allocator: tcmalloc
2019-03-26T10:50:53.310821Z - mongod-server[rs2] 2019-03-26T10:50:52.857+0000 I CONTROL  [initandlisten] modules: none
2019-03-26T10:50:53.310823Z - mongod-server[rs2] 2019-03-26T10:50:52.857+0000 I CONTROL  [initandlisten] build environment:
2019-03-26T10:50:53.310837Z - mongod-server[rs2] 2019-03-26T10:50:52.857+0000 I CONTROL  [initandlisten]     distmod: ubuntu1604
2019-03-26T10:50:53.310838Z - mongod-server[rs2] 2019-03-26T10:50:52.857+0000 I CONTROL  [initandlisten]     distarch: x86_64
2019-03-26T10:50:53.310848Z - mongod-server[rs2] 2019-03-26T10:50:52.857+0000 I CONTROL  [initandlisten]     target_arch: x86_64
2019-03-26T10:50:53.31085Z - mongod-server[rs2] 2019-03-26T10:50:52.857+0000 I CONTROL  [initandlisten] options: { config: "/var/vcap/jobs/mongodb3.4/config/mongodb3.4.conf", net: { port: 27017, unixDomainSocket: { filePermissions: 600, pathPrefix: "/var/vcap/sys/tmp/mongodb3.4/mongod" } }, processManagement: { fork: true, pidFilePath: "/var/vcap/sys/run/mongodb3.4/mongod/mongodb3.4.pid" }, replication: { replSetName: "bf4474c8bc1cd841b8c36ccde9e77c13" }, security: { authorization: "enabled", clusterAuthMode: "keyFile", javascriptEnabled: false, keyFile: "/var/vcap/jobs/mongodb3.4/config/keyfile" }, storage: { dbPath: "/var/vcap/store/mongodb/data", ...

And for the time 2019-03-26T13:23:01 UTC, you are right the node exited from STARTUP2, here is the log

2019-03-26T13:25:20.531332Z - mongod-server[rs2] 2019-03-26T13:25:19.894+0000 I REPL     [replExecDBWorker-0] transition to STARTUP2
2019-03-26T13:25:20.531334Z - mongod-server[rs2] 2019-03-26T13:25:19.894+0000 I REPL     [replExecDBWorker-0] Starting replication storage threads
2019-03-26T13:25:20.531342Z - mongod-server[rs2] 2019-03-26T13:25:19.897+0000 I REPL     [replExecDBWorker-0] Starting replication fetcher thread
2019-03-26T13:25:20.531343Z - mongod-server[rs2] 2019-03-26T13:25:19.897+0000 I REPL     [replExecDBWorker-0] Starting replication applier thread
2019-03-26T13:25:20.531351Z - mongod-server[rs2] 2019-03-26T13:25:19.897+0000 I REPL     [replExecDBWorker-0] Starting replication reporter thread
2019-03-26T13:25:20.531352Z - mongod-server[rs2] 2019-03-26T13:25:19.897+0000 I REPL     [rsSync] transition to RECOVERING
2019-03-26T13:25:20.531359Z - mongod-server[rs2] 2019-03-26T13:25:19.900+0000 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 10.11.51.1:27017
2019-03-26T13:25:20.531361Z - mongod-server[rs2] 2019-03-26T13:25:19.900+0000 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 10.11.51.2:27017

Is this information sufficient for you ?

Also particulary for this replica set and the kind of workload it has I just wanted to let you know we have seen high system memory usage for wiredTiger cache(more than what is default configured wiredTiger cache)

Comment by Eric Sedor [ 01/Apr/19 ]

aishwary31 do we understand correctly from this diagnostic data that Node1 was restarted at 2019-03-26T10:39:37 UTC and only exited the STARTUP2 state at 2019-03-26T13:23:01 UTC? Can you provide the mongod logs at that time?

Comment by Eric Sedor [ 28/Mar/19 ]

Thank you aishwary31 for the complete set and the additional measurements; we are reviewing.

Comment by Aishwary Joshi [ 27/Mar/19 ]

Regarding output

 find /$dbpath/ | wc -l 


On Node1 above command returned 50 number of files
On Node2, it returned 56
On Node3, it returnee 55

Comment by Aishwary Joshi [ 27/Mar/19 ]

eric.sedor : Please ignore the previous diagnostic.data and iostat logs that were uploaded before. As asked by you for uploading diagnostic.data and iostat logs for all nodes, please note that the earlier diagnostic.data was for different mongodb cluster
Following files have been uploaded

  • Node1.diagnostic.data.zip
  • Node1.iostat.log
  • Node2.diagnostic.data.zip
  • Node2.iostat.log
  • Node3diagnostic.data.zip
  • Node3.iostat.log
    We are using 3 node replicaset mongodb cluster
Comment by Eric Sedor [ 20/Mar/19 ]

Hello, I want to see if you saw my most recent request. In addition to the above, can you also let us know how many files are in your dbpath directory (such as via find /$dbpath/ | wc -l)?

Comment by Eric Sedor [ 08/Mar/19 ]

aishwary31, ologn we are sorry if we have introduced any confusion.

We are looking for log files, diagnostic.data, and iostat output for all nodes during a period of time during which starting one node takes 16 minutes, to investigate the possibility of a bug. But high startup times are expected on slow disks.

Unfortunately, we are not able to piece anything together from the current files:

  • WiredTiger_Initialize_issue.log seems to cover 2018-11-28T22:28:31.120 to 2018-11-28T22:44:08.335 UTC during which it appears the node took some time to enter the STARTUP2 phase.
  • mongodb.log seems to cover 019-02-09T22:45:02.111 to 2019-02-10T02:45:01.629 UTC but the node does not appear to have been restarted at all during that time. The node appears to be in the RECOVERING state and is unable to find a node to sync from because it has already become too stale.
  • diagnostic.data the time period of mongodb.log but also do not include any indication of a restart.
  • iostat.log overlaps the time period of mongodb.log but simply shows high disk utilization

Are you able to provide a consistent view of a slow startup time across these data sources?

Comment by Aishwary Joshi [ 08/Mar/19 ]

@Eric We have also seen wiredTiger cache using more memory than the default configured cache size.

Comment by Aishwary Joshi [ 06/Mar/19 ]

The logs that are provided belong to PRIMARY node which transitioned to RECOVERING node. If you want I can provide dignostic.data for other node.

Comment by Eric Sedor [ 20/Feb/19 ]

We appreciate your patience ologn. So far, the diagnostic data you provided indicates a heavily utilized vdb volume. Are you able to provide the same diagnostic data for the primary member of the replica set? We'd like to compare the two sets.

Comment by Ponraj [ 11/Feb/19 ]

Hi eric.sedor , ramon.fernandez ,

Can you please re-open the ticket? Because I am not able to. We have come back with the log files that you asked.

Comment by Aishwary Joshi [ 11/Feb/19 ]

diagnostic.tar.gziostat.logmongodb.log

 
 rs.printReplicationInfo()
 configured oplog size: 1994.330810546875MB
 log length start to end: 842secs (0.23hrs)
 oplog first event time: Sat Feb 09 2019 01:03:13 GMT+0000 (UTC)
 oplog last event time: Sat Feb 09 2019 01:17:15 GMT+0000 (UTC)
 now: Mon Feb 11 2019 06:31:26 GMT+0000 (UTC)
 XXXXXXXX:RECOVERING> use local
switched to db local
XXXXXXXX:RECOVERING> db.oplog.rs.stats().size
2950741224
XXXXXXXX:RECOVERING> db.oplog.rs.stats().storageSize
6681374720
XXXXXXXX:RECOVERING> db.oplog.rs.stats().maxSize
NumberLong(2091207424)
  

 

Comment by Eric Sedor [ 15/Jan/19 ]

Hello,

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 the above information and we will reopen the ticket.

Gratefully,
Eric

Comment by Ramon Fernandez Marina [ 19/Dec/18 ]

ologn, we haven't heard back from you for some time. If this is still an issue for you, will you please provide the information requested above by Eric so we can continue to investigate? We're trying to determine where the startup time is going and we suspect I/O.

Thanks,
Ramón.

Comment by Eric Sedor [ 07/Dec/18 ]

Ponraj, for us to help investigate this issue, please:

1) Execute the following shell script prior to starting the server:

delay=1
iostat -k -t -x ${delay:?} >iostat.log &

2) Start the server with additional log verbosity (add the -vvvvv option described here)

3) After the server starts, record the results of the following commands in the shell:

> rs.printReplicationInfo()

and

> use local
> db.oplog.rs.stats().size
> db.oplog.rs.stats().storageSize
> db.oplog.rs.stats().maxSize

4) archive (tar or zip) the $dbpath/diagnostic.data directory

Then, attach the mongod log, iostat.log, command results, and diagnostic data archive to this ticket.

Comment by Ponraj [ 06/Dec/18 ]

Hi Eric Sedor,

As you can see in the log, it lists the size of the oplog.

2018-11-28T22:28:34.098+0000 I STORAGE [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.rs
2018-11-28T22:28:34.098+0000 I STORAGE [initandlisten] The size storer reports that the oplog contains 1205 records totaling to 5886951874 bytes

Besides, I cannot run these commands as mongod has not opened its connection in the shell. Thats the actual problem we have.

Comment by Eric Sedor [ 05/Dec/18 ]

ologn, can you let us know about any system bottlenecks during that time? Is the disk or CPU saturated for example?

We'd also like to better understand the size of the oplog. From the MongoDB shell, can you provide the outputs of:

> rs.printReplicationInfo()

and

> use local
> db.oplog.rs.stats().size
> db.oplog.rs.stats().storageSize
> db.oplog.rs.stats().maxSize

Comment by Ponraj [ 05/Dec/18 ]

Now this happens frequently on AZURE as well. Can you provide an update on this? Thanks.

Comment by Ponraj [ 01/Dec/18 ]

Hi Ramon Fernandez,

This happens on GCP. What more details do you need?

Comment by Ramon Fernandez Marina [ 30/Nov/18 ]

ologn, can you provide more details about your deployment? This looks very similar to the issue described in SERVER-27036, which is related to AWS volumes.

Generated at Thu Feb 08 04:48:35 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.