При выполнении тестов периодически сталкивался с неожиданными изменениями результатов тестов после рестарта linux и при обновлении версии linux. Причиной оказался источник времени. В статье рассматривается как источник времени влияет на скорость работы приложений в linux, на примере команды explain analyze.
Как я узнал об источнике времени
Источник времени это не ntp и chrony, о которых все знают. Обновив linux и выполнив тесты я увидел, что часть запросов стала выполняться в несколько раз медленнее, а именно запросы с командой explain analyze. Эта команда используется в PostgreSQL для просмотра плана с выполнением запроса без возврата результата. Передо мной были две виртуальные машины, все установки по умолчанию, отличается только версия linux, всё остальное одинаково, а время выполнения команд различается в несколько раз. Чудес не бывает. В документации про команду explain написано: "может быть существенной дополнительная нагрузка, связанная с функциями измерений EXPLAIN ANALYZE, особенно в системах, где вызов gettimeofday() выполняется медленно. Для измерения этой нагрузки вы можете воспользоваться утилитой pg_test_timing". Я помнил что где-то на материнской плате есть RTC и батарейка CR3032. Но индустрия шагнула вперёд со времён RTC, так я узнал про источники времени.
Что такое источник времени
Источник времени (clock source) используется ядром linux и процессами для получения меток времени. Например, по умолчанию linux маркирует каждый сетевой пакет меткой времени. Также метки используются, чтобы воспроизведение звука и видео было гладким, а не плавающим. То есть источник времени влияет не только на PostgreSQL, но и на любое приложение. Обращение к источникам времени может быть довольно частым. Важны детальность (частота, fine grain) временных меток, реальная точность (drift, jitter), отсутствие рассинхронизации между ядрами процессора, отсутствие выдачи разным процессам меток в обратном порядке, то есть не соответствующем ходу реального времени. Такое возникает из-за низкоуровневой оптимизации out-of-order exeсution. Использование обратного порядка для меток времени может привести к плохо диагностируемым ошибкам в работе программ.
Во время загрузки linux проверяет доступные источники времени и выбирает один для использования. Предпочтителен Time Stamp Counter (TSC). В нём для получения метки используется инструкция процессора RDTSC, по которой в регистре процессора появляется 64-битное целое число кванта (тика, jiffy) времени. Грубо это можно представить как счётчик тактов процессора с момента его обнуления или подачи питания на него. Число обнуляется при сбросе питания, засыпании. Посмотреть параметры источника времени можно командой cat /proc/cpuinfo. Команда может выдать значение rdtsp (у процессора есть регистр, выдающий время TSC) или constant_tsc (процессор нормализует тики, чтобы не зависели от частоты процессора а соответствовали реальному времени).
Проблема в том, что при загрузке linux, особенно в виртуальных машинах, случайным образом может выбираться источник времени acpi_pm, который медленнее tsc.
Следующий по предпочтению источник интегрированный в чипсет: High Precision Event Timer (HPET). Технология была создана Intel и Microsoft. Одна из проблем технологии в том, что время доступа к источнику нивелирует его детальность. HPET запрещен в использовании с процессорами Intel Cofee Lake начиная с версии ядра linux 5.4. Это может быть связано с аппаратными ошибками ( https://bugzilla.kernel.org/show_bug.cgi?id=203183 ). Однако, в последних ядрах linux, HPET используется в целях калибровки TSC. Если HPET отключён в BIOS или запрещен в linux, то для калибровки используются другой способ (PMTIMER). Следующий по предпочтению источник: ACPI Power Management Timer (ACPI_PM, он же PMTIMER). Следующие Programmable Interval Timer (PIT) и Real Time Clock (RTC), но они менее предпочтительны.
Список источников, которые linux счел возможными к использованию:
cat /sys/devices/system/clocksource/clocksource0/available_clocksource
tsc acpi_pmКакой источник времени используется в настоящее время:
cat /sys/devices/system/clocksource/clocksource0/current_clocksource
tscСравнение источников времени в PostgreSQL
Источник времени может активно использоваться процессами экземпляра. Примером является команда explain analyze. Помимо неё время активно считывается при включении параметров конфигурации PosgreSQL: track_io_timing, track_wal_io_timing, track_commit_timestamp. Первый параметр полезен и его часто включают. В документации к первым двум параметрам написано: "параметр по умолчанию отключён, так как для данного замера требуется постоянно запрашивать текущее время у операционной системы, что может значительно замедлить работу на некоторых платформах." Сложно предположить, что такой платформой может оказаться linux, если выберет медленный источник времени.
Рассмотрим пример, как источник времени влияет на команду explain analyze.
Создание таблицы для теста:
create table t(pk bigserial, c1 text default 'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t select *, 'a' from generate_series(1, 100000);Тестовая команда:
explain analyze select count(pk) from t;
Aggregate (cost=1352.50..1352.51 rows=1 width=8) (actual time=307.270..307.276 rows=1 loops=1)
-> Seq Scan on t (cost=0.00..1190.20 rows=64920 width=8) (actual time=0.017..152.937 rows=100000 loops=1)
Planning Time: 0.038 ms
Execution Time: 307.383 ms
(4 rows)Команда explain analyze показывает время выполнения команды 307 миллисекунд.
Заменим источник времени tsc на acpi_pm:
sudo sh -c 'echo acpi_pm>/sys/devices/system/clocksource/clocksource0/current_clocksource'Выполним команду снова:
explain analyze select count(pk) from t;
Aggregate (cost=1352.50..1352.51 rows=1 width=8) (actual time=805.557..805.573 rows=1 loops=1)
-> Seq Scan on t (cost=0.00..1190.20 rows=64920 width=8) (actual time=0.015..399.513 rows=100000 loops=1)
Planning Time: 0.148 ms
Execution Time: 805.792 ms
(4 rows)Время выполнения команды увеличилось с 0.3 до 0.8 секунд, то есть в ~2.8 раз.
На время выполнения простой команды explain analyze заметно повлияло изменение источника времени.
Утилита командной строки pg_test_timing стандартно поставляется с PostgreSQL, используется для измерения скорости источника времени, выдаёт распределение выдаваемых источником времени значений.
pg_test_timing
Testing timing overhead for 3 seconds.
Per loop time including overhead: 3931.22 ns
Histogram of timing durations:
< us % of total count
1 0.02475 497
2 60.52305 1215427
4 39.20322 787281
8 0.02480 498
16 0.08869 1781
...Скрытый текст
Сравнение скорости получения меток времени программой на C
Проверить скорость источника времени можно создав файл clock_timing.c:
#include <time.h>
int main()
{
int rc;
long i;
struct timespec ts;
for(i=0; i<10000000; i++) rc = clock_gettime(CLOCK_MONOTONIC, &ts);
return 0;
}
скомпилировать файл командой:
gcc clock_timing.c -o clock_timing -lrt
и проверить какую нагрузку дает считывание времени 10000000 раз.
Для acpi_pm:
time ./clock_timing
real 0m38.889s
user 0m15.760s
sys 0m23.126s
Для tsc:
time ./clock_timing
real 0m13,967s
user 0m13,938s
sys 0m0,008s
Разница в 2,8 раз.
Можно заменить CLOCK_MONOTONIC на CLOCK_MONOTONIC_COARSE и скорость увеличится в 50 раз.
В примере максимум распределения на ~2.5 микросекундах.
Символами "us" обозначаются микросекунды (µs). Колебания выдачи времени в приведённом выводе утилиты не меньше 1 микосекунды. Это значит, что числа менее 1 микросекунды являются случайными.
3931.22 ns (3.931 микросекунды) это задержка (накладные расходы) на операцию получения времени. Команда explain analyze обращается к источнику времени два раза - до выполнения операции (в запросе select count(pk) from t это обработка строки) и после операции. Для тестовой команды select count(pk) from t расчёт такой:
3.931 микросекунды*100000 строк*2 измерения = 786 миллисекунд.
786мс - это и есть накладные расходы на получение времени для команды. Проверим это, отключив в команде explain измерение времени:
explain (analyze, buffers, timing off) select count(pk) from t;
Aggregate (cost=1791.00..1791.01 rows=1 width=8) (actual rows=1 loops=1)
Buffers: shared hit=541
-> Seq Scan on t (cost=0.00..1541.00 rows/=100000 width=8) (actual rows=100000 loops=1)
Buffers: shared hit=541
Planning:
Buffers: shared hit=65
Planning Time: 0.431 ms
Execution Time: 21.388 ms
(8 rows)786+21.388=807мс, что с хорошей точностью соответствует 805мс, полученных раньше.
С опцией timing off результаты команды explain соответствуют результатам тестов pgbench и выполнению запросов без explain.
Ускорим выполнение команды, немного поменяв запрос:
explain (analyze, buffers, timing off) select count(*) from t;
Aggregate (cost=1791.00..1791.01 rows=1 width=8) (actual rows=1 loops=1)
Buffers: shared hit=541
-> Seq Scan on t (cost=0.00..1541.00 rows=100000 width=0) (actual rows=100000 loops=1)
Buffers: shared hit=541
Planning:
Buffers: shared hit=3
Planning Time: 0.058 ms
Execution Time: 16.357 ms
(8 rows)Если бы стояла задача оптимизации, можно было бы сказать, что задача выполнена: скорость исполнения уменьшилась до 16 мс.
Вернуть источник времени tscможно командой:
sudo sh -c 'echo tsc>/sys/devices/system/clocksource/clocksource0/current_clocksource'Заключение
1) По умолчанию, источник времени каждый раз выбирается linux при загрузке. Есть вероятность, что будет произвольно выбран медленный источник времени. Такое может произойти и после обновления ядра linux на части архитектур процессоров, если источник времени сочтут проблемным. Вероятность увеличивают: неотключение энергосбережения в BIOS, включение Hyper Threading в BIOS, любая активность оборудования в процессе тестирования источника времени при загрузке linux (например, активность Intel ME). Вероятность произвольной замены источника времени высока на виртуальных машинах, так как при загрузке виртуальной машины нагрузка на аппаратуру неравномерна. Наиболее быстрый источник tsc, acpi_pm медленнее в ~2.8 раз. Стоит проверять, какой источник времени используется командой cat /sys/devices/system/clocksource/clocksource0/current_clocksource. Если результат отличается от tsc, то приложения работают медленнее, чем могли бы. Желаемый источник времени можно задать в параметрах загрузки ядра linux.
2) Команда explain (analyze) выдает точную длительность выполнения команды при использовании опции timing off. По умолчанию timing on и накладные расходы на использование источника времени искажают результат независимо от источника времени.