Bug 1128010 - mongodb preallocates journal files adding over 30 seconds to install time
Summary: mongodb preallocates journal files adding over 30 seconds to install time
Keywords:
Status: CLOSED EOL
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: ImageStreams
Version: 2.2.0
Hardware: Unspecified
OS: Unspecified
medium
medium
Target Milestone: ---
: ---
Assignee: Miciah Dashiel Butler Masters
QA Contact: libra bugs
URL:
Whiteboard:
Depends On: 1021726
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-08-08 06:08 UTC by Yanping Zhang
Modified: 2017-01-13 22:19 UTC (History)
14 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of: 1021726
Environment:
Last Closed: 2017-01-13 22:19:07 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)

Description Yanping Zhang 2014-08-08 06:08:32 UTC
+++ This bug was initially created as a clone of Bug #1021726 +++

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.

--- Additional comment from Rob Millner on 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.

--- Additional comment from Rob Millner on 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.

--- Additional comment from Rob Millner on 2013-10-23 13:10:14 EDT ---

Pull request:
https://github.com/openshift/origin-server/pull/3968

--- Additional comment from openshift-github-bot on 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.

--- Additional comment from Meng Bo on 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 -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...

--- Additional comment from Rob Millner on 2013-10-24 13:28:14 EDT ---

If you are seeing those log entries then my solution isn't working.  Investigating.

--- Additional comment from Rob Millner on 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.

--- Additional comment from Rob Millner on 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!

--- Additional comment from Meng Bo on 2013-10-24 22:44:47 EDT ---

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.

--- Additional comment from John Skeoch on 2013-11-17 19:50:31 EST ---

User rmillner's account has been closed

--- Additional comment from John Skeoch on 2013-11-17 19:53:57 EST ---

User rmillner's account has been closed

Comment 2 Yanping Zhang 2014-08-08 07:27:04 UTC
Add info:The bug exists on ose 2.1.z/2014-08-06.1.

Comment 3 Luke Meyer 2014-08-08 15:50:08 UTC
I thought maybe the pre-create script just didn't get updated for SCL version. But it did:
https://github.com/openshift/enterprise-server/blob/enterprise-2.1/cartridges/openshift-origin-cartridge-mongodb/bin/mkjournal

Nothing important fails if it's broken, you just don't get this optimization.

Comment 4 Miciah Dashiel Butler Masters 2015-09-19 00:50:08 UTC
It looks like the fix for this defect was shipped in RHBA-2014:0600 "Red Hat OpenShift Enterprise 2.1.1 bug fix and enhancement update" and would also have been included in RHSA-2014:1796 "Moderate: Red Hat OpenShift Enterprise 2.2 Release Advisory".  QE, can you verify that the defect does not exist in OpenShift Enterprise 2.2?

Comment 5 Yanping Zhang 2015-09-21 03:21:04 UTC
Checked on ose 2.2 puddle OpenShiftEnterpriseErrata/2.2/2015-09-18.2/.

Steps to test:
1.# time rhc cartridge add mongodb-2.4 -a phptest
Adding mongodb-2.4 to application 'phptest' ... done

mongodb-2.4 (MongoDB 2.4)
-------------------------
  Gears:          Located with php-5.4
  Connection URL: mongodb://$OPENSHIFT_MONGODB_DB_HOST:$OPENSHIFT_MONGODB_DB_PORT/
  Database Name:  phptest
  Password:       5tSBGmZDejKR
  Username:       admin

MongoDB 2.4 database added.  Please make note of these credentials:

   Root User:     admin
   Root Password: 5tSBGmZDejKR
   Database Name: phptest

Connection URL: mongodb://$OPENSHIFT_MONGODB_DB_HOST:$OPENSHIFT_MONGODB_DB_PORT/

real 	1m9.335s
user 	0m0.652s
sys	0m0.198s

2.# rhc ssh phptest cat app-root/logs/mongodb.log |grep prealloc
Warning: the RSA host key for 'phptest-domzyp.ose22-auto.com.cn' differs from the key for the IP address '10.66.79.203'
Offending key for IP in /root/.ssh/known_hosts:49
Matching host key in /root/.ssh/known_hosts:65
Are you sure you want to continue connecting (yes/no)? yes
note: noprealloc may hurt performance in many applications
Mon Sep 21 11:04:29.179 [initandlisten] options: { auth: true, bind_ip: "127.8.160.130", command: [ "run" ], config: "/var/lib/openshift/domzyp-phptest-1/mongodb//conf/mongodb.conf", dbpath: "/var/lib/openshift/domzyp-phptest-1/mongodb/data/", nohttpinterface: "true", noprealloc: "true", pidfilepath: "/var/lib/openshift/domzyp-phptest-1/mongodb/pid/mongodb.pid", quiet: "true", smallfiles: "true" }

From the test results, when add mongodb to app, though noprealloc is applied in mongodb, the adding time is still more than 30 seconds.

Comment 6 Rory Thrasher 2017-01-13 22:19:07 UTC
OpenShift Enterprise v2 has officially reached EoL.  This product is no longer supported and bugs will be closed.

Please look into the replacement enterprise-grade container option, OpenShift Container Platform v3.  https://www.openshift.com/container-platform/

More information can be found here: https://access.redhat.com/support/policy/updates/openshift/


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