Микрооптимизации важны: предотвращаем 20 миллионов системных вызовов

Эта публикация — логическое продолжение поста «Как настройка переменной окружения TZ позволяет избежать тысяч системных вызовов». Здесь мы рассмотрим характерную ситуацию, когда микрооптимизации (например, удаление системного вызова) очень сильно влияют на производительность.

Что такое заметное улучшение?

Ранее мы описали переменную окружения, которую может настраивать приложение, чтобы избежать тысяч дополнительных системных вызовов. Эту статью встретили справедливыми вопросами с некоторой долей скепсиса:

• «Тонко, но разве удаление единственного системного вызова заметно повлияет на производительность всей программы?»
• «Это выглядит ненужным; в Linux системные вызовы и так выполняются быстро».

Трудно сказать, что каждый из разработчиков вкладывает в понятие «заметное улучшение» применительно к конкретному приложению. Разработчики ядра и драйверов часто тратят немало времени на микрооптимизацию кода и структур данных, чтобы как можно полнее использовать кеш процессора и снизить потребление самого CPU. Даже если большинство программистов сочтут выгоду очень незначительной. Нужно ли уделять меньше внимания таким оптимизациям? Кто-то может вообще сказать, что микрооптимизации нельзя расценивать как заметные.

В рамках этой статьи определим заметное как легко измеряемое и совершенно очевидное. Можем ли мы показать реальный пример, когда удаление из кода фрагмента (code path) медленного (без vDSO) системного вызова приводит к легко измеряемому и совершенно очевидному результату?

Есть множество реальных примеров: от снифферов пакетов до сред выполнения (runtime) программных языков. Рассмотрим такой печально известный случай, как влияние sigprocmask на runtime языка Ruby.

Что такое sigprocmask?

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

Это не особенно сложный системный вызов. Код ядра, относящийся к sigprocmask, говорит нам, что вызов записывает sigset_t в C-структуру, содержащую состояние текущего процесса (в ядре называется как task_struct). Это очень быстрая операция.

Давайте создадим простую тестовую программу, которая в маленьком цикле вызывает sigprocmask. Измерять будем с помощью strace и time:

#include <stdlib.h>
#include <signal.h>

int
main(int argc, char *argv[])
{
    int i = 0;
    sigset_t test;

    for (; i < 1000000; i++) {
        sigprocmask(SIG_SETMASK, NULL, &test);
    }

    return 0;
}

Компилируем с помощью gcc -o test test.c. Сначала выполняем с time, а затем — со strace и time.

На моей тестовой системе:

• Выполнение time ./test показало: 0,047 секунды — реальное время, 0,012 секунды — пользовательское время, 0,036 секунды — системное время.
• Выполнение time strace -ttT ./test показало: 52,364 секунды — реальное время, 9,313 секунды — пользовательское время, 14,349 секунды — системное время.

В случае со strace для каждого вызова sigprocmask (в вашей системе наверняка будет отображаться как rt_sigprocmask) будут продемонстрированы приблизительные значения длительности выполнения. Они очень малы. На моей тестовой системе я получил в большинстве случаев значения в районе 0,000003 секунды — с неожиданным всплеском до 0,000074 секунды.

Довольно трудно измерить точное время выполнения системного вызова по целому ряду причин. Они выходят далеко за пределы вопроса, обсуждаемого в этой статье. Так что можем предположить, что все измерения были проведены в равной мере некорректно.

Итак, что мы уже знаем:

• sigprocmask — системный вызов, используемый для настройки или проверки сигнальной маски текущего процесса.
• Код ядра прост и должен выполняться очень быстро.
• Результаты измерений с time и strace показывают, что при выполнении в маленьком цикле миллиона вызовов sigprocmask каждый вызов занимает очень мало времени.

Так зачем нам избавляться от дополнительных sigprocmask, будет ли это стоить наших усилий?

Разберёмся подробнее

