Неоправданные измерения времени с помощью clock_gettime () из-за кода вне профилированного раздела - PullRequest
2 голосов
/ 22 февраля 2020

Я использую приведенную ниже программу C (скомпилированную с g cc) для измерения времени вычислений для данного раздела кода. Проблема заключается в том, что при использовании функции uleep() вне профилируемой секции кода в elapsed_time.

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

int main()
{
    int f = 0;
    while (f < 10)
    {
        double sum = 1.0;
        struct timespec t0, t1;

        clock_gettime(CLOCK_MONOTONIC, &t0);

        // CODE SECTION BEING PROFILED
        for (unsigned int i = 0; i < 5e6; i++)
            sum += 0.001;
        // END OF CODE SECTION BEING PROFILED

        clock_gettime(CLOCK_MONOTONIC, &t1);


        double elapsed_time = t1.tv_sec - t0.tv_sec;
        elapsed_time += (t1.tv_nsec - t0.tv_nsec) * 1e-9;

        printf("%.2f ms\n", elapsed_time*1000 );

        f++;

        // Sleep causing fake clock_gettime measurements?
        usleep(50000);
    }

    return 0;
}

получаются различные измерения. Ниже я вставляю результаты программ когда uleep(50000) комментируется:

13,83 мс 14,30 мс 14,41 мс 13,77 мс 13,85 мс 13,88 мс 14,55 мс 13,28 мс 13,70 мс 13,56 мс

Теперь, результаты присутствуют, когда присутствует uleep(50000):

15,37 мс 14,16 мс 36,43 мс 39,39 мс 36,38 мс 36,27 мс 34,14 мс 38,52 мс 38,18 мс 37,53 мс

Я пытался измерить время с разными часами в clock_gettime() , а также с помощью C ++ std::chrono::high_resolution_clock. Тем не менее, результаты одинаковы во всех случаях. Более того, я пробовал разные флаги g cc, например O2. В этом случае, хотя получается намного меньшее время, все же некоторые измеренные значения при usleep() на ~ 3x выше, чем при usleep().

Я обнаружил, что количество микросекунд, используемых в usleep(), влияет на итоговое измеренное время, например, при 10000 мсек я получаю:

13,75 мс 13,54 мс 13,34 мс 14,15 мс 13,12 мс 12,79 мс 28,72 мс 25,84 мс 26,18 мс 24,53 мс

После всех этих тестов я не могу найти причину этих «поддельных» измерений времени в этой программе. Буду признателен, если кто-нибудь сможет пролить свет на эту проблему.

Заранее спасибо!


Редактировать:

После некоторого дальнейшего тестирования я понял, что то же самое проблема вызвана printf() (см. код ниже).

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

int main()
{
    double total_time = 0.0;
    int f = 0;
    while (f < 1000)
    {
        double sum = 1.0;
        struct timespec t0, t1;

        clock_gettime(CLOCK_MONOTONIC, &t0);

        // Code section being profiled
        for (unsigned int i = 0; i < 5e6; i++)
            sum += 0.001;
        // End of Code section being profiled

        clock_gettime(CLOCK_MONOTONIC, &t1);


        double elapsed_time = t1.tv_sec - t0.tv_sec;
        elapsed_time += (t1.tv_nsec - t0.tv_nsec) * 1e-9;
        total_time += elapsed_time;


        f++;

        // Sleep/printf causing fake clock_gettime measurements?
        printf("%.2f ms\n", elapsed_time*1000 );
        // usleep(10000);
    }
    printf("TOTAL TIME: %.2f ms\n", total_time*1000 );
    return 0;
}

Результаты

Когда я запускаю этот код, скомпилированный с g++ -g f, я получаю общее время:

  • ~ 13071.42 мс когда присутствует строка printf("%.2f ms\n", elapsed_time*1000 ); (примечание, что эта линия снова находится вне профилируемой секции).
  • ~ 12712,22 мс , когда эта строка закомментирована.

Если программа скомпилирована с использованием оптимизации (g++ -O2), я получаю общее время :

  • ~ 3145,27 мс при наличии printf().
  • ~ 2741,45 мс при отсутствии printf() .

При printf() измеренное время увеличивается в меньшей степени по сравнению с usleep(). Таким образом, usleep(), похоже, не единственная функция, вызывающая эту проблему ... В любом случае, измеренное время не должно быть затронуто для кода, размещенного вне профилируемой секции кода ... Я что-то упустил?


Редактировать 2:

