Сегодня меня захватила идея узнать насколько дорого обходится этот 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: Я не гуру, возможно моя методика подсчета не верна, но мне она кажется логичной.
habr.com
Для теста была использована кастомная сборка 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: Я не гуру, возможно моя методика подсчета не верна, но мне она кажется логичной.
Сколько мы переплачиваем за сервера используя Ruby on Rails
В прошлой статье я разбирался с тем как работает GIL, а сегодня меня захватила идея узнать насколько дорого обходится этот GIL для кода, который исполняется у нас на бэкенде. Для этого я решил...
habr.com