Rails app encounters performance issues due to Rack :: Lock

Question

I have a Ruby on Rails application with the following versions:

Ruby: 1.9.3-p547

Rails: 3.2.16

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

Using this, I found that Rack :: Lock is time consuming. The following are some of the RackTimer logs from the logs 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 you can see, the processing time of the Rack :: Lock middleware ranges from 10 ms to more than 130 seconds. And most of them come into the picture when servicing assets on my home page.

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

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

I have a production version app configured to control using NewRelic. Also, graphical charts show the largest percentage and time spent on Rack :: Lock.

I am completely empty about what makes Rack :: Lock take so many milliseconds. It would be helpful if someone in the community could provide valuable guidance on what could be causing this and how to fix it?

Below you can find the Gemfile, which is used by all Middlewares and Dev Environment Logs.

Gemfile:

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

Intermediaries:

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

Development Environment Logs:

----- FIRST TIME LOADED HOME INDEX PAGE

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

----- SECOND TIME LOADS HOME PAGE INDEX WITHOUT RESTORING THE SERVER

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

Thanks Jignesh

Answer 1

I post my findings here after I posted my question above. Hoping that someone else will benefit from these results when he finds himself in a situation like the one above.

Discussing the Rack :: Lock issue with one of my senior Juha Litola employees , below were his first thoughts (quoting his own words as they are):

Could it be possible that you see the dimension of the artifact in the sense that you simply see Rack :: Lock as time-consuming, but this is only because it completes the actual call? Thus, Rack :: Lock time is a cumulative time from everything that happens when processing a request. Cm.

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

As for performance issues, could you clarify what problems you have so that I can help?

What I thought this might be an opportunity. However, I could not convince myself of this possibility because of the following doubts:

Rack::Lock is in second position in the Middlewares chain with the Rails application (see the list of middleware mentioned above at https://gist.github.com/JigneshGohel-BoTreeConsulting/91c004686de21bd6ebc1 ). And each middleware is processed sequentially in a chain. Thus, Rack::Lock will be the second to process the request and then the others in the chain will be able to jump.

In this case, as I understand it, the timestamps recorded for the Rack :: Lock middleware are cumulative time from everything that happens when processing the request. And that should be the time taken by Rack :: Lock middleware.

Later Juha, having spent several minutes viewing the server (see the note below), provided the following data:

With quick browsing, I think there is a pretty obvious problem with how the application is configured. The application does not have config.threadsafe !, which means that Rack :: Lock is enabled and request processing is limited to one thread / process. Now puma is configured for only one process, but on threads 16-32. This means that puma is currently processing only one request at a time.

The best solution, of course, would be if you could enable thread safe mode, but that would require rigorous testing. If this does not work or is not an option, puma should be configured with multiple employees with 1 thread each.

Note. I forgot to add any configuration information for the web server on which my application is deployed. We use the Puma web server ( https://github.com/puma/puma )

With this, I got a hint to dig more into config.threadsafe! . Searching the Internet, I landed on the following articles.

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

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

sheds great hope on how to enable or disable the config.threadsafe option ! affects the performance of an application deployed on a multi-threaded or multi-processor web server during production.

A brief overview of what is presented above the articles

What is Rack :: Lock?

Rack :: Lock is a middleware that is pushed onto the Rails middleware stack to protect our applications from multithreaded Bogeyman. This middleware is supposed to protect us from unpleasant race conditions and dead ends by wrapping our queries with a mutex. The binder locks the mutex at the start of the request and unlocks the mutex when the request completes.

Suppose there is a program that executes and sends 5 requests at the same time 100 times for an application whose code (for example, Controller) is NOT thread safe.

Now consider the effects of the middleware combination Rack :: Lock, config.threadsafe! the option is enabled or disabled, insecure code in the application and a multithreaded or multiprocessor web server, after the program is terminated or destroyed

Multithreaded Web Server (Puma)

 # Combination 1: config.threadsafe! option : Disabled Rack::Lock middleware : Available in app 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 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. Runtime examples and statistics are provided at http://tenderlovemaking.com/2012/06/18/removing-config-threadsafe.html

Multiprocessor Web Server (Unicorn)

 # Combination 1: config.threadsafe! option : Disabled Rack::Lock middleware : Available in app 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 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 multiprocessor environment, Rack :: Lock becomes redundant if we save config.threadsafe! option is disabled. This is because in a multiprocessor environment, the socket is our lock, and we do not need additional lock. Thus, it is useful to include config.threadsafe! and remove Rack :: Lock overhead in the production environment.

• In a multi-threaded environment, if we save config.threadsafe! developers need to ensure that application code is thread safe. And the advantage of saving config.threadsafe! lies in the fact that it takes less time to process incoming requests.

In my application context, we configured the Puma server configuration, increasing the number of workers. I hope the performance improves.