Rails application facing performance issues due to Rack::Lock

Question

I have a Ruby on Rails application with following versions:

Ruby: 1.9.3-p547

Rails: 3.2.16

I am facing some performance issues in this application. My initial efforts on diagnosing this landed me up on using the RackTimer gem (https://github.com/joelhegg/rack_timer) mentioned in article at http://www.codinginthecrease.com/news_article/show/137153 to record the Middleware timestamps.

Using it I found that Rack::Lock consumes a lot of time.For e.g. following are some of the RackTimer logs from the logs provided below:

    Rack Timer (incoming) -- Rack::Lock: 73.77910614013672 ms
    Rack Timer (incoming) -- Rack::Lock: 67.05522537231445 ms
    Rack Timer (incoming) -- Rack::Lock: 87.3713493347168 ms
    Rack Timer (incoming) -- Rack::Lock: 59.815168380737305 ms
    Rack Timer (incoming) -- Rack::Lock: 55.583953857421875 ms
    Rack Timer (incoming) -- Rack::Lock: 111.56821250915527 ms
    Rack Timer (incoming) -- Rack::Lock: 119.28486824035645 ms
    Rack Timer (incoming) -- Rack::Lock: 69.2741870880127 ms
    Rack Timer (incoming) -- Rack::Lock: 75.4690170288086 ms
    Rack Timer (incoming) -- Rack::Lock: 86.68923377990723 ms
    Rack Timer (incoming) -- Rack::Lock: 113.18349838256836 ms
    Rack Timer (incoming) -- Rack::Lock: 116.78934097290039 ms
    Rack Timer (incoming) -- Rack::Lock: 118.49355697631836 ms
    Rack Timer (incoming) -- Rack::Lock: 132.1699619293213 ms

As can be seen Rack::Lock middleware processing time fluctuates between 10 ms to more than 130 seconds. And the majority of these comes into picture while serving assets on my Home Page.

BTW I have Asset Pipeline enabled in my config/application.rb

    # Enable the asset pipeline
    config.assets.enabled = true

I have my Production-version application configured to be monitored by NewRelic.There too the graph-charts highlights highest % and time taken by Rack::Lock.

I am totally blank on what is contributing towards making Rack::Lock take so many milliseconds.Would appreciate if anybody from the community can provide their valuable guidance in figuring out what might be causing this and how to fix it?

Below can be found the Gemfile, what all Middlewares are involved and Dev environment Logs.

Gemfile:

https://gist.github.com/JigneshGohel-BoTreeConsulting/1b10977de58d09452e19

Middlewares Involved:

https://gist.github.com/JigneshGohel-BoTreeConsulting/91c004686de21bd6ebc1

Development Environment Logs:

----- FIRST TIME LOADED THE HOME INDEX PAGE

https://gist.github.com/JigneshGohel-BoTreeConsulting/990fab655f156a920131

----- SECOND TIME LOADED THE HOME INDEX PAGE WITHOUT RESTARTING THE SERVER

https://gist.github.com/JigneshGohel-BoTreeConsulting/f5233302c955e3b31e2f

Thanks, Jignesh

Answer 1

I am posting my findings here after I posted my question above. Hoping that somebody else benefits from these findings when ends up in a situation like above.

Discussing about the Rack::Lock issue with one of my senior associates Juha Litola, below were his first thoughts (quoting his own words as it is):

Could it just be possible that you are seeing measuring artifact in sense that you are just seeing Rack::Lock as taking a lot of time, but that is just because it is wrapping the actual call? So the Rack::Lock time is cumulative time from everything that happens in the request processing. See

https://github.com/rack/rack/blob/master/lib/rack/lock.rb .

As for the performance issues, could you elaborate on what kind of problems you have so I could help?

To which I thought it could be a possibility. However I could not convince myself with this possibility because of the following doubt:

Rack::Lock is at the second position in the Middlewares chain with a Rails application (please refer the Middleware List I mentioned in post above at https://gist.github.com/JigneshGohel-BoTreeConsulting/91c004686de21bd6ebc1 ). And each middleware is processed in sequential order in the chain. Thus Rack::Lock would be the second one to process the request and then others in the chain would get a chance to jump in.

In such a case as per my understanding I don't think the timestamps recorded for Rack::Lock middleware is the cumulative time from everything that happens in the request processing.And it should be the time taken by Rack::Lock middleware itself.

Later Juha, after spending a few minutes looking at the server(see note below) config provided following inputs:

With a quick look I think that there is a quite clear problem in how the application has been configured. Application doesn’t have config.threadsafe! enabled, which means that Rack::Lock is enabled, and request processing is limited to one thread / process. Now puma is configured only to have one process, but 16-32 threads. What this means in effect that puma is currently processing only one request at given moment.

Best solution would of course be if you could enable thread safe mode, but that will require thorough testing. If that fails or is not an option puma should be configured with multiple workers with 1 thread each.

Note: I forgot to add any details about the configuration of web server on which my application is deployed. We are using Puma Web Server (https://github.com/puma/puma)

With that I got a hint to dig more into the config.threadsafe!. Doing a search on web I landed up on following articles

http://www.sitepoint.com/config-threadsafe/

http://tenderlovemaking.com/2012/06/18/removing-config-threadsafe.html

shedding great insights on how enabling or disabling the option config.threadsafe! impacts the performance of the application deployed on a multi-threaded or multi-process webserver on production.

A Brief Summary Of What The Above Articles Conveyed

What is Rack::Lock?

Rack::Lock is a middleware that is inserted to the Rails middleware stack in order to protect our applications from the multi-threaded Bogeyman. This middleware is supposed to protect us from nasty race conditions and deadlocks by wrapping our requests with a mutex. The middleware locks a mutex at the beginning of the request, and unlocks the mutex when the request finishes.

Let's assume that there is a program running and sending 5 requests simultaneously 100 times to an application whose code (say Controller) is NOT thread-safe.

Now lets observe the impact of combination of Rack::Lock middleware, config.threadsafe! option enabled or disabled, Thread-unsafe code in the application, and Multi-Threaded or Multi-Process Web Server, after the program gets finished or is killed

Multi-Threaded Web Server (Puma)

# Combination 1:
    config.threadsafe! option   : Disabled
    Rack::Lock middleware       : Available in app's middleware stack because of config.threadsafe! option disabled

    With this combination the web server is successfully able to entertain all the 500 requests received.
    This is because each request is augmented by Rack::Lock so as to execute it synchronously.In other words
    Rack::Lock ensures we have only one concurrent request at a time.Thus each of the 500 requests gets a chance to
    execute.

# Combination 2:
    config.threadsafe! option   : Enabled
    Rack::Lock middleware       : Unavailable in app's middleware stack because of config.threadsafe! option enabled

    With this combination the web server is able to entertain only 200 out of 500 requests received.
    This is because of the absence of Rack::Lock middleware, which ensures that we have only one concurrent request
    at a time and thus each request gets a chance.

However there are advantages as well as disadvantages of each combination mentioned above:

# Combination 1
    Advantage:
        Each of the request received gets chance to be processed

    Disadvantage:
        * The runtime to process all of the 500 requests took 1 min 46 secs (compare it to runtime of Combination 2)
        * Using a multi-threaded webserver is useless, if Rack::Lock remains available in middleware stack.

# Combination 2
    Advantage:
        The runtime to process 200 requests took 24 secs (compare it to runtime of Combination 1).
        The reason being the multi-threaded nature of webserver is being leveraged in this case to entertain concurrent requests coming in.

    Disadvantage:
        * Not all 500 requests got a chance to be processed

Note: Examples and Runtime statistics have been quoted from http://tenderlovemaking.com/2012/06/18/removing-config-threadsafe.html

Multi-Process Web Server (Unicorn)

# Combination 1:
    config.threadsafe! option   : Disabled
    Rack::Lock middleware       : Available in app's middleware stack because of config.threadsafe! option disabled

    Since multiple processes are forked by the webserver and each of them listens for requests and also
    Rack::Lock middleware is available, the web server is successfully able to entertain all the 500 requests received.

# Combination 2:
    config.threadsafe! option   : Enabled
    Rack::Lock middleware       : Unavailable in app's middleware stack because of config.threadsafe! option enabled

    Here too multiple processes are forked by the webserver and each of them listens for requests,
    however Rack::Lock middleware is unavailable which enables multi-threading, which in turn means that we'll
    get a race condition in the thread-unsafe code we have in the application.But strangely with this combination
    too the web server is successfully able to entertain all the 500 requests received.

    The reason being a process-based web server creates worker processes and each process holds one instance of
    our application. When a request is received webserver spawns a child process for handling it.

Conclusion:

• In a multi-process environment Rack::Lock becomes redundant if we keep config.threadsafe! option disabled. This is because in multi-process environment the socket is our lock and we don't need any additional lock. Thus it is beneficial to enable config.threadsafe! and remove Rack::Lock overhead in production environment.

• In a multi-threaded environment if we keep config.threadsafe! enabled the developers needs to ensure the application's code is thread-safe. And the advantage of keeping config.threadsafe! is that lesser runtime is needed to process the incoming requests.

In my application's context we tweaked the Puma server's config by increasing the workers. I hope the performance improves.