Почему clock_gettime так неустойчиво?
Введение
Раздел Старый вопрос содержит исходный вопрос ( Дальнейшее исследование и Заключение были добавлены с тех пор).
Перейдите к разделу Дополнительные исследования ниже для подробного сравнения различных методов синхронизации (
rdtsc,clock_gettimeиQueryThreadCycleTime).Я считаю, что неустойчивое поведение CGT может быть связано либо с ошибкой ядра, либо с ошибкой процессора (см. раздел Заключение ).
Используемый код для тестирования находится в конце этого вопроса (см. раздел Приложение ).
Извинения за длину.
Старый вопрос
Вкратце : Я использую clock_gettime для измерения времени выполнения многих сегментов кода. Я наблюдаю очень несовместимые измерения между отдельными запусками. Этот метод имеет чрезвычайно высокое стандартное отклонение по сравнению с другими методами (см. Пояснение ниже).
Вопрос : Есть ли причина, по которой clock_gettime дает столь непоследовательные измерения по сравнению с другими методами? Есть ли альтернативный метод с таким же разрешением, который учитывает время простоя потока?
Объяснение : Я пытаюсь профилировать несколько небольших частей кода C. Время выполнения каждого из сегментов кода не более пары микросекунд. За один прогон каждый из сегментов кода будет выполняться несколько сотен раз, что дает прогонов × сотни измерений.
Мне также нужно измерить только время, которое поток фактически тратит на выполнение (что составляет почему rdtsc не подходит). Мне также нужно высокое разрешение (поэтому раз не подходит).
Я пробовал следующие методы:
rdtsc(в Linux и Windows),clock_gettime(с 'CLOCK_THREAD_CPUTIME_ID'; в Linux) иQueryThreadCycleTime(в Windows).
Методология : Анализ проводился на 25 запусках. В каждом прогоне отдельные сегменты кода повторяются 101 раз. Поэтому у меня 2525 измерений. Затем я смотрю на гистограмму измерений, а также вычисляю некоторые базовые данные (например, среднее, стандартное отклонение, медиана, режим, минимум и максимум).
Я не представляю, как я измерил «сходство» из трех методов, но это просто включает базовое сравнение доли времени, затраченного на каждый сегмент кода («пропорция» означает, что время нормализовано). Затем я смотрю на чистые различия в этих пропорциях. Это сравнение показало, что все rdtsc, QTCT и CGT имеют одинаковые пропорции при усреднении по 25 прогонам. Однако приведенные ниже результаты показывают, что «CGT» имеет очень большое стандартное отклонение. Это делает его непригодным для использования в моем случае.
Результаты :
Сравнение clock_gettime с rdtsc для того же сегмента кода (25 запусков 101 измерения = 2525 показаний):
clock_gettime :
- 1881 измерений 11 нс,
- 595 измерений (почти нормальное распределение) между 3369 и 3414 нс,
- 2 измерения 11680 нс,
- 1 измерение составляет 1506022 нс, а
остальное составляет от 900 до 5000 нс.
Мин .: 11 нс
- Макс .: 1506022 нс
- Среднее: 1471,862 нс
- Медиана: 11 нс
- Режим: 11 нс
- Стандартное отклонение: 29991.034
rdtsc (примечание: во время этого запуска не происходило переключения контекста, но если это произойдет,обычно результат всего одного измерения составляет 30000 тиков или около того):
- 1178 измерений между 274 и 325 тактами,
- 306 измерений между 326 и 375 тактами,
- 910 измерений между 376 и 425 тактами,
- 129 измерений от 426 до 990 тиков,
- 1 измерение для 1240 тиков и
1 измерение из 1256 тиков.
Мин .: 274 тика
- Макс .: 1256 тиков
- Среднее: 355,806 тиков
- Медиана: 333 тика
- Режим: 376 тиков
- Стандартное отклонение: 83,896
Обсуждение :
rdtscдает очень похожие результаты как в Linux, так и в Windows. Он имеет приемлемое стандартное отклонение - на самом деле он довольно последовательный / стабильный. Однако он не учитывает время простоя потока. Поэтому переключение контекста делает измерения нестабильными (в Windows я наблюдал это довольно часто: сегмент кода со средним значением в 1000 тиков или около того будет время от времени принимать ~ 30000 тиков - определенно из-за упреждения).QueryThreadCycleTimeдает очень последовательные измерения - т.е. значительно меньшее стандартное отклонение по сравнению сrdtsc. Когда не происходит переключения контекста, этот метод почти идентиченrdtsc.clock_gettime, с другой стороны, дает крайне противоречивые результаты (не только между запусками, но и между измерениями). Стандартные отклонения очень велики (по сравнению сrdtsc).
Надеюсь, статистика в порядке. Но в чем может быть причина такого расхождения в измерениях между двумя методами? Конечно, есть кеширование, миграция процессора / ядра и другие вещи. Но ничто из этого не должно быть причиной каких-либо различий между 'rdtsc' и 'clock_gettime'. Что происходит?
Дальнейшее расследование
Я исследовал это немного дальше. Я сделал две вещи:
Измерял накладные расходы на простой вызов
clock_gettime (CLOCK_THREAD_CPUTIME_ID, & t)(см. Код 1 в Приложении ) ив простом цикле, вызываемом
clock_gettimeи сохранил показания в массиве (см. Код 2 в приложении ). Я измеряю дельта-времена (разница в времени последовательных измерений, которая должна немного соответствовать накладным расходам вызоваclock_gettime).
Я измерил это на двух разных компьютерах с двумя разными версиями ядра Linux:
CGT :
ЦП : Core 2 Duo L9400 @ 1,86 ГГц
Ядро : Linux 2.6.40-4.fc15.i686 # 1 SMP, пт, 29 июля, 18:54:39 UTC 2011 i686 i686 i386
Результаты :
- Расчетные
clock_gettimeнакладные расходы : между 690-710 нс Разница времен ]:
- Среднее значение: 815,22 нс
- Медиана: 713 нс
- Режим: 709 нс
- Мин .: 698 нс
- Макс .: 23359 нс
Гистограмма (оставленные диапазоны имеют частоты 0 ):
Диапазон | Частота ------------------ + ----------- 69778111 <- кэшировано? 800 <х ≤ 1000 -> 16412 1000 <х ≤ 1500 -> 3 1500 4836 <- без кеширования? 2000 <х ≤ 3000 -> 305 3000 <х ≤ 5000 -> 161 5000 <х ≤ 10000 -> 105 10000 <х ≤ 15000 -> 53 15000 <х ≤ 20000 -> 8 20000 <х -> 5
- Расчетные
ЦП : 4-кратный двухъядерный процессор AMD Opteron 275
Ядро : Linux 2.6.26-2-amd64 # 1 SMP Вс, 20 июня, 20:16:30 UTC 2010 x86_64 GNU / Linux
Результаты :
- Расчетные
clock_gettimeнакладные расходы : между 279–283 нс Дельта-времена :
- Среднее значение: 320,00
- Медиана: 1
- Режим: 1
- Мин: 1
- Макс: 3495529
Гистограмма (пропущенные диапазоны имеют частоты 0):
Диапазон | Частота -------------------- + ----------- x ≤ 1 -> 86738 <- кэшировано? 28213118 <- без кеширования? 300 <х ≤ 440 -> 78 2000 <х ≤ 5000 -> 52 5000 <х ≤ 30000 -> 5 3000000 <х -> 8
- Расчетные
RDTSC :
Связанный код rdtsc_delta.c и rdtsc_overhead.c .
ЦП : Core 2 Duo L9400 @ 1,86 ГГц
Ядро : Linux 2.6.40-4.fc15.i686 # 1 SMP Пт 29 июля 18:54:39 UTC 2011 i686 i686 i386
Результаты :
- Предполагаемые накладные расходы : между 39–42 тика
Дельта-времена :
- Среднее: 52,46 тика
- Медиана: 42 тика
- Режим: 42 тика
- Мин .: 35 тиков
- Макс: 28700 тиков
Гистограмма (пропущенные диапазоны имеют частоты 0):
Диапазон | Частота ------------------ + ----------- 3416240 <- кэшировано? 41 63585 <- без кеширования? (небольшая разница) 48 19779 <- без кеширования? 49 <х ≤ 120 -> 195 3125 <х ≤ 5000 -> 144 5000 <х ≤ 10000 -> 45 10000 <х ≤ 20000 -> 9 20000 <х -> 2
ЦП : 4 × двухъядерный процессор AMD Opteron 275
Ядро : Linux 2.6.26-2-amd64 # 1 SMP Вс, 20 июня, 20:16:30 UTC 2010 x86_64 GNU / Linux
Результаты :
- Предполагаемые накладные расходы : от 13,7 до 17,0 тиков
Дельта-времена :
- Среднее: 35,44 тика
- Медиана: 16 тиков
- Режим: 16 тиков
- Мин .: 14 тиков
- Макс .:16372 тика
Гистограмма (пропущенные диапазоны имеют частоту 0):
Диапазон | Частота ------------------ + ----------- 13 <х ≤ 14 -> 192 1478172 <- кэшировано? 21 <х ≤ 50 -> 10818 50 10624 <- без кеширования? 5825 <х ≤ 6500 -> 88 6500 <х ≤ 8000 -> 88 8000 <х ≤ 10000 -> 11 10000 <х ≤ 15000 -> 4 15000 <х ≤ 16372 -> 2
QTCT :
Связанный код qtct_delta.c и qtct_overhead.c .
ЦП : Core 2 6700 @ 2,66 ГГц
Ядро : 64-разрядная версия Windows 7
Результаты :
- Предполагаемые накладные расходы : от 890-940 тиков
Дельта-времена :
- Среднее значение: 1057,30 тиков
- Медиана: 890 тиков
- Режим: 890 тиков
- Мин .: 880 тиков
- Макс .: 29400 тиков
Гистограмма (оставленные диапазоны имеют частоты 0):
Диапазон | Частота ------------------ + ----------- 87971347 <- кэшировано? 895 <х ≤ 1469 -> 844 1469 27613 <- без кеширования? 1600 <х ≤ 2000 -> 55 2000 <х ≤ 4000 -> 86 4000 <х ≤ 8000 -> 43 8000 <х ≤ 16000 -> 10 16000 <х -> 1
Заключение
Я считаю, что ответом на мой вопрос будет ошибка в реализации на моей машине (той, которая оснащена процессорами AMD со старым ядром Linux).
Результаты CGT машины AMD со старым ядром показывают некоторые экстремальные значения. Если мы посмотрим на дельта-времена, мы увидим, что наиболее частая дельта составляет 1 нс. Это означает, что вызов clock_gettime занял менее наносекунды! Более того, он также произвел ряд необычайно больших дельт (более 3000000 нс)! Это кажется ошибочным поведением. (Может быть, неучтенные миграции ядра?)
Примечания:
Накладные расходы CGT и QTCT довольно велики.
Также трудно учесть их накладные расходы, потому что кэширование ЦП, похоже, имеет большое значение.
Возможно, использование RDTSC, привязка процесса к одному ядру и назначение приоритета в реальном времени - самый точный способ узнать, сколько циклов использовалось фрагментом кода ...
Приложение
Код 1 : clock_gettime_overhead.c
#include <time.h>
#include <stdio.h>
#include <stdint.h>
/* Compiled & executed with:
gcc clock_gettime_overhead.c -O0 -lrt -o clock_gettime_overhead
./clock_gettime_overhead 100000
*/
int main(int argc, char **args) {
struct timespec tstart, tend, dummy;
int n, N;
N = atoi(args[1]);
clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tstart);
for (n = 0; n < N; ++n) {
clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
}
clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tend);
printf("Estimated overhead: %lld ns\n",
((int64_t) tend.tv_sec * 1000000000 + (int64_t) tend.tv_nsec
- ((int64_t) tstart.tv_sec * 1000000000
+ (int64_t) tstart.tv_nsec)) / N / 10);
return 0;
}
Код 2 : clock_gettime_delta.c
#include <time.h>
#include <stdio.h>
#include <stdint.h>
/* Compiled & executed with:
gcc clock_gettime_delta.c -O0 -lrt -o clock_gettime_delta
./clock_gettime_delta > results
*/
#define N 100000
int main(int argc, char **args) {
struct timespec sample, results[N];
int n;
for (n = 0; n < N; ++n) {
clock_gettime(CLOCK_THREAD_CPUTIME_ID, &sample);
results[n] = sample;
}
printf("%s\t%s\n", "Absolute time", "Delta");
for (n = 1; n < N; ++n) {
printf("%lld\t%lld\n",
(int64_t) results[n].tv_sec * 1000000000 +
(int64_t)results[n].tv_nsec,
(int64_t) results[n].tv_sec * 1000000000 +
(int64_t) results[n].tv_nsec -
((int64_t) results[n-1].tv_sec * 1000000000 +
(int64_t)results[n-1].tv_nsec));
}
return 0;
}
Код 3 : rdtsc.h
static uint64_t rdtsc() {
#if defined(__GNUC__)
# if defined(__i386__)
uint64_t x;
__asm__ volatile (".byte 0x0f, 0x31" : "=A" (x));
return x;
# elif defined(__x86_64__)
uint32_t hi, lo;
__asm__ __volatile__ ("rdtsc" : "=a"(lo), "=d"(hi));
return ((uint64_t)lo) | ((uint64_t)hi << 32);
# else
# error Unsupported architecture.
# endif
#elif defined(_MSC_VER)
return __rdtsc();
#else
# error Other compilers not supported...
#endif
}
Код 4 : rdtsc_delta .c
#include <stdio.h>
#include <stdint.h>
#include "rdtsc.h"
/* Compiled & executed with:
gcc rdtsc_delta.c -O0 -o rdtsc_delta
./rdtsc_delta > rdtsc_delta_results
Windows:
cl -Od rdtsc_delta.c
rdtsc_delta.exe > windows_rdtsc_delta_results
*/
#define N 100000
int main(int argc, char **args) {
uint64_t results[N];
int n;
for (n = 0; n < N; ++n) {
results[n] = rdtsc();
}
printf("%s\t%s\n", "Absolute time", "Delta");
for (n = 1; n < N; ++n) {
printf("%lld\t%lld\n", results[n], results[n] - results[n-1]);
}
return 0;
}
Код 5 : rdtsc_overhead.c
#include <time.h>
#include <stdio.h>
#include <stdint.h>
#include "rdtsc.h"
/* Compiled & executed with:
gcc rdtsc_overhead.c -O0 -lrt -o rdtsc_overhead
./rdtsc_overhead 1000000 > rdtsc_overhead_results
Windows:
cl -Od rdtsc_overhead.c
rdtsc_overhead.exe 1000000 > windows_rdtsc_overhead_results
*/
int main(int argc, char **args) {
uint64_t tstart, tend, dummy;
int n, N;
N = atoi(args[1]);
tstart = rdtsc();
for (n = 0; n < N; ++n) {
dummy = rdtsc();
dummy = rdtsc();
dummy = rdtsc();
dummy = rdtsc();
dummy = rdtsc();
dummy = rdtsc();
dummy = rdtsc();
dummy = rdtsc();
dummy = rdtsc();
dummy = rdtsc();
}
tend = rdtsc();
printf("%G\n", (double)(tend - tstart)/N/10);
return 0;
}
Код 6 : qtct_delta.c
#include <stdio.h>
#include <stdint.h>
#include <Windows.h>
/* Compiled & executed with:
cl -Od qtct_delta.c
qtct_delta.exe > windows_qtct_delta_results
*/
#define N 100000
int main(int argc, char **args) {
uint64_t ticks, results[N];
int n;
for (n = 0; n < N; ++n) {
QueryThreadCycleTime(GetCurrentThread(), &ticks);
results[n] = ticks;
}
printf("%s\t%s\n", "Absolute time", "Delta");
for (n = 1; n < N; ++n) {
printf("%lld\t%lld\n", results[n], results[n] - results[n-1]);
}
return 0;
}
Код 7 : qtct_overhead.c
#include <stdio.h>
#include <stdint.h>
#include <Windows.h>
/* Compiled & executed with:
cl -Od qtct_overhead.c
qtct_overhead.exe 1000000
*/
int main(int argc, char **args) {
uint64_t tstart, tend, ticks;
int n, N;
N = atoi(args[1]);
QueryThreadCycleTime(GetCurrentThread(), &tstart);
for (n = 0; n < N; ++n) {
QueryThreadCycleTime(GetCurrentThread(), &ticks);
QueryThreadCycleTime(GetCurrentThread(), &ticks);
QueryThreadCycleTime(GetCurrentThread(), &ticks);
QueryThreadCycleTime(GetCurrentThread(), &ticks);
QueryThreadCycleTime(GetCurrentThread(), &ticks);
QueryThreadCycleTime(GetCurrentThread(), &ticks);
QueryThreadCycleTime(GetCurrentThread(), &ticks);
QueryThreadCycleTime(GetCurrentThread(), &ticks);
QueryThreadCycleTime(GetCurrentThread(), &ticks);
QueryThreadCycleTime(GetCurrentThread(), &ticks);
}
QueryThreadCycleTime(GetCurrentThread(), &tend);
printf("%G\n", (double)(tend - tstart)/N/10);
return 0;
}