Различные часы, которые я пробовал: CLOCK_MONOTONIC_RAW, CLOCK_PROCESS_CPUTIME_ID и CLOCK_REALTIME. Все они предлагают одинаковое поведение.

Более того, я проверил возвращаемое значение clock_gettime(), чтобы отменить ошибки.

1 Ответ

0 голосов
/ 02 марта 2020

Похоже, вы стали жертвой масштабирования частоты процессора .

масштабирования частоты процессора

Ваш драйвер масштабирования процессора регулирует частоту процессора в соответствии с различными факторами, но важно, согласно текущей загрузке процессора. Для ядра Linux доступны различные драйверы и разные регуляторы масштабирования. Каждый драйвер может поддерживать определенный набор регуляторов масштабирования и вести себя по-разному в зависимости от текущего активного регулятора.

Например, драйвер по умолчанию на моем ноутбуке - intel_pstate с доступными регуляторами powersave и performance , Если я поменяю драйвер на acpi-cpufreq, я также получу ondemand, userspace и conservative.

Основное различие между разными губернаторами заключается в их имени: губернатор powersave попытается сохранить ЦП на более низкой частоте для экономии энергии, тогда как регулятор performance будет пытаться поддерживать высокую частоту ЦП для ускорения работы go.

В некоторых случаях регулятор performance просто фиксирует максимально возможную частоту процессора (для меня это то, что происходит с драйвером intel_pstate). В других случаях он просто попытается сохранить его «высоким», но все равно вносит коррективы (для меня это то, что происходит с драйвером acpi-cpufreq).

В любом случае комбинация масштабирования драйвер и регулятор, который динамически регулирует частоту ЦП, будет учитывать нагрузку на ЦП, чтобы по мере возможности регулировать частоту на лету. Это может произойти, когда код ядра вводится с помощью системного вызова, или по расписанию, когда само ядро ​​запускает планировщик для перепланирования текущих запущенных процессов.

Что происходит?

Скорее всего, у вас есть комбинация драйвера масштабирования и регулятора, который динамически устанавливает частоту процессора.

Когда ваш код запускается без , вызывая usleep(), процессор находится под большой нагрузкой, а частота в основном стабильна. Однако, если ваш код вызывает usleep(), загрузка ЦП значительно уменьшается, а драйвер масштабирования снижает частоту ЦП. К тому моменту, когда процесс запускается ядром после сна, частота становится намного ниже, и требуется некоторое время, чтобы драйвер масштабирования понял, что его необходимо увеличить. Если вы продолжаете спать регулярно, есть вероятность, что у драйвера никогда не будет достаточно времени для повторного масштабирования частоты, а код будет работать медленнее.

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

Вот пример на моей машине с динамическим c регулятором (например, ondemand):

demo

Вы можете четко видеть, как частота ЦП застревает на максимальном значении во время первого запуска ( без usleep()), а затем колеблется вверх и вниз без достаточного времени для стабилизации во время второго запуска ( с usleep()). На самом деле вы можете заметить, что время avg для теста №2 почти в 3 раза больше, чем у теста № 1. Это также происходит для acpi-cpufreq и регулятора performance на моей машине.

Решение

Если вы можете установить другую комбинацию масштабирующего драйвера / регулятора, которая поддерживает фиксированную частоту ЦП, вы не увидите никакой разницы во времени между двумя версиями вашего кода.

Вот еще один пример на моей машине с частотой процессора c (например, с использованием регулятора userspace и установкой фиксированной скорости). вручную):

demo 2

Как видите, оба теста выполняются примерно в одно и то же время.

Если вы не можете установите другой регулятор масштабирования, попробуйте изменить драйвер масштабирования вашего ядра. Если вы используете Debian или Ubuntu, у вас могут быть загружаемые модули для разных драйверов масштабирования.

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

cat /boot/config-$(uname -r) | grep FREQ

Например, я вижу:

...
CONFIG_X86_PCC_CPUFREQ=m
CONFIG_X86_ACPI_CPUFREQ=m
...

Где m означает «доступен как модуль» (загружается с помощью modprobe), а y означает «встроенный».

Вы можете, например, попытаться сделать:

# Load acpi-cpufreq since we have CONFIG_X86_ACPI_CPUFREQ=m
sudo modprobe acpi_cpufreq 

# Switch driver
echo acpi-cpufreq | sudo tee /sys/devices/system/cpu/cpu*/cpufreq/scaling_driver

