Краткое сравнение популярных функций измерения времени
Попросил DALL-E нарисовать программиста, выбирающего секундомер. Вот результат)
Решил обновить свою старую крохотную библиотечку для тайминга кода. Измерение коротких временнЫх интервалов в ней выполнялось с помощью: инструкции RDTSC при компиляции MSC для x86 и gettimeofday при сборке GCC под Linux. IMHO, на сегодняшний день это не самые правильные методы, и захотелось объективно выбрать что-то более точное и лёгкое. Для этого были измерены несколько параметров наиболее популярных функций измерения времени. Результатами этих измерений и делюсь с вами (вдруг кому тоже интересно).
Для удобства сравнения в таблице ниже приведены результаты тестирования на одной машине с процессором i7–6700K@4.00GHz, но под двумя ОС: Win10 22H2 и Ubuntu 22.04. Подобные тесты проводились и на других машинах (всего 8 штук включая два Raspberry Pi: 1B+ и 4B), но расширять таблицу не стал, результаты аналогичные. Все числа в статье замерены на указанной выше тестовой машине!
В таблице ниже все значения указаны в микросекундах. Discreteness — минимальный прирост показаний функции (очень грубо говоря это точность измерения), Duration — длительность вызова самой функции (overhead), One tick — значение единицы измерения, Type — тип функции (мировое время, время потока или процесса).
Краткие (если получится) замечания по наиболее популярным функциям измерения времени:
clock () [С89] — Описываю исключительно из уважения к этой древнейшей функции, которая появилась ещё в первой редакции ANSI C и предназначалась как раз для точного измерения интервалов времени. По стандарту функция должна возвращать «processor time used by the program so far», но по историческим причинам её реализация у Microsoft не соответствует стандарту и возвращает «the elapsed time since the CRT initialization at the start of the process». Это различие не имело значения в одно-процессных ОС (например, в MS DOS), но принципиально для современных многозадачных ОС. Так что для портируемых приложений эта функция не годится. Кроме того, «правильная» реализация функции в Linux ну оооочень медленная (длительность вызова 960ns (!!!) против 36ns на Windows). Вообще все функции, возвращающие время, связанное с процессом или потоком, очень неспешны, видимо их реализация требует перехода в режим ядра, а это, как известно, операция дорогая. Дискретность функции сегодня тоже не удовлетворительна (1ms в Windows и 1µs в POSIX).
timespec_get () [C11] — Позволяет получать системное время в наносекундах. Но не следует путать единицы измерения и точность — в Windows эта функция имеет дискретность 100ns, а в Linux зависит от железа (22ns на тестовой машине и 1,1µs (!!!) на Raspberry Pi 1B+). То, что функция возвращает системное время, делает её не монотонной — система может корректировать время (даже назад).
std: chrono [C++11] — функции now () классов high_resolution_clock и steady_clock достаточно лёгкие и позволяют получать время в наносекундах (см. комментарий к timespec_get ()). В стандарте оговаривается, что high_resolution_clock предоставляет наиточнейшее измерение времени, но есть нюанс, эти часы не обязаны быть steady. В Linux high_resolution_clock является синонимом для system_clock, а значит зависит от коррекции времени, как и timespec_get, короче говоря, в Linux время измеренное high_resolution_clock может уменьшаться! Зачем так сделано не знаю. В Windows этот класс является синонимом steady_clock и потому является монотонным. На исследованных платформах дискретность и длительность измерения времени с помощью всех классов std: chrono оказались одинаковы и соответствуют timespec_get (). В большинстве случаев можно прямо использовать steady_clock и не связываться с high_resolution_clock.
gettimeofday () [POSIX] — позволяет получать время в микросекундах. На сегодня считается устаревшей — «POSIX.1–2008 marks gettimeofday () as obsolete, recommending the use of clock_gettime () instead». Упоминаю её лишь потому, что она часто используется в примерах из интернета.
clock_gettime (CLOCK_MONOTONIC_RAW) [Linux] — видимо лучший вариант для тайминга в LinuxAPI. Точность и время выполнения около 22ns.
QueryPerformanceCounter () [WinAPI] — хороший и очень популярный вариант из WinAPI. Функция монотонна, дискретность — 100ns (хотелось бы поменьше), время выполнения — 13ns (!).
RDTSC/RDTSCP — для измерения интервалов времени на x86 процессорах часто рекомендуют эти инструкции. На тестовой машине они выполняются за 6,4/9,2ns (при частоте процессора 4,0GHz это примерно 26/37 тактов). TSC приписывают несколько проблем: а) счётчик может обновляться с непостоянной скоростью; б) на разных ядрах они могут быть не синхронизированы; в) процессор может переупорядочить инструкции, возвращающие значение счётчика.
cntvct_el0 — Counter-timer Virtual Count регистр ARM процессора. В таблицу не попал, но был испытан на RPi 4B. Доступен в пользовательском режиме и показывает дискретность равную 18,5ns при длительности вызова 5.0ns (для процессора с частотой 1.8GHz это примерно 33 и 9 тактов). Пример кода для чтения этого регистра:
inline uint64_t vi_get_cntvct()
{ uint64_t result;
__asm__ __volatile__("mrs %0, cntvct_el0" : "=r"(result));
return result;
}
Чуть подробнее про упомянутые выше проблемы TSC на x86 процессоре
Первая проблема — уже не проблема: «For Pentium 4 processors, Intel Xeon processors <…>; for Intel Core Solo and Intel Core Duo processors <...>; for the Intel Xeon processor 5100 series and Intel Core 2 Duo processors <...>; for Intel Core 2 and Intel Xeon processors <…>; for Intel Atom processors <…>: the time-stamp counter increments at a constant rate»(Intel® 64 and IA-32 Architectures Software Developer«s Manual Combined Volumes: 1, 2A, 2B, 2C, 2D, 3A, 3B, 3C, 3D, and 4. Vol. 3B. P.18–42)
Вторую проблему рекомендуют уменьшить двумя способами:
Использовать сочетание инструкций RDTSCP и LFANCE: «The RDTSCP instruction is not a serializing instruction, but it does wait until all previous instructions have executed <…> If software requires RDTSCP to be executed prior to execution of any subsequent instruction (including any memory accesses), it can execute LFENCE immediately after RDTSCP» (Intel® 64 and IA-32 Architectures Software Developer«s Manual Combined Volumes: 1, 2A, 2B, 2C, 2D, 3A, 3B, 3C, 3D, and 4. Vol. 2B. P.4–553). Если я правильно понял, то рекомендуется нечто подобное коду ниже (при включении соответствующих заголовочных файлов эти intrinsic функции компилируются и в GCC, и в MSC):
inline uint64_t vi_get_tsc()
{ uint32_t aux; // Будет удалён оптимизатором
const uint64_t result = __rdtscp(&aux);
_mm_lfence();
return result;
}Другой популярный в интернете совет сериализации инструкций в ассемблере — использовать CPUID:
inline uint64_t vi_get_tsc()
{ int32_t cpuInfo[4]; // Будет удалён оптимизатором
uint32_t aux;
const uint64_t result = __rdtscp(&aux);
__cpuid(cpuInfo, 0);
return result;
}
Но! При использовании CPUID под Windows я столкнулся с непонятным поведением. Указанные в таблице 32ns для
Как проводились измерения
Утилита запускалась с приоритетом ABOVENORMAL (nice -n -5). Перед всеми измерениями процессор прогревался полсекунды при 100% загрузке рабочего потока. Потом вызвалась функция std: this_thread: yield () это наивная попытка предотвратить переключение контекста если измерение укладывается в один квант времени (к сожалению, это не защищает от системных прерываний). Далее 5 раз вызывались задействованные в тесте функции и данные, чтобы исключить из измерений время подгрузки в кэш процессора. Замеры проводились дважды с разным числом повторов для учёта накладных расходов. Наконец все измерения производились по 20 раз и за результат бралось медианное значение (обычно оно очень близко к минимальному).
Итоги
Никаких открытий сделано не было (и не ожидалось). Для себя сделал выбор функции примерно таким образом (надеюсь на критику профи):
#include
#ifdef _MSC_VER
# include
# pragma intrinsic(__rdtscp, _mm_lfence)
#elif defined(__GNUC__)
# include
#endif
#ifdef __cplusplus
extern "C" {
#endif
# if defined(_M_X64) || defined(_M_AMD64) || defined(__x86_64__) || defined(__amd64__)
// MSC or GCC on Intel
static inline uint64_t vi_tmGetTicks(void)
{ uint32_t _; // будет удалён оптимизатором
const uint64_t result = __rdtscp(&_);
_mm_lfence();
return result;
}
# elif __ARM_ARCH >= 8 // ARMv8 (RaspberryPi4)
static inline uint64_t vi_tmGetTicks(void)
{ uint64_t result;
__asm__ __volatile__("mrs %0, cntvct_el0" : "=r"(result));
return result;
}
# elif defined(_WIN32) // Windows on other platforms.
static inline uint64_t vi_tmGetTicks(void)
{ LARGE_INTEGER cnt;
QueryPerformanceCounter(&cnt);
return cnt.QuadPart;
}
# elif defined(__linux__) // Linux on other platforms
static inline uint64_t vi_tmGetTicks(void)
{ struct timespec ts;
clock_gettime(CLOCK_MONOTONIC_RAW, &ts);
return 1000000000ULL * ts.tv_sec + ts.tv_nsec;
}
# else
# error "You need to define function(s) for your OS and CPU"
# endif
#ifdef cplusplus
} // extern "C" {
#endif Буду благодарен за конструктивные замечания.
Спасибо, что дочитали)
P.S.
Ещё пара логов с других машин:
i3–4005U CPU @ 1.70GHz
Start: 2024.05.05 20:11:01
Processor: Intel(R) Core(TM) i3-4005U CPU @ 1.70GHz
Collecting function properties... Done (872.0s )
Measured properties of time functions (median of 5 measurements):
Name:............................................ Discreteness: +/- Duration: +/- One tick: +/- Type:
vvvvvv
::timeGetTime():............................ 15.6ms 0.5% 25.0ns 1.7% 1.0ms 0.1% Wall
::timeGetSystemTime():...................... 15.6ms 0.5% 29.0ns 0.8% 1.0ms 0.1% Wall
::_time64():................................ 1.0s 0.0% 18.0ns 21.0% 1.0s 0.0% Wall
::_time32():................................ 1.0s 0.0% 18.0ns 4.6% 1.0s 0.0% Wall
::QueryUnbiasedInterruptTimePrecise():...... 100.0ns 0.0% 42.0ns 0.0% 100.0ns 0.0% Wall
::QueryUnbiasedInterruptTime():............. 15.6ms 0.0% 15.0ns 38.0% 100.0ns 0.0% Wall
::QueryThreadCycleTime():................... 880.0ns 0.2% 910.0ns 0.3% 590.0ps 0.0% Thread
::QueryProcessCycleTime():.................. 8.5us 10.0% 8.2us 4.6% 590.0ps 0.0% Process
::QueryPerformanceCounter():................ 100.0ns 0.0% 28.0ns 0.0% 100.0ns 0.0% Wall
::QueryInterruptTimePrecise():.............. 100.0ns 0.2% 41.0ns 3.6% 100.0ns 0.0% Wall
::QueryInterruptTime():..................... 15.6ms 0.0% 2.1ns 86.0% 100.0ns 0.0% Wall
::NtQuerySystemTime():...................... 15.6ms 0.0% 4.4ns 23.0% 100.0ns 0.0% Wall
::GetTickCount64():......................... 15.6ms 0.0% 14.0ns 57.0% 1.0ms 0.1% Wall
::GetTickCount():........................... 15.6ms 0.5% 13.0ns 42.0% 1.0ms 0.1% Wall
::GetThreadTimes():......................... 15.6ms 0.0% 890.0ns 0.3% 100.0ns 1.2% Thread
::GetSystemTimes() K+U:..................... 8.6ms 7.5% 3.2us 1.4% 25.0ns 0.9% Wall
::GetSystemTimePreciseAsFileTime():......... 100.0ns 0.0% 48.0ns 0.0% 100.0ns 0.0% Wall
::GetSystemTimeAsFileTime():................ 15.6ms 0.0% 14.0ns 14.0% 100.0ns 0.0% Wall
::GetSystemTime():.......................... 15.6ms 0.0% 130.0ns 0.3% 100.0ns 0.1% Wall
::GetProcessTimes():........................ 15.6ms 0.0% 1.0us 1.8% 100.0ns 0.0% Process
::GetLocalTime():........................... 15.6ms 0.0% 190.0ns 0.3% 100.0ns 0.1% Wall
::timespec_get(TIME_UTC):................... 100.0ns 0.0% 73.0ns 3.8% 1.0ns 0.0% Wall
::time():................................... 1.0s 0.0% 18.0ns 4.3% 1.0s 0.0% Wall
::clock():.................................. 1.0ms 0.0% 85.0ns 4.1% 1.0ms 0.0% Wall
::system_clock::now():...................... 100.0ns 0.0% 45.0ns 0.0% 100.0ns 0.0% Wall
::steady_clock::now():...................... 100.0ns 0.0% 36.0ns 0.0% 1.0ns 0.0% Wall
::high_resolution_clock::now():............. 100.0ns 0.0% 36.0ns 0.0% 1.0ns 0.0% Wall
::cpu_timer.elapsed() wall:................. 1.1us 0.1% 1.1us 3.0% 1.0ns 0.0% Wall
::cpu_timer.elapsed() user + system:........ 15.6ms 0.0% 1.1us 0.1% 1.0ns 0.0% Process
::RDTSC_INTRINSIC:.......................... 14.2ns 0.0% 14.0ns 0.0% 590.0ps 0.0% Wall
::RDTSC_ASM:................................ 14.2ns 1.0% 14.0ns 0.0% 590.0ps 0.0% Wall
::RDTSCP_INTRINSIC:......................... 19.5ns 0.0% 18.0ns 0.0% 590.0ps 0.0% Wall
::RDTSCP_ASM:............................... 21.2ns 1.1% 19.0ns 0.0% 590.0ps 0.0% Wall
::RDTSCP+LFENCE_INTRINSIC:.................. 32.6ns 0.0% 31.0ns 0.0% 590.0ps 0.0% Wall
::RDTSCP+LFENCE_ASM:........................ 33.6ns 0.0% 33.0ns 0.0% 590.0ps 0.0% Wall
::RDTSCP+CPUID_INTRINSIC:................... 79.0ns 0.0% 79.0ns 1.2% 590.0ps 0.0% Wall
::RDTSCP+CPUID_ASM:......................... 80.1ns 0.0% 79.0ns 0.1% 590.0ps 0.0% Wall
::MFENCE+LFENCE+RDTSC_INTRINSIC:............ 36.8ns 0.0% 39.0ns 0.0% 590.0ps 0.0% Wall
::MFENCE+LFENCE+RDTSC_ASM:.................. 40.7ns 0.0% 40.0ns 0.0% 590.0ps 0.0% Wall
::LFENCE+RDTSC_INTRINSIC:................... 21.1ns 2.2% 19.0ns 5.4% 590.0ps 0.0% Wall
::LFENCE+RDTSC_ASM:......................... 22.4ns 0.0% 21.0ns 0.0% 590.0ps 0.0% Wall
::CPUID+RDTSC_INTRINSIC:.................... 64.9ns 0.7% 67.0ns 0.0% 590.0ps 0.0% Wall
::CPUID+RDTSC_ASM:.......................... 68.4ns 0.0% 67.0ns 0.0% 590.0ps 0.0% Wall
Notes:
The std::chrono::system_clock::is_steady: false;
The std::chrono::steady_clock::is_steady: true;
The std::chrono::high_resolution_clock::is_steady: true;
The std::chrono::system_clock::duration: 100.0ns;
The std::chrono::steady_clock::duration: 1.0ns;
The std::chrono::high_resolution_clock::duration: 1.0ns;
The number of clock vi_tmGetTicks per second 'CLOCKS_PER_SEC': 1'000 (what is equivalent to 1.0ms)
Frequency of the performance counter 'QueryPerformanceFrequency()': 10'000'000 (what is equivalent to 100.0ns);
The timer resolution 'NtQueryTimerResolution()': 15.6ms. (from 0.5 to 15.6ms);
The timer device to determine its resolution 'timeGetDevCaps()': from 1 to 1'000'000ms.;
Periodic time adjustments 'GetSystemTimeAdjustment()':
TimeAdjustment = 15.6ms;
TimeIncrement = 15.6ms;
TimeAdjustmentDisabled = true;
Time expend: 00:14:33
Cortex-A72 1.8GHz (Raspberry Pi 4B)
Start: 2024.05.29 16:08:46
Model name: Cortex-A72
CPU max MHz: 1800.0000
CPU min MHz: 600.0000
Computer: 'RaspberryPi4'
Collecting function properties... Done (1.5ks)
Measured properties of time functions (median of 20 measurements):
Name:............................................ Discreteness: +/- Duration: +/- One tick: +/- Type:
vvvvvv
::times(tms):............................... 10.0ms 0.0% 870.0ns 0.5% 10.0ms 0.8% Process
::times(nullptr):........................... 10.0ms 0.0% 400.0ns 0.0% 10.0ms 0.0% Wall
::gettimeofday():........................... 1.0us 0.0% 44.0ns 0.3% 1.0us 0.0% Wall
::getrusage(RUSAGE_THREAD):................. 4.0ms 0.0% 680.0ns 0.3% 1.0us 0.0% Thread
::getrusage(RUSAGE_SELF):................... 1.1us 0.4% 1.1us 0.2% 1.0us 0.0% Process
::clock_gettime(CLOCK_THREAD_CPUTIME_ID):... 747.0ns 0.9% 750.0ns 0.3% 1.0ns 0.0% Thread
::clock_gettime(CLOCK_TAI):................. 48.3ns 0.1% 45.0ns 0.1% 1.0ns 0.0% Wall
::clock_gettime(CLOCK_REALTIME_COARSE):..... 4.0ms 0.0% 18.0ns 0.2% 1.0ns 0.0% Wall
::clock_gettime(CLOCK_REALTIME):............ 48.3ns 0.1% 45.0ns 0.3% 1.0ns 0.0% Wall
::clock_gettime(CLOCK_PROCESS_CPUTIME_ID):.. 773.0ns 0.9% 790.0ns 0.5% 1.0ns 0.0% Process
::clock_gettime(CLOCK_MONOTONIC_RAW):....... 48.5ns 7.0% 46.0ns 12.0% 1.0ns 0.0% Wall
::clock_gettime(CLOCK_MONOTONIC_COARSE):.... 4.0ms 0.0% 18.0ns 0.2% 1.0ns 0.0% Wall
::clock_gettime(CLOCK_MONOTONIC):........... 48.3ns 0.2% 45.0ns 0.2% 1.0ns 0.0% Wall
::clock_gettime(CLOCK_BOOTTIME):............ 48.3ns 0.2% 45.0ns 2.8% 1.0ns 0.0% Wall
::timespec_get(TIME_UTC):................... 47.3ns 9.5% 44.0ns 12.0% 1.0ns 0.0% Wall
::time():................................... 1.0s 0.0% 22.0ns 2.0% 1.0s 0.0% Wall
::clock():.................................. 1.0us 0.0% 780.0ns 0.3% 1.0us 0.0% Process
::system_clock::now():...................... 46.7ns 12.0% 44.0ns 7.6% 1.0ns 0.0% Wall
::steady_clock::now():...................... 46.7ns 13.0% 43.0ns 0.6% 1.0ns 0.0% Wall
::high_resolution_clock::now():............. 46.7ns 12.0% 43.0ns 1.3% 1.0ns 0.0% Wall
::MRS:...................................... 18.9ns 0.2% 5.0ns 0.7% 19.0ns 0.0% Wall
Notes:
The std::chrono::system_clock::is_steady: false;
The std::chrono::steady_clock::is_steady: true;
The std::chrono::high_resolution_clock::is_steady: false;
The std::chrono::system_clock::duration: 1.0ns;
The std::chrono::steady_clock::duration: 1.0ns;
The std::chrono::high_resolution_clock::duration: 1.0ns;
The number of clock vi_tmGetTicks per second 'CLOCKS_PER_SEC': 1'000'000 (what is equivalent to 1.0us)
The number of clock vi_tmGetTicks per second 'sysconf(_SC_CLK_TCK)': 100 (10ms);
Resolution (precision) 'clock_getres(CLOCK_REALTIME)': 1.0ns;
Resolution (precision) 'clock_getres(CLOCK_MONOTONIC)': 1.0ns;
Resolution (precision) 'clock_getres(CLOCK_PROCESS_CPUTIME_ID)': 1.0ns;
Resolution (precision) 'clock_getres(CLOCK_THREAD_CPUTIME_ID)': 1.0ns;
Time expend: 00:25:14 