Большая задержка при обработке HTTP-запроса от NGINX к Unicorn (AngularJS to Rails API) только в Chrome
У меня есть внешний интерфейс AngularJS, который отправляет запросы в серверное приложение Rails API. Внешний интерфейс AngularJS работает на сервере NGINX. Rails API работает на сервере Unicorn.
Как правило, они отлично работают вместе, но в одном случае. Когда я впервые загружаю домашнюю страницу в большинстве случаев (но не всегда), возникает большая задержка (около 12 секунд для обработки запроса к Rails). Я не уверен, но я предполагаю, что это происходит только для первого запроса от Nginx к Unicorn.
Это большая проблема для меня, потому что когда пользователь запрашивает домашнюю страницу в первый раз, страница загружается и отображается довольно быстро (для отображения всех компонентов требуется около 2 секунд), однако пользователь должен ждать около этих 12 секунд, пока поля со списком не будут загружены данными, поступающими из серверной части.
Я понятия не имею о конфигурации сервера. Я просто разработчик. Я попытался отладить запрос и попытаться выяснить, где находится узкое место, но я ничего не нашел.
Пожалуйста, найдите мои журналы NGINX access.log:
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"
Как видите, это занимает около 2 секунд. В этот момент я не знаю, почему я не вижу запрос к Rails API в этом файле (во всяком случае, вы можете увидеть их в прикрепленном снимке).
После этого журнала я просто жду 12 секунд для запроса API rails:
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)
Видите, с последней записи журнала в Nginx есть задержка в 12 секунд до первой записи журнала в Unicorn.
Я не знаю, что происходит в это время.
Я также прилагаю снимок из инструментов Google. Он отображает более или менее ту же информацию, что и Nginx access.log. Но на этот раз вы можете увидеть запросы к Rails API (то есть getTranslationLanguages) с задержкой в 12.40 с.
Почему он ждет эти 12 секунд? Может быть какой-нибудь кеш? Что еще я могу проверить?
ОБНОВЛЕНИЕ: я не знаю, почему это связано с кешем или куки. Когда я удаляю историю браузера с кешем и файлами cookie в моем браузере и загружаю сайт, проблема больше не возникает. После этого, если я просто обновлю страницу, проблема произойдет.
ВАЖНОЕ ОБНОВЛЕНИЕ Теперь, я уверен, что проблема находится в Unicorn. Если я просто отключаю Unicorn и запускаю webrick (без какого-либо другого обновления в моем приложении или коде), проблема больше не возникает.
Я прилагаю свой файл конфигурации Unicorn.rb:
# 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
Примечание: вам не нужно беспокоиться об окружающей среде, проблема возникает в обоих из них.
ОБНОВЛЕНИЕ: Когда я отправляю запрос в своем браузере напрямую на конечную точку Rails в Unicorn, т.е. http://localhost:8080/getTranslationLanguages
Я сразу получил результат в своем браузере в формате json. Я имею в виду, проблема не возникает. Таким образом, похоже, что проблема заключается только в том, что запрос отправляется из Nginx в Unicorn.
ВАЖНОЕ ОБНОВЛЕНИЕ Я подтвердил, что проблема возникает только с Google Chrome. Это никогда не случается с Safari. Даже, как я заметил, когда я запускаю инструмент аудита в инструментах Google, он каким-то образом очищает все, поэтому каждый раз, когда я запускаю аудит, он работает отлично.
ОБНОВЛЕНИЕ: Я установил и протестировал с Puma. Работает. Я не знаю, почему не работает комбинация Unicorn и Chrome.