[SERVER-35558] Drop in performance for the insert command after restarting the MongoDB database Created: 12/Jun/18  Updated: 27/Oct/23  Resolved: 17/Jun/18

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

Type: Question Priority: Major - P3
Reporter: Nikolay Malitsky Assignee: Dmitry Agranat
Resolution: Works as Designed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: PNG File io_SERVER_35558.png    
Issue Links:
Duplicate
Participants:

 Description   

Good afternoon,

Our team has experienced a substantial drop in performance for the bulk insert command (when inserting 10,000 documents) after restarting the MongoDB database (3.2.20). Based on a brief analysis, there seem to be two issues: (1) The particular collection uses random scattered keys (2) The index tree is only partially loaded in the CPU memory.

The first issue can be easily fixed by prepending timestamp to the scattered keys. For resolving the second issue, we are looking for feedback from MongoDB experts. Specifically, there are three questions:

  1. Is it “a bug or feature” of the MongoDB database to keep only a part of the index tree in CPU memory? We are using a multi-core server with around 200 GB memory. According to the collection statistics, however, the ‘datum_id_1’ cache contains only 1,912,845,502.0 bytes while the total index size is 9,059,713,024.0 as demonstrated by the following script:

https://github.com/malitsky/nsls2/blob/master/mongohxn/tests/insert.6.10.18.ipynb

  1. Is there any mechanism to push and keep an index tree in the CPU memory?
  2. Are the data and index caches managed by one or two different LRU procedures?

Thank you in advance,

Nikolay

This question has been submitted to http://groups.google.com/group/mongodb-user

and http://stackoverflow.com/questions/tagged/mongodb.



 Comments   
Comment by Dmitry Agranat [ 17/Jun/18 ]

Hi nmalitsky,

Thanks for your report and questions. As we did not find any evidence that the reported issue is related to MongoDB, I will go ahead and close this ticket.

Please note that SERVER project is for reporting bugs or feature suggestions for the MongoDB server. For MongoDB-related support discussion please post on the mongodb-user group
or Stack Overflow with the mongodb tag.
A question like this involving more discussion would be best posted on the mongodb-user group.

If this issue is reproducible on a storage system as mentioned here, feel free to reopen this ticket.

Thanks,
Dima

Comment by Nikolay Malitsky [ 15/Jun/18 ]

Hi Dima,

Our IT team is analyzing the file system. I expect that that slow
throughput rate is determined by the seek time of spinning disks
(0.004-0.009 s) dominating reading small index pages (16,384 bytes/100 MB/s
= 0.00016). I will let you know once our IT team has the disk
specification.

Most importantly, your analysis confirmed my previous concern associated
with partial index allocation. Could you answer the following questions?

1. Is there any mechanism to push and keep an index tree in the CPU memory?

2. Are the data and index caches managed by one or two different LRU
procedures?

3. Is prepending the scattered random keys with timestamp (line 7-8 in
GitHub script) the correct/best solution for achieving the best insert
performance for our case (partially loaded index tree and slow i/o access).
This solution is derived from the MongoDB brief notes:

https://docs.mongodb.com/manual/tutorial/ensure-indexes-fit-ram/#indexes-that-hold-only-recent-values-in-ram

4. What btree and cache information is provided in ‘wiredTiger’ entry
(towards the end) of the collStats command (line 10 in GitHub script below)
in addition to ‘indexDetails’ (towards the beginning of this command):

https://github.com/malitsky/nsls2/blob/master/mongohxn/tests/insert.gpu-001.6.13.18.ipynb

These questions are important for updating our MongoDB environment and we
thank you in advance for taking the time to answer our questions.

Best regards,

Nikolay

On Thu, Jun 14, 2018 at 2:39 PM, Dmitry Agranat (JIRA) <jira@mongodb.org>

Comment by Dmitry Agranat [ 14/Jun/18 ]

Hi nmalitsky,

If you can reproduce this issue on the system which has more than just a few MB/s read & write throughput capacity, we'll be able to look into this. For a reference, these are our disk and file-system recommendations.

A rate of ~ 2.8 MB/s looks very slow indeed. Would this rate include some
MongoDB overhead?

I was not able to find any indication that the reads from disk were related to MongoDB.

If this issue is reproducible on a storage system according to our recommendations (and ideally on the latest MongoDB version), please provide the following information:

  • compressed mongod log and archived content of $dbpath/diagnostic.data
  • file-system type (EXT4 or XFS) and disk throughput specifications
  • any supporting profiling information like you did in your previous comments

Thanks,
Dima

Comment by Nikolay Malitsky [ 14/Jun/18 ]

