При выполнении тестов периодически сталкивался с неожиданными изменениями результатов тестов после рестарта linux и при обновлении версии linux. Причиной оказался источник времени. В статье рассмотрен как влияет источник времени на выполнение explain analyze.
Что такое источник времени
Источник времени (clock source) используется ядром linux и процессами для получения меток времени. Например, linux может маркировать каждый сетевой пакет меткой времени. Также метки используются, чтобы воспроизведение звука и видео было гладким, а не плавающим. Обращение к источникам времени может быть довольно частым. Важны детальность (частота, 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 ). Однако, в последних ядрах используется для калибровки 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. Время активно считывается при включении параметров конфигурации track_wal_io_timing, track_io_timing, track_commit_timestamp.
Рассмотрим пример как источник времени влияет на команду explain analyze.
Создание таблицы для теста:
create table t(pk bigserial, c1 text default 'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
insert into t select *, 'a' from generate_series(1, 100000);
Тестовая команда:
postgres=#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 показывает время выполнения команды 307 миллисекунд.
Заменим источник времени tsc на acpi_pm:
sudo sh -c 'echo acpi_pm>/sys/devices/system/clocksource/clocksource0/current_clocksource'
Выполним команду снова:
postgres=#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
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 микросекунды) это задержка (накладные расходы) на операцию получения времени. 3.931 микросекунды*100000 строк*2 измерения = 786 миллисекунд. Это и есть накладные расходы на получение времени. Проверим это выполнив команду, отключив в команде explain измерение времени:
postgres=#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.
Ускорим выполнение команды, немного поменяв запрос:
postgres=# 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'
Заключение
По умолчанию, источник времени каждый раз выбирается linux при загрузке. Есть вероятность, что будет произвольно выбран медленный источник времени. Такое может произойти и после обновления ядра linux на части архитектур процессоров, если источник времени сочтут проблемным. Вероятность увеличивают: неотключение энергосбережения в BIOS, включение Hyper Threading в BIOS, любая активность оборудования в процессе тестирования источника времени, например, активность Intel ME. Вероятность произвольной замены источника времени высока на виртуальных машинах, так как при загрузке виртуальной машины нагрузка на аппаратуру неравномерна. Наиболее быстрый источник tsc, acpi_pm более медленный. Если обнаружится, что выбирается источник, отличный от tsc, то можно фиксировать желаемый источник времени в параметрах загрузке ядра linux.
Команда explain (analyze) выдает точную длительность выполнения команды при использовании опции timing off. По умолчанию timing on и накладные расходы на использование источника времени искажают результат независимо от источника времени.
