[SERVER-31647] Benchmark performance against APFS Created: 19/Oct/17  Updated: 02/Apr/18  Resolved: 07/Mar/18

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

Type: Task Priority: Major - P3
Reporter: Rogerio Carrasqueira Assignee: Cristopher Stauffer
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
is related to WT-3724 Log an error if flushing with F_FULLS... Closed
Participants:

 Description   
Original Summary

MongoDB is so slow with write operations on OSX High Sierra

Original Description

Hello!

There is an issue that deserve some research on MongoDB running on OSX High Sierra. I was using Mongo DB 3.0.2 running in OSX Sierra and after the an updated required by Apple, where it installs the new OSX High Sierra, the write operations became so slow.

No configuration was changed, I'm opened an issue at stack overflow where I've put my config there, you can check it at https://stackoverflow.com/questions/46828828/mongodb-running-in-macos-high-sierra-is-with-write-operations-very-slow

This matter deserves some research because this is a new Operating System brought by Apple and I think there we have to observe the Mongo's behaviour running on it.

Some log information can be checked bellow:

2017-10-19T17:41:39.688-0200 I CONTROL  [initandlisten] MongoDB starting : pid=17344 port=27017 dbpath=/usr/local/var/mongodb 64-bit host=Macbook-Pro-Rogerio-Carrasqueira.local
2017-10-19T17:41:39.688-0200 I CONTROL  [initandlisten] db version v3.0.15
2017-10-19T17:41:39.688-0200 I CONTROL  [initandlisten] git version: b8ff507269c382bc100fc52f75f48d54cd42ec3b
2017-10-19T17:41:39.688-0200 I CONTROL  [initandlisten] build info: Darwin mci-osx1010-9.build.10gen.cc 14.0.0 Darwin Kernel Version 14.0.0: Fri Sep 19 00:26:44 PDT 2014; root:xnu-2782.1.97~2/RELEASE_X86_64 x86_64 BOOST_LIB_VERSION=1_49
2017-10-19T17:41:39.688-0200 I CONTROL  [initandlisten] allocator: system
2017-10-19T17:41:39.688-0200 I CONTROL  [initandlisten] options: { config: "/usr/local/etc/mongod.conf", net: { bindIp: "127.0.0.1" }, storage: { dbPath: "/usr/local/var/mongodb", engine: "wiredTiger" }, systemLog: { destination: "file", logAppend: true, path: "/usr/local/var/log/mongodb/mongo.log" } }
2017-10-19T17:41:39.689-0200 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=4G,session_max=20000,eviction=(threads_max=4),statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
2017-10-19T17:41:39.982-0200 I CONTROL  [initandlisten] ** WARNING: You are running this process as the root user, which is not recommended.
2017-10-19T17:41:39.982-0200 I CONTROL  [initandlisten] 
2017-10-19T17:41:39.982-0200 I CONTROL  [initandlisten] 
2017-10-19T17:41:39.982-0200 I CONTROL  [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000
2017-10-19T17:41:40.126-0200 I NETWORK  [initandlisten] waiting for connections on port 27017
2017-10-19T17:42:27.502-0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:53741 #1 (1 connection now open)
2017-10-19T17:42:38.335-0200 I INDEX    [conn1] build index on: mailerweb_test.contact properties: { v: 1, key: { customer_id: 1, opt_out: 1 }, name: "customer_id_1_opt_out_1", ns: "mailerweb_test.contact", background: true }
2017-10-19T17:42:38.341-0200 I INDEX    [conn1] build index done.  scanned 0 total records. 0 secs
2017-10-19T17:42:38.342-0200 I COMMAND  [conn1] command mailerweb_test.$cmd command: createIndexes { createIndexes: "contact", indexes: [ { background: true, name: "customer_id_1_opt_out_1", key: { customer_id: 1, opt_out: 1 }, dropDups: true } ] } keyUpdates:0 writeConflicts:0 numYields:0 reslen:113 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1, W: 2 } }, Collection: { acquireCount: { W: 1 } } } 215ms
2017-10-19T17:42:38.404-0200 I INDEX    [conn1] build index on: mailerweb_test.contact properties: { v: 1, key: { customer_id: 1, status: 1 }, name: "customer_id_1_status_1", ns: "mailerweb_test.contact", background: true }
2017-10-19T17:42:38.404-0200 I INDEX    [conn1] build index done.  scanned 0 total records. 0 secs
2017-10-19T17:42:38.468-0200 I INDEX    [conn1] build index on: mailerweb_test.contact properties: { v: 1, key: { customer_id: 1, campaigns.id: 1, last_updated: -1 }, name: "customer_id_1_campaigns.id_1_last_updated_-1", ns: "mailerweb_test.contact", background: true }
2017-10-19T17:42:38.468-0200 I INDEX    [conn1] build index done.  scanned 0 total records. 0 secs
2017-10-19T17:42:38.541-0200 I INDEX    [conn1] build index on: mailerweb_test.contact properties: { v: 1, key: { name: 1 }, name: "name_1", ns: "mailerweb_test.contact", background: true }
2017-10-19T17:42:38.541-0200 I INDEX    [conn1] build index done.  scanned 0 total records. 0 secs
2017-10-19T17:42:38.609-0200 I INDEX    [conn1] build index on: mailerweb_test.contact properties: { v: 1, key: { email: 1 }, name: "email_1", ns: "mailerweb_test.contact", background: true }
2017-10-19T17:42:38.610-0200 I INDEX    [conn1] build index done.  scanned 0 total records. 0 secs
2017-10-19T17:42:38.676-0200 I INDEX    [conn1] build index on: mailerweb_test.contact properties: { v: 1, key: { tag_list: 1 }, name: "tag_list_1", ns: "mailerweb_test.contact", background: true }
2017-10-19T17:42:38.677-0200 I INDEX    [conn1] build index done.  scanned 0 total records. 0 secs
2017-10-19T17:42:38.744-0200 I INDEX    [conn1] build index on: mailerweb_test.contact properties: { v: 1, key: { customer_id: 1 }, name: "customer_id_1", ns: "mailerweb_test.contact", background: true }
2017-10-19T17:42:38.745-0200 I INDEX    [conn1] build index done.  scanned 0 total records. 0 secs
2017-10-19T17:42:38.801-0200 I INDEX    [conn1] build index on: mailerweb_test.contact properties: { v: 1, key: { date_created: 1 }, name: "date_created_1", ns: "mailerweb_test.contact", background: true }
2017-10-19T17:42:38.802-0200 I INDEX    [conn1] build index done.  scanned 0 total records. 0 secs
2017-10-19T17:42:38.859-0200 I INDEX    [conn1] build index on: mailerweb_test.contact properties: { v: 1, key: { campaigns.id: 1 }, name: "campaigns.id_1", ns: "mailerweb_test.contact", background: true }
2017-10-19T17:42:38.859-0200 I INDEX    [conn1] build index done.  scanned 0 total records. 0 secs
2017-10-19T17:42:38.923-0200 I INDEX    [conn1] build index on: mailerweb_test.contact properties: { v: 1, unique: true, key: { customer_id: 1, email: 1 }, name: "customer_id_1_email_1", ns: "mailerweb_test.contact", background: true, sparse: false }
2017-10-19T17:42:38.924-0200 I INDEX    [conn1] build index done.  scanned 0 total records. 0 secs
2017-10-19T17:43:23.772-0200 I INDEX    [conn1] build index on: mailerweb_test.opt_out_list properties: { v: 1, key: { customer_id: 1 }, name: "customer_id_1", ns: "mailerweb_test.opt_out_list", background: true }
2017-10-19T17:43:23.773-0200 I INDEX    [conn1] build index done.  scanned 0 total records. 0 secs
2017-10-19T17:43:23.774-0200 I COMMAND  [conn1] command mailerweb_test.$cmd command: createIndexes { createIndexes: "opt_out_list", indexes: [ { background: true, name: "customer_id_1", key: { customer_id: 1 }, dropDups: true } ] } keyUpdates:0 writeConflicts:0 numYields:0 reslen:113 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1, W: 2 } }, Collection: { acquireCount: { W: 1 } } } 178ms
2017-10-19T17:43:23.836-0200 I INDEX    [conn1] build index on: mailerweb_test.opt_out_list properties: { v: 1, key: { email: 1 }, name: "email_1", ns: "mailerweb_test.opt_out_list", background: true }
2017-10-19T17:43:23.836-0200 I INDEX    [conn1] build index done.  scanned 0 total records. 0 secs
2017-10-19T17:43:23.900-0200 I INDEX    [conn1] build index on: mailerweb_test.opt_out_list properties: { v: 1, key: { reason: 1 }, name: "reason_1", ns: "mailerweb_test.opt_out_list", background: true }
2017-10-19T17:43:23.901-0200 I INDEX    [conn1] build index done.  scanned 0 total records. 0 secs
2017-10-19T17:43:23.962-0200 I INDEX    [conn1] build index on: mailerweb_test.opt_out_list properties: { v: 1, key: { date_created: 1 }, name: "date_created_1", ns: "mailerweb_test.opt_out_list", background: true }
2017-10-19T17:43:23.962-0200 I INDEX    [conn1] build index done.  scanned 0 total records. 0 secs
2017-10-19T17:43:24.027-0200 I INDEX    [conn1] build index on: mailerweb_test.opt_out_list properties: { v: 1, key: { customer_id: 1, email: 1 }, name: "customer_id_1_email_1", ns: "mailerweb_test.opt_out_list", background: true }
2017-10-19T17:43:24.027-0200 I INDEX    [conn1] build index done.  scanned 0 total records. 0 secs
2017-10-19T17:43:24.089-0200 I INDEX    [conn1] build index on: mailerweb_test.opt_out_list properties: { v: 1, key: { customer_id: 1, reason: 1 }, name: "customer_id_1_reason_1", ns: "mailerweb_test.opt_out_list", background: true }
2017-10-19T17:43:24.090-0200 I INDEX    [conn1] build index done.  scanned 0 total records. 0 secs
2017-10-19T17:43:24.154-0200 I INDEX    [conn1] build index on: mailerweb_test.opt_out_list properties: { v: 1, unique: true, key: { email: 1, customer_id: 1 }, name: "email_1_customer_id_1", ns: "mailerweb_test.opt_out_list", background: true, sparse: false }
2017-10-19T17:43:24.154-0200 I INDEX    [conn1] build index done.  scanned 0 total records. 0 secs
2017-10-19T17:43:24.161-0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:53877 #2 (2 connections now open)
2017-10-19T17:43:33.178-0200 I NETWORK  [conn2] end connection 127.0.0.1:53877 (1 connection now open)
2017-10-19T17:43:39.817-0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:54065 #3 (2 connections now open)
2017-10-19T17:43:48.830-0200 I NETWORK  [conn3] end connection 127.0.0.1:54065 (1 connection now open)
2017-10-19T17:43:49.267-0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:54130 #4 (2 connections now open)
2017-10-19T17:43:58.139-0200 I NETWORK  [conn4] end connection 127.0.0.1:54130 (1 connection now open)
2017-10-19T17:44:25.786-0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:54213 #5 (2 connections now open)
2017-10-19T17:44:34.573-0200 I NETWORK  [conn5] end connection 127.0.0.1:54213 (1 connection now open)
2017-10-19T17:44:45.638-0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:54247 #6 (2 connections now open)
2017-10-19T17:44:45.689-0200 I NETWORK  [conn6] end connection 127.0.0.1:54247 (1 connection now open)
2017-10-19T17:44:46.176-0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:54251 #7 (2 connections now open)
2017-10-19T17:44:46.176-0200 I NETWORK  [conn7] end connection 127.0.0.1:54251 (1 connection now open)
2017-10-19T17:44:46.180-0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:54252 #8 (2 connections now open)
2017-10-19T17:44:46.182-0200 I NETWORK  [conn8] end connection 127.0.0.1:54252 (1 connection now open)
2017-10-19T17:44:46.185-0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:54253 #9 (2 connections now open)
2017-10-19T17:44:46.187-0200 I NETWORK  [conn9] end connection 127.0.0.1:54253 (1 connection now open)
2017-10-19T17:44:46.195-0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:54254 #10 (2 connections now open)
2017-10-19T17:44:46.198-0200 I NETWORK  [conn10] end connection 127.0.0.1:54254 (1 connection now open)
2017-10-19T17:44:46.203-0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:54255 #11 (2 connections now open)
2017-10-19T17:44:46.205-0200 I NETWORK  [conn11] end connection 127.0.0.1:54255 (1 connection now open)
2017-10-19T17:44:46.209-0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:54256 #12 (2 connections now open)
2017-10-19T17:44:46.210-0200 I NETWORK  [conn12] end connection 127.0.0.1:54256 (1 connection now open)
2017-10-19T17:44:46.215-0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:54257 #13 (2 connections now open)
2017-10-19T17:44:46.221-0200 I NETWORK  [conn13] end connection 127.0.0.1:54257 (1 connection now open)
2017-10-19T17:44:46.225-0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:54258 #14 (2 connections now open)
2017-10-19T17:44:46.229-0200 I NETWORK  [conn14] end connection 127.0.0.1:54258 (1 connection now open)
2017-10-19T17:44:47.474-0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:54268 #15 (2 connections now open)
2017-10-19T17:44:47.662-0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:54270 #16 (3 connections now open)
2017-10-19T17:44:56.508-0200 I NETWORK  [conn16] end connection 127.0.0.1:54270 (2 connections now open)



 Comments   
