Mongoid 2.3 = major bottlenecks in Goliath?

[Adam Watson]

I've been profiling the Goliath-based server I've been building, and
ran into a really interesting problem. By merely removing the "
require 'mongoid' " line for the mongoid gem (2.3.3) from my config,
I'm seeing drastic improvements in response time.

Using apachebench, I tested the simple status endpoint that is
provided via Goliath::Rack::Heartbeat. No other code is being
exercised in the endpoint.

When I have this line in the config:

require 'mongoid'

...the ab results show that I'm getting approximately 80 requests per
second for the /status. When I remove the require, my throughput jumps
up to around 350 requests per second for /status. The actual ab
results are at the bottom of this message.

Anyone have any idea what could be going on? I might expect that
slowdowns could occur if something in the mongoing gem was not async-
aware... but given that I'm not actually using any of the code (just
requiring the gem) I'm puzzled by this result.



ab results *without* the mongoid gem being required:


(! 726)-> ab -n500 -c20 http://localhost:9000/status
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Completed 400 requests
Completed 500 requests
Finished 500 requests


Server Software: Goliath
Server Hostname: localhost
Server Port: 9000

Document Path: /status
Document Length: 2 bytes

Concurrency Level: 20
Time taken for tests: 1.320 seconds
Complete requests: 500
Failed requests: 0
Write errors: 0
Total transferred: 47752 bytes
HTML transferred: 1016 bytes
Requests per second: 378.78 [#/sec] (mean)
Time per request: 52.801 [ms] (mean)
Time per request: 2.640 [ms] (mean, across all concurrent
requests)
Transfer rate: 35.33 [Kbytes/sec] received

Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 0.1 0 0
Processing: 16 51 8.3 52 72
Waiting: 3 40 12.9 42 56
Total: 16 51 8.2 53 72

Percentage of the requests served within a certain time (ms)
50% 53
66% 56
75% 56
80% 56
90% 60
95% 64
98% 72
99% 72
100% 72 (longest request)



ab results *with* the mongoid mongoid being required:



(! 727)-> ab -n500 -c20 http://localhost:9000/status
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Completed 400 requests
Completed 500 requests
Finished 500 requests


Server Software: Goliath
Server Hostname: localhost
Server Port: 9000

Document Path: /status
Document Length: 2 bytes

Concurrency Level: 20
Time taken for tests: 5.151 seconds
Complete requests: 500
Failed requests: 0
Write errors: 0
Total transferred: 47658 bytes
HTML transferred: 1014 bytes
Requests per second: 97.07 [#/sec] (mean)
Time per request: 206.041 [ms] (mean)
Time per request: 10.302 [ms] (mean, across all concurrent
requests)
Transfer rate: 9.04 [Kbytes/sec] received

Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 0.1 0 0
Processing: 27 202 43.4 207 299
Waiting: 9 168 45.7 189 224
Total: 27 203 43.4 207 300

Percentage of the requests served within a certain time (ms)
50% 207
66% 212
75% 217
80% 220
90% 255
95% 280
98% 297
99% 300
100% 300 (longest request)


Cheers,
Adam

[Ilya Grigorik]

Adam, so the difference is only based on "require mongoid"??

Are you running with -e production flag?

This feels weird.

ig

[Adam Watson]

Hi Ilya,

Yes, the difference is only based on "require mongoid". I just
finished a second test, on a completely different macbook pro, I am
getting the same results as my first test by only adding a single
'require mongoid' line in my config file.

I am not running the -e flag. My startup command looks like this:
ruby ./server.rb -s -v -c ./config/base.rb -p 8000

I agree, it does feel weird.

Adam

On Nov 14, 6:20 pm, Ilya Grigorik <igrigo...@google.com> wrote:
> Adam, so the difference is only based on "require mongoid"??
>
> Are you running with -e production flag?
>
> This feels weird.
>
> ig
>
>
>
>
>
>
>
> On Mon, Nov 14, 2011 at 6:15 PM, Adam Watson <awat...@ngmoco.com> wrote:
> > I've been profiling the Goliath-based server I've been building, and
> > ran into a really interesting problem. By merely removing the "
> > require 'mongoid' " line for the mongoid gem (2.3.3) from my config,
> > I'm seeing drastic improvements in response time.
>
> > Using apachebench, I tested the simple status endpoint that is
> > provided via Goliath::Rack::Heartbeat. No other code is being
> > exercised in the endpoint.
>
> > When I have this line in the config:
>
> >   require 'mongoid'
>
> > ...the ab results show that I'm getting approximately 80 requests per
> > second for the /status. When I remove the require, my throughput jumps
> > up to around 350 requests per second for /status. The actual ab
> > results are at the bottom of this message.
>
> > Anyone have any idea what could be going on? I might expect that
> > slowdowns could occur if something in the mongoing gem was not async-
> > aware...  but given that I'm not actually using any of the code (just
> > requiring the gem) I'm puzzled by this result.
>
> > ab results *without* the mongoid gem being required:
>

> > (! 726)-> ab -n500 -c20http://localhost:9000/status

> > This is ApacheBench, Version 2.3 <$Revision: 655654 $>

> > Copyright 1996 Adam Twiss, Zeus Technology Ltd,http://www.zeustech.net/
> > Licensed to The Apache Software Foundation,http://www.apache.org/

> > (! 727)-> ab -n500 -c20http://localhost:9000/status

> > This is ApacheBench, Version 2.3 <$Revision: 655654 $>

> > Copyright 1996 Adam Twiss, Zeus Technology Ltd,http://www.zeustech.net/
> > Licensed to The Apache Software Foundation,http://www.apache.org/

[Ilya Grigorik]

Adam, any chance you can extract the minimum relevant bits and throw it up into a gist? This seems bizzarre.. at best. :-)