Иногда чужой код, который мы используем в своих приложениях (системные библиотеки, ядро, glibc и т. д.), делает неожиданные вещи или имеет неочевидные на первый взгляд побочные эффекты. В качестве примера ниже я покажу, как косвенное использование sigprocmask в тестовой программе приводит к серьёзному снижению производительности. А затем продемонстрирую, как это проявляется в реальном приложении.

С Ruby 1.8.7 был связан один из самых ярких примеров того, как дополнительные вызовы sigprocmask приводили к очевидному и легко измеряемому снижению производительности. Это отмечалось в тех случаях, когда код компилировался с одним конкретным флагом configure.

Начнём со значений конфигурационных флагов по умолчанию, которые использовались на большинстве ОС (Debian, Ubuntu и т. д.) во времена широкого распространения Ruby 1.8.7.

Тестирование sigprocmask

Взгляните на тестовый код:

def make_thread
  Thread.new do
    a = []
    10_000_000.times do
      a << "a"
      a.pop
    end
  end
end

t = make_thread
t1 = make_thread

t.join
t1.join

Тут всё просто: создаём два потока выполнения, каждый из которых 10 миллионов раз добавляет и удаляет данные из массива. Если запустить со значениями конфигурационных флагов по умолчанию и strace, то получим удивительные результаты:

$ strace -ce rt_sigprocmask /tmp/test-ruby/usr/local/bin/ruby /tmp/test.rb
Process 30018 attached
Process 30018 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  0.50    0.139288           0  20033025           rt_sigprocmask

Виртуальная машина Ruby сгенерировала больше 20 миллионов системных вызовов sigprocmask. Вы скажете: «Но ведь они заняли очень мало времени! Что в этом такого?»

Как уже упоминалось, не так просто измерить длительность системного вызова. Перезапустим тестовую программу с time вместо strace и посмотрим, сколько времени займёт её завершение на моей системе:

$ time /tmp/gogo/usr/local/bin/ruby /tmp/test.rb

real        0m6.147s
user        0m5.644s
sys         0m0.476s

Около 6 секунд реального выполнения. То есть около 3,3 миллиона вызовов sigprocmask в секунду. Ого.

А если настроить один флаг configure, то виртуальная машина Ruby будет собирать систему, избегая вызовов sigprocmask!

Перезапустим тесты со strace и time, но в этот раз немножко подкрутим Ruby, чтобы он избегал вызовов sigprocmask:

$ strace -ce rt_sigprocmask /tmp/test-ruby-2/usr/local/bin/ruby /tmp/test.rb
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  -nan    0.000000           0         3           rt_sigprocmask