Hi Dima,

Thank you for the analysis.

A rate of ~ 2.8 MB/s looks very slow indeed. Would this rate include some
MongoDB overhead?

Here is the output for the “df –l” command:
Filesystem 1K-blocks Used Available Use% Mounted on

/dev/sda7 913578428 355946304 511201916 42% /
udev 10240 0 10240 0% /dev
tmpfs 52914392 9832 52904560 1% /run
tmpfs 132285972 0 132285972 0% /dev/shm
tmpfs 5120 0 5120 0% /run/lock
tmpfs 132285972 0 132285972 0% /sys/fs/cgroup
/dev/sda6 230563988 4562220 214266680 3% /var
/dev/sda1 235021 48886 174001 22% /boot
The MongoDB data files are located in a local directory.

From our side, profiling clearly identified a performance issue (CPU vs
Wall Time) located in

the __page_read method that reads a page from the file:

https://github.com/mongodb/mongo/blob/v3.2/src/third_party/wiredtiger/src/btree/bt_read.c
Regarding MongoDB 3.6.5 version. At this time, we are evaluating the
MongoDB sharded cluster using the 3.6 version.
The sharded server is connected with the production system, but we can
install the 3.6.5 version on
the research & developer server and repeat the same test.

Regards,
Nikolay

On Thu, Jun 14, 2018 at 5:46 AM, Dmitry Agranat (JIRA) <jira@mongodb.org>

Comment by Dmitry Agranat [ 14/Jun/18 ]

Hi nmalitsky,

Thank you for uploading the requested information. It was very useful.

I suspect the issue is related to the i/o subsystem.

  • At A, around 14:49:30 (UTC), we are starting to read from disk with a rate of ~2.8MB/s which results in 100% disk utilization.
  • There is a stall between B and C.
  • Right before the stall at B, there is a checkpoint trying to write about 8MB/s.
  • Bulk insert runs between A and D.
  • At E, when there are no read operations, 10K insert operations is observed
  • There is another short stall at F

To proceed with this investigation, could you please provide more details about the sda disk and what filesystem type is used? Also, is there any specific reason you are not running with latest MongoDB 3.6.5 version?

Thanks,
Dima

Comment by Nikolay Malitsky [ 13/Jun/18 ]

Hi Dima,

Thank you for your prompt response.

At this time, our production system is running a fresh database (with a few
documents of the same collection)
and we are evaluating this issue on the research & development multi-core
server.

The performance issue is reproducible. To address your request I ran the
following two steps:

1. Start the MongoDB database (at 10:33 am EDT, June 13, 2018). This
database was compiled from the github source code (git clone -b v3.2
https://github.com/mongodb/mongo.git)

malitsky@gpu-001:~/mongo/bench.v3.2$
/home/malitsky/mongo/bench.v3.2/opt/mongodb/bin/mongod --dbpath
/home/malitsky/mongo/bench.v3.2/data/mongodb.5.27.18 --logpath
/home/malitsky/mongo/bench.v3.2/var/log/mongodb/mongodb.log --port 27018
--bind_ip 127.0.0.1,gpu-001

2018-06-13T10:32:51.849-0400 I CONTROL [main] log file
"/home/malitsky/mongo/bench.v3.2/var/log/mongodb/mongodb.log" exists; moved
to
"/home/malitsky/mongo/bench.v3.2/var/log/mongodb/mongodb.log.2018-06-13T14-32-51".

2. Run the python script for inserting 10,000 documents (at 10:49 am EDT,
June 13, 2018):

https://github.com/malitsky/nsls2/blob/master/mongohxn/tests/insert.gpu-001.6.13.18.ipynb

The corresponding diagnostics.data.tar.gz and log.tar.gz files are
uploaded to your server.

Based on preliminary profiling, the issue (CPU vs Wall time) is
encapsulated in the __wt_row_search method:

https://github.com/mongodb/mongo/blob/v3.2/src/third_party/wiredtiger/src/btree/row_srch.c

Thanks again,

Nikolay

On Tue, Jun 12, 2018 at 4:39 PM, Dmitry Agranat (JIRA) <jira@mongodb.org>

Comment by Dmitry Agranat [ 12/Jun/18 ]

Hi nmalitsky,

So we can investigate it can you please upload to this secure private portal, for the affected instance:

  • archived content of $dbpath/diagnostic.data
  • complete mongod log files ideally covering time from upgrade until the present

Also can you please give me a timeline of the events that you describe as accurately as you can (including timezone). This will ensure that we're looking at the right time period in the data.

Thanks,
Dima

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