Перетащил виртуалку, на которой тестировал своё приложение с одного хоста на другой и столкнулся с тем, что приложение при старте стало ощутимо медленнее работать. Сперва грешил на то, что я по глупости своей наломал дров, поменяв немного подход к использованию трединга, долго бодался, но кому интересны истории о том, как ты воевал не туда? К делу!

Симптомы

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 и на вычисление не влияет.