Поведение журнала ожидания веб-сервера Puma - PullRequest
1 голос
/ 24 октября 2019

Это на Heroku, но на данный момент я не думаю, что это связано именно с этим. Мы также используем драгоценный камень стойки, который должен убивать процессы через 30 секунд. Пожалуйста, посмотрите ниже, почему в некоторых случаях этого не происходит.

У нас очень большой пул рабочих / нитей пумы, 5 рабочих и 20 потоков на одного рабочего. Во время этой проблемы, как уже упоминалось, у нас было 5 запущенных динамов героку, так что всего было бы 500 экземпляров пумы, доступных для рабочих запросов. С этим количеством мне очень трудно поверить, что несколько длительных запросов вызвали такое большое число 503.

Я настроил метрики puma и добавил их в пользовательский поток регистрации, и вот примерснимка, где у нас был скачок в 503 с этого утра, где результаты отставания пумы являются странными:

Oct 24 09:06:56 app app[web] info "source=web.1.worker.28 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:06:56 app app[web] info "source=web.1.worker.54 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:06:56 app app[web] info "source=web.1.worker.72 sample#puma.backlog=99 sample#puma.running=20"
Oct 24 09:06:56 app app[web] info "source=web.1.worker.90 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:06:57 app app[web] info "source=web.3.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:06:57 app app[web] info "source=web.3.worker.29 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:06:57 app app[web] info "source=web.3.worker.40 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:06:57 app app[web] info "source=web.3.worker.51 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:06:57 app app[web] info "source=web.3.worker.62 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.4.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.4.worker.29 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.4.worker.40 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.4.worker.51 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.4.worker.62 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.2.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.2.worker.34 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.2.worker.50 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.2.worker.66 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.2.worker.82 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:05 app app[web] info "source=web.5.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:05 app app[web] info "source=web.5.worker.29 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:05 app app[web] info "source=web.5.worker.47 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:05 app app[web] info "source=web.5.worker.69 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:05 app app[web] info "source=web.5.worker.74 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:06 app app[web] info "source=web.1.worker.18 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:06 app app[web] info "source=web.1.worker.28 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:06 app app[web] info "source=web.1.worker.54 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:06 app app[web] info "source=web.1.worker.72 sample#puma.backlog=99 sample#puma.running=20"
Oct 24 09:07:06 app app[web] info "source=web.1.worker.90 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:07 app app[web] info "source=web.3.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:07 app app[web] info "source=web.3.worker.29 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:07 app app[web] info "source=web.3.worker.40 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:07 app app[web] info "source=web.3.worker.51 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:07 app app[web] info "source=web.3.worker.62 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.2.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.2.worker.34 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.2.worker.50 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.2.worker.66 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.2.worker.82 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.4.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.4.worker.29 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.4.worker.40 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.4.worker.51 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.4.worker.62 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:15 app app[web] info "source=web.5.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:15 app app[web] info "source=web.5.worker.29 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:15 app app[web] info "source=web.5.worker.47 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:15 app app[web] info "source=web.5.worker.69 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:15 app app[web] info "source=web.5.worker.74 sample#puma.backlog=0 sample#puma.running=20"

Если на одного работника (например, web.1.worker.72) имеется отставание> = 1,почему puma направляет в него больше запросов, когда, как вы видите, у нас есть другие работники без отставания?

Почему это происходит в течение нескольких минут (полные журналы показывают, что у работника 72 на dyno 1 было отставание> 99в течение более 3 минут):

web.1.worker.72 sample#puma.backlog=99

Обратите внимание, что становится еще хуже:

Oct 24 09:08:26 app app[web] info "source=web.1.worker.72 sample#puma.backlog=153 sample#puma.running=20"

Тогда, наконец, лучше:

Oct 24 09:08:36 app app[web] info "source=web.1.worker.72 sample#puma.backlog=68 sample#puma.running=20"

Затем вернемся к здоровому:

Oct 24 09:08:46 app app[web] info "source=web.1.worker.72 sample#puma.backlog=0 sample#puma.running=20"

503 остановились в 9:08, и мы вернулись к здоровому состоянию, поэтому оно, безусловно, было привязано к этому странному событию, которое длилось несколько минут. У кого-нибудь есть идеи?

Кажется, что масштабирование вообще не поможет ...

...