Comment by Cristopher Stauffer [ 07/Mar/18 ]

We will follow up on platform support and performance implications on https://jira.mongodb.org/browse/SERVER-31647.

Comment by Eric Milkie [ 01/Mar/18 ]

I linked in WT-3724 to this ticket, which involves some strange errors we received when we first tried APFS; it's something to be aware of while testing.

Comment by Cristopher Stauffer [ 19/Jan/18 ]

rogerio.carrasqueira, our own internal investigation appeared to show this experience could be limited to a period of time after the upgrade when re-indexing is going on - but then resolve itself. Are you or skripnik_ma still seeing this degradation?

Comment by Kelsey Schubert [ 02/Jan/18 ]

Hi all,

Thanks for reporting this issue. I'm repurposing this ticket to track the work necessary to properly diagnosis and improve this performance issue.

As you know, MacOS is not recommended for use in production, and MongoDB does not yet support APFS.

Please note that immediately after upgrading to High Sierra there may be performance degradation as the disk is heavily utilized transitioning the file system. In these cases, we would expect performance to improve after this system operation completes.

Kind regards,
Kelsey

Comment by Maxim Skripnik [ 07/Dec/17 ]

Hello guys,

Thanks for your attention to this problem. This is very irritating issue.
Can we except this to be resolved till the end of december?

All bests,
Maxim

Comment by Rogerio Carrasqueira [ 19/Oct/17 ]

Kelsey,

Thanks for your quickly response. I've tried with 3.0.15, 3.2 and the last one 3.4.9 and all versions presented the same problem. I can assure to you that before the updating, the mongodb was running very well, because this is my development environment. I use mongodb with python/django and the unit tests are running very very slow.

Best Regards

Rogerio

Comment by Kelsey Schubert [ 19/Oct/17 ]

Hi rogerio.carrasqueira,

Thank you reporting this issue. High Sierra introduces the Apple File System, it is possible that this change is related to the issue you are observing. Would you please provide diagnostic.data after running with MongoDB 3.4.9 from macOS 10.12 and 10.13? This will help us better understand what is going on here.

Finally, please note that we do not recommend macOS when running MongoDB in production.

Kind regards,
Kelsey

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