2 апреля 20266 минсистемные вызовы

Девяносто два процента системных вызовов оказались моими же

Демон жёг 140 % процессора, не делая ничего полезного. Разбор того, как я неправильно прочитал вывод strace, чем померил по-настоящему и почему прибор, который замедляет объект в девять раз, не годится для проверки «стало ли лучше».

Симптом

Фоновый сервис, принимающий события по сети и складывающий их в файлы. Нагрузка - около 900 событий в секунду, работа копеечная. При этом top показывал 140 % CPU на процесс, а ядро - 48 100 системных вызовов в секунду. На событие приходилось больше пятидесяти обращений к ядру, и это выглядело абсурдно.

Первый прибор и первая ошибка

Взял strace, как и положено:

$ strace -f -c -p 2841
^C
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------
 61,44    4,118702         437     9 420           epoll_wait
 19,02    1,275061          42    29 884           write
 12,88    0,863404          53    16 344     8 102 futex
  3,71    0,248719          27     9 102           read
  ...

И три часа подозревал epoll_wait, потому что он стоял первым. Это чистая ошибка чтения: колонка % time у блокирующих вызовов означает время ожидания, а не работы. Поток, который честно спит в epoll_wait, всегда будет на вершине такой таблицы и никогда не будет виноват в загрузке процессора.

Правильная колонка здесь - calls. По ней картина другая: write и futex дают 46 228 вызовов из 50 тысяч, то есть 92 %.

Вторая ошибка: мерил прибором, который меняет объект

За десять секунд под strace набралось около 50 тысяч вызовов - пять тысяч в секунду. А ядро без strace показывало 48 100. Разница почти десятикратная, и это не загадка: каждый перехваченный вызов - это два останова через ptrace, и демон под наблюдением просто работает в девять раз медленнее. Если бы я на этом измерил «после», я бы получил великолепное улучшение из ничего.

Считать вызовы, не трогая процесс, умеет perf - через точки трассировки ядра:

$ perf stat -e syscalls:sys_enter_write,syscalls:sys_enter_futex \
      -p 2841 -- sleep 10

    288 714   syscalls:sys_enter_write    #  28 871/с
    163 402   syscalls:sys_enter_futex    #  16 340/с

   10,001 secs time elapsed

Соотношение сохранилось, а абсолютные числа стали боевыми. Отсюда и дальше все замеры - только так.

Откуда брались вызовы

Два независимых источника, оба мои.

Первый - запись в журнал без буфера. На каждое событие сервис писал две строки, каждая отдельным write в файл. 900 событий в секунду, два журнала, плюс служебные строки - вот и 28,9 тысячи. Файл открыт с O_APPEND, никакой буферизации в процессе не было: мне казалось, что «так надёжнее, строка сразу на диске». На диске она всё равно оказывается не сразу, потому что между write и диском есть страничный кеш, так что надёжности эта схема не давала - только сисколлы.

Второй - пробуждение всего пула. Восемь рабочих потоков ждали на условной переменной, а продьюсер звал pthread_cond_broadcast на каждое событие. Просыпались все восемь, семеро находили очередь пустой и засыпали снова. В выводе strace это видно по 8 102 ошибкам у futex: это EAGAIN от неудачных попыток захвата.

Что сделал

• Буфер на 64 КиБ на журнал, сброс по заполнению или по таймеру 200 мс, плюс явный сброс при завершении и при повороте файла.
• pthread_cond_signal вместо broadcast: будить одного, а не всех.
• Таймаут epoll_wait убран совсем - он стоял равным 1 мс, то есть поток просыпался тысячу раз в секунду, чтобы проверить флаг завершения. Флаг теперь приходит через eventfd, который сам и будит.

Результат

Задержка упала не потому, что стало меньше сисколлов, а потому что исчезли восемь пробуждений на событие: планировщик перестал перекладывать потоки между ядрами.

Что я забираю из этого

Сортировать таблицу strace -c по числу вызовов, а не по времени: время у блокирующих вызовов - это ожидание, и оно обязано быть большим. Проверять «после» тем же прибором, что и «до», но только если прибор не меняет поведение объекта; ptrace меняет, счётчики ядра - нет. И не экономить на буфере там, где его отсутствие ничего не гарантирует, кроме расходов.

Что strace делает отлично - отвечает на вопрос «какие вызовы вообще есть и с какими аргументами». Для этого он незаменим, и именно так я им теперь и пользуюсь: один раз посмотреть состав, дальше считать счётчиками. Остальные приборы перечислены на странице инструментов.