20 ноября 20257 минпрофилирование

Профиль показал memcpy, а виноват был обход массива

Три дня я оптимизировал функцию, которая стояла на вершине профиля, и получил минус один процент. Разбор того, почему сэмплирующий профиль показывает место ожидания, а не причину, и почему порядок «сначала счётчики» у меня теперь жёсткий.

Задача

Слияние двух отсортированных наборов записей. Запись - 48 байт: идентификатор, метка времени, девять полей, которые при слиянии не нужны. Всего 40 млн записей, прогон 2,31 с.

typedef struct {
    uint64_t id;          /* 0  */
    uint64_t ts;          /* 8  */
    uint32_t flags;       /* 16 */
    char     tag[12];     /* 20 */
    double   v[2];        /* 32 */
} Rec;                    /* sizeof = 48 */

Сравниваются id и ts, то есть шестнадцать байт из сорока восьми. Остальное просто переносится в выходной массив.

Что сказал профиль

$ perf record -e cycles:pp -g ./merge in1.bin in2.bin out.bin
$ perf report --stdio --percent-limit 4
  18,4%  merge  libc.so.6  [.] __memmove_avx_unaligned_erms
  14,9%  merge  merge      [.] merge_run
  11,2%  merge  merge      [.] rec_less
   ...

Вершина - копирование. Дальше три дня честной работы: убрал одно лишнее копирование целиком, оставшееся переписал на запись по 32 байта вместо вызова, выровнял выходной буфер. Итог 2,28 с вместо 2,31 - минус 1,3 %, то есть ничего.

Почему профиль не врал, но и не отвечал на мой вопрос

Сэмплирующий профиль отвечает строго на один вопрос: где находился указатель инструкций в момент прерывания. Если ядро процессора стоит и ждёт строку кеша из памяти, счётчик тактов продолжает тикать, и такты записываются на ту инструкцию, которая выполняет чтение. В моём коде первым к холодным данным прикасалось копирование - значит, оно и собрало все такты ожидания. Виноват при этом не способ копирования, а то, что данные холодные.

Разделить эти два случая профиль не может принципиально. Для этого нужны счётчики.

Счётчики

$ perf stat -r 5 -e cycles,instructions,cache-references,\
      cache-misses,LLC-load-misses ./merge in1.bin in2.bin out.bin

     9 418 221 043   cycles
     3 861 004 187   instructions   #  0,41  insn per cycle
       204 118 773   cache-references
        85 402 118   cache-misses   #  41,84 % of all refs
         8 402 551   LLC-load-misses

IPC 0,41 - это одна цифра, которая закрывает вопрос. Процессор занят не вычислениями: при полезной работе на этом стенде получается 1,5–2,5. Вместе с 42 % промахов это означает, что программа ждёт память, и ускорять в ней надо доступ, а не арифметику.

Причина

Строка кеша - 64 байта. Структура - 48. Обход с шагом 48 байт означает, что из каждой строки используются 16 нужных байт, а 48 тянутся зря и вытесняют то, что ещё понадобится. На 40 млн записей это 1,92 ГиБ прочитанных данных вместо 640 МиБ полезных.

Лечится переходом к раздельным массивам для горячих полей: id[] и ts[] отдельно, остальное - как было, по индексу. Сравнение теперь идёт по двум плотным массивам, и одна строка кеша покрывает восемь идентификаторов вместо одного.

Порядок, которого я теперь держусь

1. perf stat без аргументов-изысков: такты, инструкции, IPC, промахи. Три числа, которые говорят, чего программа ждёт.
2. Если IPC низкий - смотреть на доступ к памяти: размеры структур, шаг обхода, расположение полей.
3. Если IPC высокий, а время большое - тогда уже perf record и поиск горячей функции.

Три дня работы над memcpy были не ошибкой инструмента, а моей: я задал профилю вопрос, на который он не отвечает. Та же история с другой стороны - в записи про RSS и free, где я не поверил правильному показанию прибора.