gettimeofday составляет 90% вызываемых сисколлов в KVM, а дело в SQL
Перетащил виртуалку, на которой тестировал своё приложение с одного хоста на другой и столкнулся с тем, что приложение при старте стало ощутимо медленнее работать. Сперва грешил на то, что я по глупости своей наломал дров, поменяв немного подход к использованию трединга, долго бодался, но кому интересны истории о том, как ты воевал не туда? К делу!
Симптомы
time strace -c python3 my-utility.py --threads=2 ...
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
68.87 0.007321 0 544719 gettimeofday
...
100.00 0.010630 565481 87 total
real 0m10.764s
user 0m3.462s
sys 0m7.136s
числа 0.01s в total для syscall’ов из strace не бьются с sys 7.136s из time, но не в этом суть.
На что были подозрения
- баг в logging, типа все logging.debug несмотря на loglevel=INFO вычисляли время для строки.
- странное поведение в используемой библиотеке, которая дожидается ответа из сети, вдруг криво обрабатывает таймауты.
- баг в версии kvm, qemu или чего там ещё у libvirt.
- баг в apparmor вокруг libvirt.
Подсказки
@Stinger_XIII посоветовал статейку. Там у чувака тоже БД в виртуалках притормаживала, правда 8 лет назад и при миграции с CentOS на Ubuntu.
Ему удалось всё значительно улучшить, сменив clocksource внутри виртуальной машины на tsc. Я тоже решил попробовать. По-умолчанию был выбран источник kvm-clock (замер с ним в симптомах).
echo tsc > /sys/devices/system/clocksource/clocksource0/current_clocksource
time strace -c python3 my-utility.py --threads=2 ...
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
99.46 0.026162 1046 25 2 futex
100.00 0.026304 20733 87 total
real 0m1.322s
user 0m0.580s
sys 0m0.318s
9-кратный прирост скорости?
TSC clocksource просто замаскировал проблему
А на деле проблема в том, что я ошибочно считал, что SQLite закэширует значение функции, используемое в блоках WHERE
и ORDER BY
, типа потому что оно не зависит от строки никак (МОГ И ДОГАДАТЬСЯ), а не будет вычислять его на каждую строчку:
SELECT
...
FROM
...
WHERE
STRFTIME('%s', 'now') - updated_at > ttl
ORDER BY
STRFTIME('%s', 'now') - updated_at - ttl
LIMIT
500
Как можно догадаться, в таблице как раз ≈ 544719/2 записей, вычисление времени дёргается на каждую строчку.
Ну и LIMIT 500
применяется после ORDER BY
и на вычисление не влияет.