# Check available governors for the driver
cat /sys/devices/system/cpu/cpu*/cpufreq/scaling_available_governors

Тестовый код

Вот код тестирования, используемый для вышеуказанных GIF:

#define _GNU_SOURCE
#include <unistd.h>
#include <stdio.h>
#include <time.h>
#include <math.h>
#include <sched.h>
#include <sys/types.h>

/**
 * Marco Bonelli - 2020-03-02
 * https://stackoverflow.com/a/60481392/3889449
 *
 * Test the effect of different scaling governors on CPU frequency and
 * performance under:
 *
 *   1) Continuous heavy load.
 *   2) Intermittent and short heavy load.
 *
 * gcc -O3 scaling_governor_test.c -o test
 * ./test [N_RUNS] [N_CYCLES_PER_RUN] [TEST2_DELAY_US]
 */

#define DEFAULT_RUNS   1000
#define DEFAULT_CYCLES 1000 * 1000
#define DEFAULT_DELAY  100 * 1000

// Don't optimize this as GCC would basically trash the whole function.
#pragma GCC push_options
#pragma GCC optimize("O0")
void __attribute__ ((noinline)) func(unsigned n) {
    double sum = 1.0;

    for (unsigned i = 0; i < n; i++)
        sum += 0.001;
}
#pragma GCC pop_options

void warmup(unsigned runs, unsigned cycles) {
    for (unsigned n = 1; n <= runs; n++)
        func(cycles);
}

double bench(unsigned n) {
    struct timespec t0, t1;

    clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &t0);
    func(n);
    clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &t1);

    return (t1.tv_sec - t0.tv_sec)*1000.0L + (t1.tv_nsec - t0.tv_nsec)/1000.0L/1000.0L;
}

void setup_affinity(void) {
    cpu_set_t set;

    CPU_ZERO(&set);
    CPU_SET(0, &set);

    if (geteuid() == 0) {
        if (sched_setaffinity(0, sizeof(set), &set) == 0)
            puts("Affinity set to CPU #0.");
        else
            perror("sched_setaffinity");
    } else {
        puts("Running as normal user, run as root to set CPU affinity.");
    }
}

int main(int argc, char **argv) {
    unsigned runs, cycles, delay;
    double cur, tot1, tot2, min, max, avg;

    if (argc < 2 || sscanf(argv[1], "%i", &runs) != 1 || runs < 1)
        runs = DEFAULT_RUNS;

    if (argc < 3 || sscanf(argv[2], "%i", &cycles) != 1 || cycles < 1)
        cycles = DEFAULT_CYCLES;

    if (argc < 4 || sscanf(argv[3], "%i", &delay) != 1 || delay < 1)
        delay = DEFAULT_DELAY;

    setup_affinity();

    printf("Benchmarking %u runs of %u cycles each.\n", runs, cycles);
    printf("Test #1 will proceed normally.\nTest #2 will usleep(%u) before each run.\n", delay);
    fputs("Warming up... ", stdout);
    fflush(stdout);

    warmup(10, cycles);

    puts("done.\n---");

    tot1 = 0;
    min = INFINITY;
    max = -INFINITY;

    for (unsigned n = 1; n <= runs; n++) {
        cur = bench(cycles);

        tot1 += cur;
        avg = tot1 / n;
        if (cur < min) min = cur;
        if (cur > max) max = cur;

        printf("\rTest #1: tot %-9.3f  avg %-7.3f  min %-7.3f  max %-7.3f [ms]", tot1, avg, min, max);
        fflush(stdout);
    }

    putchar('\n');

    tot2 = 0;
    min = INFINITY;
    max = -INFINITY;

    for (unsigned n = 1; n <= runs; n++) {
        usleep(delay);
        cur = bench(cycles);

        tot2 += cur;
        avg = tot2 / n;
        if (cur < min) min = cur;
        if (cur > max) max = cur;

        printf("\rTest #2: tot %-9.3f  avg %-7.3f  min %-7.3f  max %-7.3f [ms]", tot2, avg, min, max);
        fflush(stdout);
    }

    puts("\n---");

    if (tot1 < tot2)
        printf("Test #2 ran ~%.3fx slower than Test #1.\n", tot2/tot1);
    else if (tot1 > tot2)
        printf("Test #1 ran ~%.3fx slower than Test #2.\n", tot1/tot2);
    else
        puts("Reality is a simulation.");

    if (avg < 0.5)
        puts("Such low average times are not a good indicator. You should re-run the rest with different parameters.");

    return 0;
}
...