Description of problem: Mongodb runs a test to see if it should preallocate its journal files and then preallocates them. This adds over 30 seconds to install time. Version-Release number of selected component (if applicable): How reproducible: Mostly. You can get lucky and have it be faster on EC2. Steps to Reproduce: 1. Create an app 2. time rhc cartridge-add mongodb-2.2 Actual results: time > 30 seconds Expected results: time <= 30 seconds Additional info: Mon Oct 21 18:04:22.440 [initandlisten] preallocateIsFaster check took 4.107 secs Mon Oct 21 18:04:22.440 [initandlisten] preallocating a journal file /var/lib/openshift/5265a4c9ea8f50e54d000145/mongodb/data/journal/prealloc.0 Mon Oct 21 18:04:31.622 [initandlisten] preallocating a journal file /var/lib/openshift/5265a4c9ea8f50e54d000145/mongodb/data/journal/prealloc.1 Mon Oct 21 18:04:41.171 [initandlisten] preallocating a journal file /var/lib/openshift/5265a4c9ea8f50e54d000145/mongodb/data/journal/prealloc.2 Mon Oct 21 18:04:50.576 [FileAllocator] allocating new datafile /var/lib/openshift/5265a4c9ea8f50e54d000145/mongodb/data/local.ns, filling with zeroes... Unpacking the journal from a tar file (eg: from the install hook) seems to take less than 5 seconds on my devenv.
Pre-creating the journal causes the cartridge install time to drop from around 60 seconds to around 15.
Hmmm, I'm having trouble validating the original numbers. Creation seems fast now even without the journal pre-packaged. 20 seconds instead of almost 60. Without the pre-packaged journal: Tue Oct 22 23:00:49.941 [initandlisten] preallocateIsFaster=true 3.16 Tue Oct 22 23:00:49.942 [initandlisten] preallocating a journal file /var/lib/openshift/52673b43ea8f50855a000001/mongodb/data/journal/prealloc.0 Tue Oct 22 23:00:54.127 [initandlisten] preallocating a journal file /var/lib/openshift/52673b43ea8f50855a000001/mongodb/data/journal/prealloc.1 Tue Oct 22 23:00:58.573 [initandlisten] preallocating a journal file /var/lib/openshift/52673b43ea8f50855a000001/mongodb/data/journal/prealloc.2 Tue Oct 22 23:01:03.197 [FileAllocator] allocating new datafile /var/lib/openshift/52673b43ea8f50855a000001/mongodb/data/local.ns, filling with zeroes... I suspect that the write pattern for creating the journal files (ex: lots of fsync calls) has high delays when EC2 is having a bad day with storage and today happens to be a good day. So, on a good day it only saves 5 seconds and on a bad day it saves 25.
Pull request: https://github.com/openshift/origin-server/pull/3968
Commit pushed to master at https://github.com/openshift/origin-server https://github.com/openshift/origin-server/commit/bd0dd1f6046ec2f6b33577e3ed0e3861b17635f4 Bug 1021726 - Create the mongo journal ahead of time and copy it into the gear for speed.
Checked on devenv_3939, the expend time for adding mongodb is reduced to about 25s. # time rhc cartridge-add mongodb-2.2 -a php1 -l bmeng -pxx -k real 0m25.087s user 0m0.795s sys 0m0.424s From the mongo log, the journal file are allocated faster. Thu Oct 24 05:20:11.508 [initandlisten] preallocateIsFaster=true 5.56 Thu Oct 24 05:20:11.509 [initandlisten] preallocating a journal file /var/lib/openshift/5268e5fab07b10741700002e/mongodb/data/journal/prealloc.0 Thu Oct 24 05:20:16.793 [initandlisten] preallocating a journal file /var/lib/openshift/5268e5fab07b10741700002e/mongodb/data/journal/prealloc.1 Thu Oct 24 05:20:22.542 [initandlisten] preallocating a journal file /var/lib/openshift/5268e5fab07b10741700002e/mongodb/data/journal/prealloc.2 Thu Oct 24 05:20:27.940 [FileAllocator] allocating new datafile /var/lib/openshift/5268e5fab07b10741700002e/mongodb/data/local.ns, filling with zeroes...
If you are seeing those log entries then my solution isn't working. Investigating.
Ok, it works on my devenv: $ time rhc cartridge-add mongodb-2.2 -a rmtest ... real 0m15.484s user 0m0.646s sys 0m0.049s The following returns no output. $ rhc ssh rmtest cat mongodb/log/mongodb.log |grep 'preallocating a journal file' I'll see what's happening with devenv_3939.
It works on devenv_3941: $ time rhc cartridge-add mongodb-2.2 -a rmtest Adding mongodb-2.2 to application 'rmtest' ... done ... real 0m10.483s user 0m0.669s sys 0m0.047s # No output from the following command. $ rhc ssh rmtest cat mongodb/log/mongodb.log |grep 'preallocating a journal file' Putting this back on Q/A to re-validate. Thanks!
Checked on devenv_3942, # time rhc cartridge-add mongodb-2 -a perl1 -lbmeng -pxx -k Using mongodb-2.2 (MongoDB 2.2) for 'mongodb-2' ... real 0m25.482s user 0m0.758s sys 0m0.428s [root@ip-10-73-152-118 mongodb]# cat log/mongodb.log |grep prealloc Thu Oct 24 22:39:32.842 [initandlisten] options: { auth: true, bind_ip: "127.1.244.130", command: [ "run" ], config: "/var/lib/openshift/5269d951804377ea02000030/mongodb//conf/mongodb.conf", dbpath: "/var/lib/openshift/5269d951804377ea02000030/mongodb/data/", fork: "true", logpath: "/var/lib/openshift/5269d951804377ea02000030/mongodb/log/mongodb.log", nohttpinterface: "true", noprealloc: "true", pidfilepath: "/var/lib/openshift/5269d951804377ea02000030/mongodb/pid/mongodb.pid", quiet: "true", smallfiles: "true" } [root@ip-10-73-152-118 mongodb]# cat log/mongodb.log |grep preallocating [root@ip-10-73-152-118 mongodb]# Move bug to verified.