I'm curious to see what the heck is causing this.

ig

[Adam Watson]

Sure thing. I created a very simple example that removes all but the
most basic code in this gist: https://gist.github.com/1367854

I haven't dug into Mongoid thoroughly yet, but after a cursory look, I
do see that a lot of dependency loading is done just by 'require'ing
the gem. I also see that mongoid is threaded and includes custom rack
middleware, which may very well be the source of the problem...
though I would need to dig deeper before coming to any solid
conclusions.

Thanks,
Adam

[Ilya Grigorik]

Adam, left a comment on the gist.. but I can't reproduce the problem on this end. Hmm?

ig

[Adam Watson]

Hi Ilya,

Wow, I had no idea that running Goliath in production mode had any other effect than to specify the environment configuration to use. It's not documented anywhere that massively better performance could be obtained by running with the -e production switch.

It seems the bottleneck I point out is only happening in the other modes—it disappears entirely when the production switch is used. So, this is not really an issue...  except that it makes it difficult to get realistic metrics back when load testing the server in development or staging environments.

In any event, I'm still cheering the fact that in production mode, the issue I was experiencing disappears, and I'm getting over 8x better throughput with my app. Thanks for your awesome insight and help.

Adam 

[Ilya Grigorik]

Adam, the only difference between "prod" flag and others is that we inject the "reloader" middleware in all other modes, which does a file stat + code reload on each request (such that you can update code, hit save and refresh API to see the results). In prod mode, the file is cached when its loaded and edits require a restart. 

The perf difference is strictly due to the extra filesystem calls.

ig

[Sujal Shah]

Does this mean we no longer need to include the reloaded middleware explicitly in our API classes?

I was seeing similar performance issues when testing last night with an API server that uses Mongoid. I will double check that my environment is getting set properly. Glad I saw this today. Could've saved me a few hours of debugging last night.

Sujal

[Ilya Grigorik]

On Wed, Nov 16, 2011 at 4:35 AM, Sujal Shah <code...@gmail.com> wrote:

Does this mean we no longer need to include the reloaded middleware explicitly in our API classes?

Correct, the explicit middleware is deprecated. 

 

ig 

[Adam Watson]

Aha, this completely explains it. In fact, I have seen the reloader middleware in action, but just didn't connect it with the performance differences.

Thanks again for the help Ilya!

Cheers,

Adam