I have an AngularJS front-end that sends requests to a Rails API back-end application. The AngularJS front-end is running in a NGINX server. The Rails API is running in an Unicorn server.
Generally, they are working fine together, but in one case. When I first load the home page most of the times (but not always) there is a big delay (around 12 seconds to process the request to Rails). I´m not sure, but my guess is this is only happening for the first request from Nginx to Unicorn.
This is a big issue for me, because when a user request the home page for first time, the page is loaded and displayed quite fast (it takes around 2 secs to display all components), however, the user has to wait around these 12 seconds, until the combo boxes are loaded with data coming from the backend.
I have no idea about server configuration. I´m just a developer. I tried to debug the request and try to figure out where the bottleneck is, but I don´t find anything.
Please, find my NGINX access.log logs:
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET / HTTP/1.1" 304 0 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET /css/bootstrap.min.css HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET /css/bootstrap-responsive.min.css HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET /dist/css/yanpy.min.css HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET /css/icons.css HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET /css/menus.css HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET /css/join-us.css HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET /css/font-awesome.min.css HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET /css/font-awesome-ie7.min.css HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET /dist/css/yanpy-ext-1.min.css HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET /css/lightbox.css HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET /dist/js/yanpy-libs-1.min.js HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET /js/app.js HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET /js/services.js HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET /js/controllers.js HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET /dist/js/yanpy.min.js HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET /js/filters.js HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET /js/directives.js HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET /js/i18n.js HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET /js/properties/properties.js HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET /dist/js/yanpy-libs-2.min.js HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:45 +0100] "GET /img/logo.png HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:46 +0100] "GET /languages/locale-en.json HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:46 +0100] "GET /lib/angular/i18n/angular-locale_en.js HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:46 +0100] "GET /languages/locale-en.json HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:46 +0100] "GET /partials/login.html HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:46 +0100] "GET /img/glyphicons-halflings.png HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:46 +0100] "GET /partials/home.html HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:46 +0100] "GET /img/facilImage.png HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:46 +0100] "GET /img/rapidoImage.png HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:46 +0100] "GET /img/seguroImage.png HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:46 +0100] "GET /img/carrusel1.jpg HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:46 +0100] "GET /img/carrusel2.jpg HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:46 +0100] "GET /img/carrusel3.jpg HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:46 +0100] "GET /img/carrusel4.jpg HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:46 +0100] "GET /partials/boat-searcher.html HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
127.0.0.1 - - [12/Nov/2014:19:33:47 +0100] "GET /img/glyphicons-halflings-white.png HTTP/1.1" 304 0 "http://localhost/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
As you can see it takes around 2 seconds. This point I don´t know why I can´t see the request to the Rails API in this file (anyway, you can see them in the snapshot I attach).
After this log, I´m just waiting for 12 seconds for the rails api request:
Started GET "/getTranslationLanguages" for 127.0.0.1 at 2014-11-12 19:33:59 +0100
Processing by LanguagesController#translationLanguages as HTML
Language Load (0.4ms) SELECT `languages`.* FROM `languages` WHERE `languages`.`translation` = 1
Completed 200 OK in 2ms (Views: 1.0ms | ActiveRecord: 0.4ms)
Started GET "/currencies" for 127.0.0.1 at 2014-11-12 19:33:59 +0100
Processing by CurrenciesController#index as HTML
Currency Load (0.3ms) SELECT `currencies`.* FROM `currencies`
Completed 200 OK in 3ms (Views: 1.8ms | ActiveRecord: 0.3ms)
Started GET "/boat_people" for 127.0.0.1 at 2014-11-12 19:33:59 +0100
Processing by BoatPeopleController#index as HTML
BoatPerson Load (0.3ms) SELECT `boat_people`.* FROM `boat_people`
Completed 200 OK in 2ms (Views: 0.9ms | ActiveRecord: 0.3ms)
Started GET "/getTranslationLanguages" for 127.0.0.1 at 2014-11-12 19:33:59 +0100
Processing by LanguagesController#translationLanguages as HTML
Language Load (0.4ms) SELECT `languages`.* FROM `languages` WHERE `languages`.`translation` = 1
Completed 200 OK in 2ms (Views: 1.0ms | ActiveRecord: 0.4ms)
Started GET "/currencies" for 127.0.0.1 at 2014-11-12 19:33:59 +0100
Processing by CurrenciesController#index as HTML
Currency Load (0.3ms) SELECT `currencies`.* FROM `currencies`
Completed 200 OK in 2ms (Views: 1.1ms | ActiveRecord: 0.3ms)
See, there is a delay of 12 seconds from the last log entry in Nginx to first log entry in Unicorn.
I don´t know what happens while this time.
I also attach a snapshot from Google tools. It displays more or less same info that the Nginx access.log. But this time, you can see the requests to Rails API (i.e. getTranslationLanguages) that has a latency of 12.40 secs.
Why is it waiting for that 12 seconds? Could be any cache? What else can I check?
UPDATE: I don´t know why it seems to be related to cache or cookies. When I delete browsing history with cache and cookies in my browser and I load the site the issue doesn´t happen anymore. After that, if I just refresh the page, the issue happens.
IMPORTANT UPDATE Now, I´m pretty sure the issue is located in Unicorn. If I just shutdown Unicorn and startup webrick (without any other update on my application or code) the issue doens´t happen anymore.
I attach my Unicorn.rb config file:
# config/unicorn.rb
if ENV["RAILS_ENV"] == "development"
worker_processes 1
stderr_path "/Users/Rober/Projects/yanpy/dev/yanpyapi/log/unicorn.stderr.log"
stdout_path "/Users/Rober/Projects/yanpy/dev/yanpyapi/log/unicorn.stdout.log"
elsif ENV["RAILS_ENV"] == "test"
worker_processes 1
stderr_path "/home/ubuntu/env/test/www/yanpyapi-test/log/unicorn.stderr.log"
stdout_path "/home/ubuntu/env/test/www/yanpyapi-test/log/unicorn.stdout.log"
listen 8081
else
#worker_processes 3
worker_processes 1
stderr_path "/home/ubuntu/env/production/www/yanpyapi/log/unicorn.stderr.log"
stdout_path "/home/ubuntu/env/production/www/yanpyapi/log/unicorn.stdout.log"
end
timeout 30
Note: You don´t have to worry about the environment, the issue is happening in both of them.
UPDATE: When I send request in my browser directly to a Rails endpoint in Unicorn i.e http://localhost:8080/getTranslationLanguages I got the result immediately in my browser in json format. I mean, the issue doesn´t happen. So, it looks like the issue is only when the request are sent from Nginx to Unicorn.
IMPORTANT UPDATE I have confirmed the issue is only happening with Google Chrome. It never happens with Safari. Even, I have noticed, when I run audit tool in Google tools, it somehow clean everything, so everytime I run the audit it works perfectly.
UPDATE: I have installed and tested with Puma. It´s working. I don´t know why the combination of Unicorn and Chrome is not working.