Почему задержка вызова в clock_gettime(CLOCK_REALTIME, ..) так сильно отличается?

Question

Я пытаюсь определить, как долго clock_gettime(CLOCK_REALTIME,...) берет на звонок. "Назад в тот день" я обычно звонил один раз в начале цикла, так как это был довольно дорогой звонок. Но теперь я надеялся, что с vDSO и некоторыми улучшениями часов, это может быть не так медленно.

Я написал тестовый код, который использовал __rdtscp время повторных звонков clock_gettime (rdtscp звонки шли вокруг цикла, который называется clock_gettime и добавил результаты вместе, просто чтобы компилятор не слишком оптимизировал).

Если я позвоню clock_gettime() в быстрой последовательности продолжительность времени увеличивается примерно с 45000 тактов до 500 циклов. Некоторое из этого, я думал, может быть связано с тем, что при первом вызове нужно было загрузить код vDSO (для меня это еще не до конца понятно), но как мне нужно несколько вызовов, чтобы получить 500, я не могу объяснить вообще, и такое поведение кажется быть постоянным независимо от того, как я это проверяю:

42467
1114
1077
496
455

Однако, если я сплю (в течение секунды или десяти, не имеет значения) между вызовами clock_gettime, он достигает только устойчивого состояния около 4,7 тыс. Циклов:

Вот на 10 секунде спит:

28293
1093
4729
4756
4736

Здесь на 1 секунду спит:

61578
855
4753
4741
5645
4753
4732

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

Я пытаюсь понять, сколько времени требуется, чтобы позвонить clock_gettime(CLOCK_REALTIME,...) не понимаю, почему он работает быстрее, если вызывается в быстрой последовательности, а не между секундами между вызовами.

Обновление: вот cpuinfo на proc 0

processor   : 0
vendor_id   : GenuineIntel
cpu family  : 6
model       : 158
model name  : Intel(R) Core(TM) i7-7700HQ CPU @ 2.80GHz
stepping    : 9
microcode   : 0x84
cpu MHz     : 2800.000
cache size  : 6144 KB
physical id : 0
siblings    : 8
core id     : 0
cpu cores   : 4
apicid      : 0
initial apicid  : 0
fpu     : yes
fpu_exception   : yes
cpuid level : 22
wp      : yes
flags       : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc art arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf tsc_known_freq pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch cpuid_fault epb intel_pt tpr_shadow vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid mpx rdseed adx smap clflushopt xsaveopt xsavec xgetbv1 xsaves dtherm ida arat pln pts hwp hwp_notify hwp_act_window hwp_epp
bugs        :
bogomips    : 5616.00
clflush size    : 64
cache_alignment : 64
address sizes   : 39 bits physical, 48 bits virtual
power management:

Вот воссозданный тестовый код:

#include <time.h>
#include <unistd.h>
#include <stdio.h>
#include <stdlib.h>
#include <x86intrin.h>

// compiled gcc -Wall -O3 -o clockt clockt.cpp
// called glockt sleeptime trials loops

unsigned long long now() {
    struct timespec s;
    clock_gettime(CLOCK_REALTIME, &s);
    return (s.tv_sec * 1000000000ull) + s.tv_nsec;
}

int main(int argc, char **argv) {
    int sleeptime = atoi(argv[1]);
    int trials = atoi(argv[2]);
    int loops = atoi(argv[3]);

    unsigned long long x, y, n = 0;
    unsigned int d;


    x = __rdtscp(&d);
    n = now();
    asm volatile("": "+r" (n));
    y = __rdtscp(&d);

    printf("init run %lld\n", (y-x));

    for(int t = 0; t < trials; ++t) {
        if(sleeptime > 0) sleep(sleeptime);
        x = __rdtscp(&d);
        for(int l = 0; l < loops; ++l) {
            n = now();
            asm volatile("": "+r" (n));
        }
        y = __rdtscp(&d);
        printf("trial %d took %lld\n", t, (y-x));
    }

    exit(0);
}

Answer 1

Самый первый раз clock_gettime вызван сбой страницы на странице, которая содержит инструкции этой функции. В моей системе это ошибка мягкой страницы, и для ее обработки требуется несколько тысяч циклов (до 10000 циклов). Мой процессор работает на частоте 3,4 ГГц. Я думаю, что ваш процессор работает на более низкой частоте, поэтому обработка ошибки страницы в вашей системе займет больше времени. Но дело в том, что первый звонок clock_gettime займет гораздо больше времени, чем последующие звонки, что вы и наблюдаете.

