В прошлой статье я разбирался с тем как работает GIL, а сегодня меня захватила идея узнать насколько дорого обходится этот GIL для кода, который исполняется у нас на бэкенде. Для этого я решил пропатчить MRI и добавить пару переменных, в которых буду засекать сколько времени поток реально выполнял код, а сколько ничего не делал и ждал пока ему удастся завладеть локом.
Для теста была использована кастомная сборка Ruby 2.7.4 (флаги компиляции не изменены, только добавлен новый код), Rails 6.1.4.1 с puma 5.5 в качестве апп сервера с 1 инстансом и 5ю тредами (по умолчанию). Все это дело запускалось на моем ноутбуке HP с 4 ядрами и 8GB RAM, а также на google cloud в регионе us-central2 с инстансом e2-medium (2 vCPU, 4 GB memory). Результаты между локальной машиной и облаком в процентном соотношении примерно равны. Для измерения только рабочих воркеров пумы я еще и ее запатчил, чтобы достучаться до ее тред пула.
В качестве приложения я создал 2 эндпоинта: один для статистики, а другой рабочий
class TestingController < ApplicationController def stats threads = $puma_thread_poll.workers.map do { running: _1.running_time, wait_gvl: _1.wait_gvl_time, gvl_vs_running: (_1.wait_gvl_time / _1.running_time * 100).round(2), }.tap(&:clear_timings) end avg_gvl_vs_running = threads.sum { _1[:gvl_vs_running] } / threads.size render json: { avg_gvl_vs_running: avg_gvl_vs_running, threads: threads } end def do_work # имитирую бурную деятельность с походами в базу и сериализацией # жсона 50.times { User.last } 10.times { make_user } render json: User.last(25).map(&:as_json) end def make_user User.create!(email: "#{SecureRandom.hex}@mail.ru", username: SecureRandom.hex, country_code: "RU", logins_count: rand(10..150)) end end
Методика измерения внутри руби такая: любой поток, перед тем как сможет выполняться, должен взять GIL, а после того как исчерпает свое время, он должен его вернуть. Таким образом я буду замерять 2 промежутка: непосредственно время захвата лока, а так же время между захватом и освобождением.
Код не особо интересен, но вдруг кому-то надо...
Да, да, код картинками, можете начинать хейтить, но так проще
Когда все было приготовлено я 10 раз дернул рабочий эндпоинт руками, чтобы пума подняла все свои воркеры. Время ответа вполне себе приемлимое (выбрал средний результат)
Completed 200 OK in 91ms (Views: 1.3ms | ActiveRecord: 18.6ms | Allocations: 36166)
Затем пошел глянул стату
{ "avg_gvl_vs_running":"16.09%", "threads":[ { "running":423187434.0, "wait_gvl":14709976.0, "gvl_vs_running":"3.48%" }, { "running":494142788.0, "wait_gvl":1916580.0, "gvl_vs_running":"0.39%" }, { "running":1263953814.0, "wait_gvl":35301242.0, "gvl_vs_running":"2.79%" }, { "running":19586474.0, "wait_gvl":10783870.0, "gvl_vs_running":"55.06%" }, { "running":17937350.0, "wait_gvl":3359780.0, "gvl_vs_running":"18.73%" } ] }
Ух ты! Всего лишь 16 процентов времени, что работал воркер, было потрачено впустую! Как вам такое, хейтеры руби? Кажется, гил не такая уж и большая проблема. Для верности нужно провести небольшое нагрузочное тестирование.
ab -n 500 -c 4 http://192.168.100.9:3000/testing/do_work ... Concurrency Level: 4 Time taken for tests: 31.135 seconds Complete requests: 500 Failed requests: 0 (Connect: 0, Receive: 0, Length: 0, Exceptions: 0) Total transferred: 1645986 bytes HTML transferred: 1142366 bytes Requests per second: 16.06 [#/sec] (mean) Time per request: 249.082 [ms] (mean) Time per request: 62.270 [ms] (mean, across all concurrent requests) Transfer rate: 51.63 [Kbytes/sec] received Connection Times (ms) min mean[+/-sd] median max Connect: 4 10 5.6 9 45 Processing: 106 238 87.7 209 633 Waiting: 105 236 87.9 207 632 Total: 115 248 88.4 219 644 Percentage of the requests served within a certain time (ms) 50% 219 66% 233 75% 254 80% 290 90% 362 95% 491 98% 519 99% 546 100% 644 (longest request)
Ага, тут уже среднее время ответа более 200мс, что довольно таки много, интересно что же там в статистике...
{ "avg_gvl_vs_running":"94.936%", "threads":[ { "running":810864938.0, "wait_gvl":714257002.0, "gvl_vs_running":"88.09%" }, { "running":1022361816.0, "wait_gvl":881835262.0, "gvl_vs_running":"86.25%" }, { "running":687098840.0, "wait_gvl":728491848.0, "gvl_vs_running":"106.02%" }, { "running":706853620.0, "wait_gvl":696489552.0, "gvl_vs_running":"98.53%" }, { "running":601701804.0, "wait_gvl":576366940.0, "gvl_vs_running":"95.79%" } ] }
Вот это поворот! 94%!!! А это еще не максимум, там и болше 100 было. Таким образом при нагрузке чуть более чем 18 рпс из-за гила ответ от сервера увеличивается чуть более чем в 2 раза!!! и если убрать гил, то для обработки того же количества клиентов нужно будет в 2 раза меньше воркеров. Что ж, выводы делать не буду, просто оставлю это здесь.
PS: Я не гуру, возможно моя методика подсчета не верна, но мне она кажется логичной. С исправлениями прошу в комментарии.
UPD: Выражаю благодарность Aquahawk за то, что дал мне понять, что 18 рпс это супермало, в виду определенных причин для свего домашнего компа и мелкого гугл клауда я думал что 18 рпс это норм. А ошибка была банальна: запускал сервер в девелопмент режиме, он пишет кучу логов в консоль, после запуска в продакшн режиме я получил результаты получше
ab -n 500 -c 4 http://192.168.100.9:3000/testing/do_work ... Concurrency Level: 4 Time taken for tests: 7.435 seconds Complete requests: 500 Failed requests: 0 (Connect: 0, Receive: 0, Length: 0, Exceptions: 0) Total transferred: 904000 bytes HTML transferred: 817500 bytes Requests per second: 67.25 [#/sec] (mean) Time per request: 59.480 [ms] (mean) Time per request: 14.870 [ms] (mean, across all concurrent requests) Transfer rate: 118.74 [Kbytes/sec] received Connection Times (ms) min mean[+/-sd] median max Connect: 4 22 101.5 11 1305 Processing: 15 37 15.4 35 194 Waiting: 15 35 14.7 33 191 Total: 21 59 102.7 47 1329 Percentage of the requests served within a certain time (ms) 50% 47 66% 50 75% 53 80% 55 90% 61 95% 69 98% 178 99% 247 100% 1329 (longest request)
С локалхоста удалось выжать 327 рпс. Так же стоит отметить что в продакшн моде расход на гил упал до 60% (но иногда там проскакивает больше ста)
{ "avg_gvl_vs_running":57.06, "threads":[ { "running":421967344.0, "wait_gvl":210011148.0, "gvl_vs_running":49.77 }, { "running":357689510.0, "wait_gvl":184854136.0, "gvl_vs_running":51.68 }, { "running":191738150.0, "wait_gvl":148564240.0, "gvl_vs_running":77.48 }, { "running":348492592.0, "wait_gvl":186578158.0, "gvl_vs_running":53.54 }, { "running":357769938.0, "wait_gvl":188994538.0, "gvl_vs_running":52.83 } ] }
