Bug 1021726 - mongodb preallocates journal files adding over 30 seconds to install time
mongodb preallocates journal files adding over 30 seconds to install time
Status: CLOSED CURRENTRELEASE
Product: OpenShift Online
Classification: Red Hat
Component: Containers (Show other bugs)
2.x
Unspecified Unspecified
medium Severity medium
: ---
: ---
Assigned To: mfisher
libra bugs
:
Depends On:
Blocks: 1128010
  Show dependency treegraph
 
Reported: 2013-10-21 18:45 EDT by Rob Millner
Modified: 2015-05-14 19:31 EDT (History)
3 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
: 1128010 (view as bug list)
Environment:
Last Closed: 2014-01-29 19:49:23 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Rob Millner 2013-10-21 18:45:08 EDT
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.
Comment 1 Rob Millner 2013-10-22 22:39:54 EDT
Pre-creating the journal causes the cartridge install time to drop from around 60 seconds to around 15.
Comment 2 Rob Millner 2013-10-22 23:08:24 EDT
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.
Comment 3 Rob Millner 2013-10-23 13:10:14 EDT
Pull request:
https://github.com/openshift/origin-server/pull/3968
Comment 4 openshift-github-bot 2013-10-23 14:14:34 EDT
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.
Comment 5 Meng Bo 2013-10-24 05:23:35 EDT
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@redhat.com -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...
Comment 6 Rob Millner 2013-10-24 13:28:14 EDT
If you are seeing those log entries then my solution isn't working.  Investigating.
Comment 7 Rob Millner 2013-10-24 14:07:47 EDT
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.
Comment 8 Rob Millner 2013-10-24 14:43:26 EDT
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!
Comment 9 Meng Bo 2013-10-24 22:44:47 EDT
Checked on devenv_3942,

# time rhc cartridge-add mongodb-2 -a perl1 -lbmeng@redhat.com -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.

Note You need to log in before you can comment on or make changes to this bug.