Второй основной эффект, который демонстрирует ваш код, - это значительные задержки из-за пропусков кэша команд. Может показаться, что вы вызываете только две функции, а именно now а также printf, но эти функции вызывают другие функции, и все они конкурируют в кэше команд L1. В целом, это зависит от того, как все эти функции выровнены в физическом адресном пространстве. Когда время ожидания равно нулю секунд, время простоя из-за пропусков кэша команд на самом деле относительно мало (вы можете измерить это, используя ICACHE.IFETCH_STALL счетчик производительности). Однако, когда время ожидания больше нуля секунд, это время задержки становится значительно больше, поскольку ОС запланирует запуск другого потока на том же ядре, и этот поток будет отличаться инструкциями и данными. Это объясняет, почему, когда вы спите, clock_gettime занимает больше времени для выполнения.

Теперь о втором и последующих измерениях. Из вопроса:

42467
1114
1077
496
455

Я заметил в своей системе, что второе измерение не обязательно больше, чем последующие измерения. Я считаю, что это также верно для вашей системы. На самом деле, это похоже на случай, когда вы спите в течение 10 секунд или 1 секунды. Во внешнем цикле две функции now а также printf содержат тысячи динамических инструкций, и они также получают доступ к кэшу данных L1. Изменчивость, которую вы видите между вторым и более поздними измерениями, воспроизводима. Так что это присуще самим функциям. Обратите внимание, что время выполнения rdtscp Сама инструкция может меняться на 4 цикла. Смотрите также это.

На практике clock_gettime полезно, когда желаемая точность составляет не более миллиона циклов. В противном случае это может ввести в заблуждение.

Answer 2

Я не мог воспроизвести ваши результаты. Даже с большим временем ожидания (10 секунд) и небольшим количеством циклов (100) я всегда получаю тактирование менее 100 часов (менее 38 нс в моей системе с частотой 2,6 ГГц).

Например:

./clockt 10 10 100
init run 14896
trial 0 took 8870 (88 cycles per call)
trial 1 took 8316 (83 cycles per call)
trial 2 took 8384 (83 cycles per call)
trial 3 took 8796 (87 cycles per call)
trial 4 took 9424 (94 cycles per call)
trial 5 took 9054 (90 cycles per call)
trial 6 took 8394 (83 cycles per call)
trial 7 took 8346 (83 cycles per call)
trial 8 took 8868 (88 cycles per call)
trial 9 took 8930 (89 cycles per call)

Вне измерения или ошибки пользователя (всегда наиболее вероятная причина) наиболее вероятное объяснение состоит в том, что ваша система не использует rdtsc как источник времени, так и системный вызов. Вы можете настроить источник синхронизации явно самостоятельно, иначе будет использоваться некоторая эвристика, которая выберет rdtsc-основан clock_gettime только если это кажется подходящим в текущей системе.

Вторая наиболее вероятная причина в том, что clock_gettime(CLOCK_REALTIME) не проходит через VDSO в вашей системе, так что системный вызов, даже если rdtsc в конечном итоге используется. Я думаю, это может быть связано со старой версией libc или чем-то в этом роде.

Третья наиболее вероятная причина в том, что rdtsc в вашей системе работает медленно, возможно, потому, что она виртуализирована или отключена в вашей системе и реализуется через выход виртуальной машины или ловушку ОС.

Результаты одного цикла

Пытаюсь с одним clock_gettime вызов за цикл, я все еще получаю "быстрые" результаты после первых нескольких испытаний. Например, ./clockt 0 20 1 дает:

init run 15932
trial 0 took 352 (352 cycles per call)
trial 1 took 196 (196 cycles per call)
trial 2 took 104 (104 cycles per call)
trial 3 took 104 (104 cycles per call)
trial 4 took 104 (104 cycles per call)
trial 5 took 104 (104 cycles per call)
trial 6 took 102 (102 cycles per call)
trial 7 took 104 (104 cycles per call)
...

Обратите внимание, что я сделал одну модификацию тестовой программы, чтобы распечатать время на вызов, которое кажется более полезным, чем общее время. printf строка была изменена на:

printf("trial %d took %lld (%lld cycles per call)\n", t, (y-x), (y-x)/loops);