Круто! Мы снизили количество вызовов sigprocmask с 20 до 3. Похоже, у strace были проблемы с вычислением времени выполнения системных вызовов :(

Посмотрим, что скажет time:

$ time /tmp/test-ruby-2/usr/local/bin/ruby /tmp/test.rb

real    0m3.716s
user    0m3.692s
sys   0m0.004s

Примерно на 40 % быстрее (реальное время выполнения), чем в предыдущем примере, и менее одного вызова sigprocmask в секунду.

Отличный результат, но возникает несколько вопросов:

• Не является ли пример немного надуманным?
• Когда это действительно актуально в реальных проектах?
• Что именно при настройке флагов configure приводит к снижению количества вызовов?

Давайте сначала рассмотрим реальный пример, а потом разберёмся с подробностями.

Реальный пример: Puppet

Найденный в Puppet баг точно демонстрирует влияние дополнительных вызовов sigprocmask на работу виртуальной машины Ruby:

Я только что столкнулся с серьёзной проблемой, связанной с производительностью. Puppet очень медленно работает.

Первый пример:

$ time puppet —version 0.24.5
real 0m0.718s user 0m0.576s sys 0m0.140s

В это время совершались сотни, если не тысячи вызовов rt_sigprocmask(SIG_BLOCK, NULL, [], 8). И всё это ради отображения версии.

Если вы почитаете переписку, то обнаружите и другие комментарии, в которых люди жалуются на низкую производительность Puppet. Той же проблеме посвящены и вопросы на Stackoverflow.

Но это проблема не только Ruby и Puppet. О подобных багах пишут и пользователи других проектов, сообщая о полной загрузке процессора и сотнях тысяч вызовов sigprocmask.

Почему так происходит? Легко ли это исправить?

Дело в том, что вызовы sigprocmask осуществляются двумя функциями из glibc (не являющимися системными вызовами): getcontext и setcontext.

Они применяются для сохранения и восстановления состояния процессора. Их широко используют программы и библиотеки, реализующие обработку исключений или потоки выполнения в пользовательском пространстве. В случае с Ruby 1.8.7 setcontext и getcontext нужны в реализации потоков выполнения в пользовательском пространстве — для переключения контекста между потоками.

Вы можете подумать, что эти две функции должны выполняться довольно быстро. Ведь они всего лишь сохраняют или восстанавливают маленький набор регистров процессора. Да, сохранение — операция очень быстрая. Но, судя по всему, реализация этих функций в glibc такова, что для сохранения и восстановления сигнальной маски используются системные вызовы sigprocmask.

Вспомним, что Linux предоставляет механизм (vDSO), который вместо ядра отвечает за выполнение определённых системных вызовов. Это позволяет снизить стоимость их выполнения. К сожалению, sigprocmask не входит в их число. Все системные вызовы sigprocmask приводят к переходу (transition) из пользовательского пространства в ядро.

Стоимость такого перехода гораздо выше стоимости других операций в setcontext и getcontext (представляющих простые записи в память). Если очень часто вызывать эти функции, то вы будете выполнять медленную операцию (в этом случае — системный вызов sigprocmask, который не проходит через vDSO) каждый раз, когда вам нужно сделать что-то быстро (например, сохранить или восстановить набор регистров процессора для переключения потоков выполнения).

Почему изменение конфигурационного флага улучшает ситуацию?

Во времена широкого использования Ruby 1.8.7 по умолчанию использовался флаг --enable-pthread, активирующий на уровне ОС отдельный поток выполнения, который запускался по таймеру (timer thread). Он стартовал по мере необходимости для перехвата (pre-empt) виртуальной машины Ruby. Таким образом машина узнавала, что пришло время переключиться между потоками выполнения в пользовательском пространстве, которые были сопоставлены (mapped) с потоками, созданными в Ruby-программах. Также обращение к --enable-pthread приводило к тому, что скрипт configure находил и использовал функции getcontext и setcontext.

Без --enable-pthread скрипт configure будет искать и использовать _setjmp и _longjmp (обратите внимание на подчёркивания). Эти функции не сохраняют и не восстанавливают сигнальную маску, а следовательно, и не генерируют системные вызовы sigprocmask.

Итак:

• --enable-pthread и --disable-pthread предназначались для управления многопоточностью в пользовательском пространстве виртуальной машины Ruby: применялся либо поток выполнения на уровне ОС, либо простой сигнал VTALRM, уведомляющий ВМ, что пора переключиться на выполнение другого потока Ruby.
• Неожиданным побочным эффектом переключения между этими двумя методами перехвата (pre-empt) стало то, что примитивы для реализации переключения искали либо setcontext/getcontext, либо _setjmp/_longjmp.
• Это приводило к тому, что если использовалась пара setcontext/getcontext, то выполнялись дополнительные вызовы sigprocmask.
• А это, в свою очередь, снижало производительность.
• С чем и столкнулись создателя ряда проектов, включая Puppet.

И всё это из-за одного флага, который включает или отключает единственный системный вызов.

Заключение

Микрооптимизации важны. Но степень их важности, конечно, зависит от специфики самого приложения. Имейте в виду, что библиотеки и код, от которых вы зависите, могут делать то, чего вы не ожидаете (например, выполнять медленный системный вызов). Если вы будете знать, как выявлять и исправлять подобные проблемы, то это окажет огромное влияние на ваших пользователей. А в некоторых случаях — на пользователей ваших пользователей.

Автор: Mail.Ru Group

Источник