Большинство из нас видели этот страшный зеленый график с морской пеной при использовании New Relic. Вы знаете одно — Очередь запросов . Вызывая холодную дрожь в позвоночнике, оно изображает медленное приложение, изо всех сил пытающееся обслуживать ваших пользователей, и увеличивающуюся вероятность того, что эти пользователи «отскочат» от вашего приложения в объятия другого.
… или это?
Очередь запросов в New Relic , возможно, является одним из наиболее неправильно понятых показателей в мониторинге производительности современных веб-приложений, и в Engine Yard у нас возникает много вопросов по этому поводу. Большинство разработчиков понимают это как показатель того, как долго в среднем обрабатываются запросы, прежде чем они обрабатываются рабочим процессом приложения (например, работником Passenger или Unicorn).
К сожалению, это полное непонимание метрики, как она измеряется и что это значит. Эта статья направлена на то, чтобы лучше объяснить, что на самом деле представляет собой очередь запросов, провести различие между очередями и задержкой, а также помочь разработчикам лучше понять, когда у приложения действительно есть проблемы, а когда цифры в очереди запросов являются просто неизбежным фактом жизни.
Здесь необходимо обратить внимание на две цифры: сколько запросов в очереди обрабатывается в данный момент времени и сколько времени занимает обработка запроса от получения nginx до обработки работником приложения. Это тонкое, но критическое различие в том, как все работает, и понимание этих различий очень поможет вам в диагностике потенциальных проблем с производительностью вашего приложения и / или конфигурации.
Итак, давайте начнем эту статью, проведя различие между очередями запросов и задержкой запросов.
Задержка запроса В
большинстве случаев, когда люди видят графики New Relic, подобные приведенным ниже, и думают об очередности запросов, они действительно видят задержку запросов.
В действительности то, что на этом графике изображено страшно-зеленовато-зеленое представление, представляет собой простое математическое вычитание времени между тем, когда nginx вставляет заголовок отслеживания времени, и когда агент New Relic анализирует этот заголовок — больше ничего.
Чтобы проиллюстрировать это, взгляните на этот пример конфигурации nginx. Это часть нашей стандартной конфигурации в Engine Yard Cloud:
Файл: /etc/nginx/common/proxy.conf — включен в /etc/nginx/servers/appname.conf
# needed to forward user's IP address to rails proxy_set_header X-Real-IP $remote_addr; proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for; proxy_set_header Host $http_host; proxy_set_header X-Forwarded-Proto $scheme; proxy_set_header X-Queue-Start 't=$start_time'; proxy_redirect off; proxy_max_temp_file_size 0;
Как показывает эта конфигурация, nginx добавляет заголовок X-Queue-Start к каждому HTTP-запросу. Позже, когда ваш обработчик обрабатывает запрос, New Relic ищет этот заголовок:
module NewRelic module Agent module Instrumentation module QueueTime unless defined?(MAIN_HEADER) MAIN_HEADER = 'HTTP_X_REQUEST_START' MIDDLEWARE_HEADER = 'HTTP_X_MIDDLEWARE_START' QUEUE_HEADER = 'HTTP_X_QUEUE_START' ALT_QUEUE_HEADER = 'HTTP_X_QUEUE_TIME' HEROKU_QUEUE_HEADER = 'HTTP_X_HEROKU_QUEUE_WAIT_TIME' APP_HEADER = 'HTTP_X_APPLICATION_START'
https://github.com/newrelic/rpm/blob/master/lib/new_relic/agent/instrumentation/queue_time.rb#L8
А потом разбирает это:
# Checks that the time is not negative, and does the actual # data recording
def record_time_stat(name, start_time, end_time) # (String, Time, Time) -> nil
total_time = end_time - start_time
if total_time < 0
raise "should not provide an end time less than start time: #{end_time.strftime('%s.%N')} is less than #{start_time.strftime('%s.%N')}. total time is #{total_time}."
else
NewRelic::Agent.get_stats(name).trace_call(total_time)
end
https://github.com/newrelic/rpm/blob/master/lib/new_relic/agent/instrumentation/queue_time.rb#L173 Итак, как мы добрались до этой конкретной точки в коде? В NewRelic :: Agent :: Instrumentation :: Queutime # parse_queue_time_from объект «совпадения» получен из get_matches_from_header, который указывает QUEUE_HEADER, в данном случае «HTTP_X_QUEUE_START», который был добавлен nginx вверх по течению. Этот «совпадающий» объект затем передается в record_rollup_queue_stat с переменной end_time, которая в конечном итоге будет Time.now. Метод record_rollup_queue_stat вызывает record_rollup_stat_of_type с временем окончания и сопоставляет ранее определенные объекты. Затем этот метод вызывает record_time_stat, который, как мы видим выше, вычисляет значение total_time как простое вычитание и сообщает его в New Relic.
Согласно нашему собственному обзору кода и даже в соответствии с проведенными нами частными беседами с New Relic, агент New Relic ни разу не попытался взглянуть на сокет Unicorn или основной процесс Passenger, чтобы определить, сколько запросы фактически находятся в очереди внутри него. Следовательно, это измерение сильно отличается от ожидаемого большинством разработчиков.
Само наличие «задержки запроса» (что New Relic называет «очередью») не обязательно указывает на проблему, хотя может быть при определенных обстоятельствах.
Так как это полезно?
Если вы видите задержку запроса в New Relic, это, как правило, указывает на то, что что-то происходит «перед» способностью New Relic анализировать этот заголовок. Обычно это не является серьезной проблемой, если только вы не начнете видеть, как эти цифры дико выходят из-под контроля.
По нашему опыту, большие пики и крутые долины обычно отражают несколько действий контроллера или серии действий или потока приложений, в которых что-то прыгает перед New Relic в порядке обработки запроса. Например, before_filter может вызывать только определенные действия по определенным причинам в определенных условиях. Другие причины могут включать перезапуск сервера приложений (Пассажир, Единорог) из-за ограничений памяти, конфликта ресурсов, медленных запросов к базе данных или различных форм таймаутов.
И наоборот, ситуации с большим количеством задержек запросов, которые являются постоянными и стабильными, обычно отражают ряд чрезмерно используемых before_filters, медленное промежуточное программное обеспечение Rack, конфликт ресурсов (обычно связанный с ЦП), медленные соединения с часто называемыми внешними службами или постоянно медленные производительность базы данных.
Мы видели, как before_filters вступали в игру, потому что они выполняются до того, как New Relic вычислит время ожидания своего запроса. В этих случаях все, что замедляет фильтр before, способствует задержке запроса. Это может привести к тому, что у приложения возникнет проблема, когда ее может не быть. Это действительно зависит от того, какое фактическое время (в миллисекундах) соответствует задержке запроса, является ли оно необходимым для большинства или всех запросов, и является ли это число разумным. В большинстве случаев задержка ~ 500 мс совершенно неоправданна, но ~ 25 мс может быть разумным, если действительно необходимо использование промежуточного программного обеспечения Rack или before_filters. Однако, возможно, вам придется проявлять большую гибкость в отношении этих цифр в зависимости от того, какие зависимые элементы вашего приложения отвечают за выполнение. Например, если вы получаете информацию из REST API,и существует большое географическое расстояние между вашими серверами и местоположением API, задержка сети может в конечном итоге стать основной причиной. (То же самое может применяться к службам DBaaS, в зависимости от того, где находятся их конечные точки.)
Кроме того, проблема конкуренции за ресурсы может быть в игре в этих ситуациях. Когда я говорю «ресурс», я намеренно имею в виду очень широкое значение. Если ваше приложение зависит от внешних веб-служб, которые часто вызываются и работают медленно, это может быть потенциальной причиной. В других случаях ваша база данных может быть забита (возможно, другое приложение имеет высокий трафик, кто-то запустил отчет на той же машине, с которой вы выполняли чтение, или срок действия кэша истек, и он восстанавливается). Возможно, ваше приложение просто находится под большим трафиком, и вы привязаны к процессору. В Amazon EC2 вы даже можете испытывать медленный ввод-вывод EBS (поскольку EBS является сетевой системой хранения). Независимо от того, когда вы видите длительные периоды непрерывной очереди запросов,часто бывает полезно исключить, что * любой * внешний ресурс, от которого зависит ваше приложение, является узким местом. Вообще говоря, вы, как правило, обнаружите, что что-то действительно тормозит, если вы посмотрите достаточно усердно.
Если вы видите большие «пики» в очереди запросов, я рекомендую проверить следующие элементы, как минимум:
* Изучите использование процессора во всех случаях. Процессоры заняты?
* Изучите использование памяти во всех случаях. Вы используете своп? (ssh, выпустите ‘free -m’, чтобы увидеть)
* Проверьте / var / log / syslog на наличие признаков перезапуска Passenger или /data/appname/log/unicorn*.log на наличие признаков перезапуска Unicorn. Если вы используете Passenger, был ли недавно перезапущен nginx или был затронут tmp / restart.txt?
* Вы только что случайно выдвинули развертывание? Это приводит к перезагрузке рабочих приложений, что может привести к тому, что запросы будут поставлены в очередь, пока новые рабочие будут работать быстрее.
* Проверьте журналы приложений на наличие повторяющихся стековых трассировок.
* Посмотрите на любые базы данных, которые использует ваше приложение, и проверьте наличие медленного журнала запросов. Например, на главном или подчиненном сервере базы данных MySQL вы можете посмотреть /db/mysql/log/slow_query.log. Здесь перечислены медленные запросы? Они выполняются в медленных запросах?
* Срок действия вашего кэша недавно истек и его необходимо восстановить? Если у вас есть внешний кеш (например, CDN, CloudFlare), «недавно» ли он «нажал» на вашем сервере / приложении свежие данные?
Хотя приведенное выше не является исчерпывающим списком, с него можно начать, чтобы дать вам хорошее представление о том, что можно исследовать.
Очередь запросов
В отличие от этого, очередность запросов — это фактическая мера того, сколько HTTP-запросов находится внутри сокета Unix или главного процесса Passenger и ожидает, когда их ожидает рабочий процесс приложения, и как долго в среднем эти запросы простаивают. прежде чем работать.
В этой статье мы рассмотрим два разных сервера приложений: Passenger (v3) и Unicorn. Если не вдаваться в подробности, основное различие в маршрутизации запросов заключается в том, что с нашей конфигурацией Passenger по умолчанию запросы принимаются nginx, заголовок добавляется, как показано выше, а затем перенаправляется в основной процесс Passenger для «балансировки» между рабочими в его бассейн. С Unicorn запросы помещаются непосредственно в Unix-сокет на локальной машине, куда рабочие Unicorn идут и вытаскивают запрос прямо из сокета по собственному желанию.
Но что произойдет, если запросы обрабатываются не так быстро, как они накапливаются? Вот что на самом деле представляет собой очередь запросов. В этом случае запросы будут «стоять в очереди» внутри главного процесса Пассажира или сокета Unix, ожидая, когда рабочий станет доступным.
Таким образом, возникает вопрос: если вы подозреваете фактическую очередь запросов (а не задержку), как вы можете проверить свои рабочие процессы и их различные механизмы организации очередей, чтобы увидеть, происходит ли это?
Пассажир
Это действительно легко с Пассажиром: просто введите «статус пассажира» в командной строке:
app i-xxxxxxxx ~ # passenger-status ----------- General information ----------- max = 16 count = 7 active = 0 inactive = 7 Waiting on global queue: 0 ----------- Application groups ----------- /data/appname/current: App root: /data/appname/current * PID: 5660 Sessions: 0 Processed: 235 Uptime: 17m 18s * PID: 17067 Sessions: 0 Processed: 2654 Uptime: 3h 46m 33s * PID: 30527 Sessions: 0 Processed: 401 Uptime: 46m 56s * PID: 17070 Sessions: 0 Processed: 2942 Uptime: 3h 46m 33s * PID: 17088 Sessions: 0 Processed: 3854 Uptime: 3h 46m 25s * PID: 17061 Sessions: 0 Processed: 1383 Uptime: 3h 46m 33s * PID: 17073 Sessions: 0 Processed: 3243 Uptime: 3h 46m 33s
Вы увидите вывод, который показывает вам большую информацию о каждом работнике Passenger — сколько времени он прошел, сколько запросов было обработано и, да, сколько запросов фактически находится в очереди. Вы можете смотреть это в течение нескольких минут автоматически, выдав «watch passenger-status». Команда будет автоматически перезапускаться каждые две секунды, и результат будет отображаться на вашем экране. Это гораздо более простой способ быстрого взгляда, но может быть немного сложнее иметь дело программно.
Теперь есть две вещи, которые нужно посмотреть здесь. В разделе «Общая информация» статуса пассажира мы видим, что Global Queuing действительно включен. Это значение по умолчанию для нашей платформы. Короче говоря, глобальная организация очередей в основном заставляет Passenger вытягивать все запросы из одной и той же очереди. В противном случае у каждого работника Passenger есть своя собственная личная очередь, и мастер будет пересылать запросы тому процессу, который имеет наименьшее количество запросов в своей очереди. Мы встречали ситуации, когда Passenger может быть немного нестабильным, поэтому в некоторых случаях может помочь простой перезапуск (/etc/init.d/nginx restart). Если это не помогает, задайте себе несколько вопросов:
* Ваши запросы зависят от внешнего веб-сервиса или API? Это вниз или медленно?
* Ваша база данных работает так же быстро, как обычно?
* Как нагрузка ввода-вывода EBS на экземпляр? Был ли у Amazon еще одно «событие»?
* Кто-нибудь в вашей команде недавно развернул код?
* Это развертывание все еще происходит случайно? (tail -f /home/deploy/appname-deploy.log)
* Какова нагрузка на экземпляр? Вы ограничены памятью или процессором?
Общая идея состоит в том, чтобы найти узкое место, устранить его и пересмотреть. И все, от чего зависит ваше приложение, является потенциальным узким местом — даже общая задержка через сам Интернет может вызвать каскадные эффекты во всем приложении.
Unicorn
Напротив, Unicorn требует от вас небольшого кода для проверки состояния его сокета Unix. Используя Raindrops, одну из зависимостей Unicorn, мы можем открыть сокет Unix, в который nginx помещает все входящие запросы, и посмотреть, что внутри него. Вот пример сценария, который вы можете использовать, который также доступен на github: https://github.com/jaustinhughey/unicorn-status
require 'rubygems'
require 'unicorn'
# Usage for this program
def usage
puts "ruby unicorn_status.rb "
puts "Polls the given Unix socket every interval in seconds. Will not allow you to drop below 3 second poll intervals."
puts "Example: ruby unicorn_status.rb /var/run/engineyard/unicorn_appname.sock 10"
end
# Look for required args. Throw usage and exit if they don't exist.
if ARGV.count < 2
usage
exit 1
end
# Get the socket and threshold values.
socket = ARGV[0]
threshold = (ARGV[1]).to_i
# Check threshold - is it less than 3? If so, set to 3 seconds. Safety first!
if threshold.to_i < 3
threshold = 3
end
# Check - does that socket exist?
unless File.exist?(socket)
puts "Socket file not found: #{socket}"
exit 1
end
# Poll the given socket every THRESHOLD seconds as specified above.
puts "Running infinite loop. Use CTRL+C to exit."
puts "------------------------------------------"
loop do
Raindrops::Linux.unix_listener_stats([socket]).each do |addr, stats|
header = "Active Requests Queued Requests"
puts header
puts stats.active.to_s + stats.queued.to_s.rjust(header.length - stats.active.to_s.length)
puts "" # Break line between polling intervals, makes it easier to read
end
sleep threshold
end
Этот скрипт просматривает данный сокет Unicorn каждые N секунд, как указано в командной строке, и дает вам общее представление о том, что внутри него. Мы рекомендуем держать интервал опроса достаточно низким (определенно не быстрее, чем каждые три секунды), так как чем чаще вы опрашиваете сокет, тем выше вероятность того, что вы серьезно ухудшите производительность машины.
Используя этот скрипт было бы довольно просто. Вы можете использовать wget, чтобы поместить его в экземпляр, как описано в readme в его репозитории GitHub, а затем запустить его так:
ruby unicorn_status.rb /path/to/your/unicorn/socket.sock 10
Обычно мы храним сокеты Unicorn в /var/run/engineyard/unicorn_appname.sock, где appname — это имя вашего приложения. Еще один способ найти это — взглянуть на вышеприведенное определение в /etc/nginx/servers/appname.conf (опять же, appname является заменой имени вашего приложения). Первые несколько строк должны определять восходящий поток, который выглядит следующим образом:
upstream upstream_todo {
server unix:/var/run/engineyard/unicorn_todo.sock fail_timeout=0;
}
Здесь вы можете видеть, что в этом случае nginx собирается прокси-запросы в /var/run/engineyard/unicorn_todo.sock. Вот где вы можете указать приведенный выше скрипт:
ruby unicorn_status.rb /var/run/engineyard/unicorn_todo.sock 10
Вы увидите вывод, похожий на следующий:
app_master i-143b2f69 ~ # ruby unicorn_status.rb /var/run/engineyard/unicorn_todo.sock 10 Running infinite loop. Use CTRL+C to exit. ------------------------------------------ Active Requests Queued Requests 47 0
Если вы подозреваете, что происходит фактическая очередь запросов, а не просто задержка, используйте вышеуказанный скрипт для проверки вашего сокета (если вы используете Unicorn; в противном случае просто используйте «статус пассажира», как упомянуто выше). Это должно дать вам гораздо лучшее представление о том, где может быть проблема, если действительно существует реальная проблема.
Так что мне делать, если нет реальной очереди, но много времени ожидания?
В случаях, когда графики New Relic указывают на большое количество очередей запросов, но вы можете доказать, что их нет, обычно есть несколько вещей, на которые стоит обратить внимание.
Во-первых, вы используете в своем приложении последнюю версию драгоценности New Relic? Мы видели случаи, когда обновление решало проблемы измерения, поэтому мы рекомендуем попробовать это как «низко висящий фрукт» в качестве первого показателя.
У вас есть случайно настроенная конфигурация nginx? Некоторые пользовательские параметры конфигурации nginx могут мешать настройке и времени nginx этого заголовка, в зависимости от того, как они реализованы. Попробуйте отключить или изменить рефакторинг любой имеющейся у вас пользовательской конфигурации и посмотрите, как она влияет на показатели очередности запросов.
Посмотрите на метрики очереди запросов, которые прошли, и посмотрите, сможете ли вы найти общие шаблоны, относящиеся к вашему коду. Они все на одном контроллере или в действии? Они все используют общий before_filter? Как это выглядит before_filter? Если у вас есть промежуточное программное обеспечение Rack, попробуйте временно отключить его, чтобы увидеть, имеет ли это значение.
В качестве примера диагностики вашего приложения для проблем с очередями запросов рассмотрим следующую историю. У нас был один клиент, который столкнулся с этой проблемой. У них был before_filter, выполняемый при каждом запросе, который просматривал UUID в базе данных MySQL. Как вы, возможно, знаете (или не знаете), MySQL не имеет собственного типа данных UUID, как PostgreSQL, поэтому он хранился в виде строки в их базе данных. Кроме того, этот клиент случайно забыл разместить индекс в этом столбце, что означало, что каждый поиск занимал несколько сотен миллисекунд на запрос (и это резко ухудшалось по мере роста компании, поскольку каждый поиск включал полное сканирование таблицы). Как только мы указали на это, они правильно проиндексировали столбец и настроили свой before_filter так, чтобы он выполнялся только для действий, которые в нем абсолютно необходимы,и количество запросов в очереди в New Relic резко сократилось — с ~ 500 мс за запрос до ~ 25 мс.
Отладка New Relic
New Relic поставляется со специальным режимом «отладки», который вы можете включить для своего приложения. Будьте очень осторожны с этим в производстве. Подождите, пока у вас мало трафика, или вы можете сделать вещи хуже, чем они есть. Чтобы использовать его, вам нужно изменить config / newrelic.yml на вашем сервере или рассматриваемых серверах и явно установить log_level для отладки:
# The newrelic agent generates its own log file to keep its logging # information separate from that of your application. Specify its # log level here. log_level: debug
После этого вам нужно будет перезапустить сервер приложений (Passenger / Unicorn). Тогда вы сможете указать -f /data/appname/current/log/newrelic_agent.log, чтобы увидеть, как поступает диагностическая информация.
Как мы уже видели, то, что New Relic называет «очередью запросов», действительно измеряет задержку. Простое присутствие этой задержки не должно вызывать у вас тревогу, если эти цифры не станут действительно очень высокими в периоды трафика с низким или умеренным. Если ваш сайт не работает (а для этого у вас должен быть другой мониторинг), очередь запросов никогда не является причиной для тревоги или экстренного лечения, просто для изучения и корректировки по мере необходимости.
New Relic — чрезвычайно полезный инструмент для диагностики проблем приложений и мониторинга общей производительности. Понимание того, как работают измерения очередей запросов, должно помочь вам более эффективно использовать его и знать, как правильно реагировать на представленные данные.