Привет! Меня зовут Александр Петровский, я инженер в DINS. Я работаю в команде, которая участвует в разработке сервисов облачной телефонии и видеоконференций для RingCentral. Каждый из них состоит из большого количества микросервисов.

Когда мы мигрировали один из наших микросервисов с CentOS 7 с ядром 4.19 на Oracle Linux 7 с ядром 5.4, мы заметили рост утилизации процессора на наших stress/performance-тестах. В статье я расскажу, как мы исследовали причины роста утилизации процессора сначала в user-space, а потом и в kernel-space и о том, к какому результату это нас привело.

Проблема

Для начала немного о том, что представляет собой наш микросервис: это in-house L3/L4 balancing router. Ядро сервиса состоит из eBPF/XDP [1] приложения, которое загружается в ядро Linux («живет» в SOFTIRQ) и решает задачи балансировки/роутинга сетевых пакетов до конечных бэкендов — это наш data plane. Cервис похож на katran [2] у Facebook, maglev [3] у Google, unimog [4] у Cloudflare и glb [5] у Github, но за небольшим исключением, что выгодно отличает нас от остальных. Серверы, на которых расположен микросервис (далее по тексту «ноды»), соединены между собой в кластер, а также соединены по BGP с L3 Juniper роутерами и получают от них сетевые пакеты с помощью ECMP. Сами кластеры располагаются в разных дата-центрах и соединены между собой, каждая нода в кластере знает состояние всех соединений во всех присоединенных кластерах. За это отвечает приложение на Erlang совместно с приложением на Golang как адаптером для работы с eBPF/XDP — это наш control plane. Таким образом, каждая нода готова балансировать/роутить пакеты в кластере, если все остальные ноды в кластере выйдут из строя. Каждый кластер в свою очередь готов балансировать/роутить пакеты других присоединенных кластеров, если они выйдут из строя.

В ходе миграции на наших stress/performance-тестах, которые генерируют высокий PPS, мы заметили рост утилизации процессора примерно на 10% на Oracle Linux 7 с ядром 5.4.17-2102.200.13.el7uek по сравнению с CentOS 7 с ядром 4.19.125-1:

Тут в первую очередь нам интересен рост утилизации процессора в SOFTIRQ: 13% vs. 26%. SOFTIRQ показывает время, затрачиваемое процессором при обработке некоторых soft deferred задач. Таких как обработка сетевых пакетов (rx/tx), RCU, таймеров и tasklet'ов. Следовательно, нам нужно выяснить, на что больше всего процессорного времени тратится в SOFTIRQ?

Исследование в user-space

Чтобы определить, на какой тип задач (обработка сетевых пакетов (rx/tx), RCU, таймеров и tasklet'ов) процессор тратит больше всего времени в SOFTIRQ, достаточно заглянуть в файл /proc/softirqs. Для нас интересны в первую очередь NET_TX и NET_RX. Пожалуйста, обратите внимание — файл содержит статистику по разным типам задач SOFTIRQ с начала старта системы и в данном случае, нам интересна только скорость роста этих значений:

[root@str01-t01-**r01 /] # cat /proc/softirqs
                    CPU0       CPU1       CPU2       CPU3
          HI:          0          0          0          0
       TIMER:  129613942  356589263  129018907  163921988
      NET_TX:    2508105    2585781    2487271    2447192
      NET_RX: 2044953742 1994883329 1858956128 1847655110
       BLOCK:     609965     122879     139668     167503
    IRQ_POLL:          0          0          0          0
     TASKLET:      73252      57791     163713     154726
       SCHED:   55000904   79751919   49854734   56760814
     HRTIMER:          2          0          0          1
         RCU:  114773995  223570840  114631792  132787573

и

[root@str01-t01-**r02 /] # cat /proc/softirqs
                    CPU0       CPU1       CPU2       CPU3
          HI:          0          0          0          0
       TIMER:  132695274  339738125  154810847  117233153
      NET_TX:    2166064    2348500    2239794    2108175
      NET_RX: 1049349788 1038558391 1003371390  911448878
       BLOCK:      97480     194503     149366     106470
    IRQ_POLL:          0          0          0          0
     TASKLET:     124116     266805     263565     141745
       SCHED:   52902419   77032919   54463361   44062142
     HRTIMER:        229          0         10        258
         RCU:  105711455  206432337  118001592   97389637

Из листингов выше видно, значения NET_TX и NET_RX во времени растут примерно с одинаковой скоростью.

Но все-таки, кто же из них стал работать медленнее и как следствие тратить больше процессорного времени? Чтобы это определить, можно воспользоваться набором скриптов из пакета BCC. Скрипт /usr/share/bcc/tools/softirqs из этого пакета просуммирует время, затрачиваемое каждыми типом задач в SOFTIRQ в течении 10 секунд. Пожалуйста, обратите внимание, оригинальный скрипт был модифицирован для сбора статистики только на 0-м ядре процессора для большей точности и гранулярности:

[root@str01-t01-**r01 /] # /usr/share/bcc/tools/softirqs 10 1
Tracing soft irq event time... Hit Ctrl-C to end.
 
SOFTIRQ          TOTAL_usecs
net_tx                    21
block                     47
rcu                     1472
timer                   3735
sched                   7419
net_rx               2663715

и

[root@str01-t01-**r02 /] # /usr/share/bcc/tools/softirqs 10 1
Tracing soft irq event time... Hit Ctrl-C to end.
 
SOFTIRQ          TOTAL_usecs
net_tx                    14
timer                   2408
rcu                     2485
sched                   9190
net_rx               2710900

После анализа листингов выше видно — основное время затрачивается при обработке входящего трафика — NET_RX. И самое странное, время в обоих случаях почти одинаково — ~266ms (str01-t01-**r01) vs. ~271ms (str01-t01-**r02). Т.е. примерно от ~266ms до ~271ms тратится на NET_RX на 0-м ядре процессора (как и на всех остальных ядрах, очевидно) в каждую секунду времени. Но! в процентном соотношении это не 13% vs. 26% как мы видели на графиках выше. It seems like we need to go deeper... :(

Исследование в kernel-space

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

• system call возвращает управление в user-space;

• hardware interrupt handler возвращает управление в ядро.

Упрощённо, общий процесс работы NET_RX и обработки сетевых пакетов выглядит следующим образом: драйвер сетевого интерфейса регистрирует свой callback как NAPI poll-функцию — vmxnet3_poll_rx_only в нашем случае. При поступлении очередного пакета драйвер информирует (нотифицирует) NAPI, о том, что один из softirq callback'ов готов к работе. Ядро вызывает _do__softirq функцию, которая вызывает net_rx_action функцию, которая уже в свою очередь вызывает NAPI poll-функцию vmxnet3_poll_rx_only. Далее эта функция в течении некоторого времени вычитывает сетевые пакеты из DMA-памяти сетевого интерфейса. Время работы функции обусловлено временным бюджетом (максимум до 2ms) или количеством пакетов, которые можно вычитать (до 64 пакетов за одну итерацию). В случае, если временной бюджет еще не исчерпан, и в DMA-памяти сетевого интерфейса есть еще пакеты, которые можно вычитать, происходит очередная итерация чтения пакетов. После этого ядро вызывает net_rps_send_ipi функцию (эта функция используется RPS подсистемой). И наконец вызывается функция process_backlog для непосредственной обработки вычитанных пакетов ядром (в контексте этой функции и работает ядро нашего сервиса — eBPF/XDP приложение) [6] [7] [8].

Для дальнейшего анализа нужно собрать stacktrace (с 0-го ядра) процессора на str01-t01-**r01 в течение 10 секунд:

[root@str01-t01-**r01 ~] # perf record -C 0 -g - sleep 10

Для наглядности полученный stacktrace я конвертировал во FlameGraph:

[root@str01-t01-**r01 ~] # perf script | ./FlameGraph/stackcollapse-perf.pl | ./FlameGraph/flamegraph.pl > perf.data.str01.svg

И то же самое на str01-t01-**r02:

[root@str01-t01-**r02 ~] # perf record -C 0 -g - sleep 10

Полученный stacktrace также сконвертируем во FlameGraph:

[root@str01-t01-**r02 ~] # perf script | ./FlameGraph/stackcollapse-perf.pl | ./FlameGraph/flamegraph.pl > perf.data.str02.svg

Используя функцию поиска — search во FlameGraph — можно найти все вызовы функции net_rx_action и время (в процентах) затраченное ей на 0-м ядре процессора. Время в обоих случаях почти одинаково — ~23.1% (str01-t01-**r01) vs. ~23.4% (str01-t01-**r02).

[root@str01-t01-**r01 ~] # /usr/share/bcc/tools/profile -C 0 -f 10 | ~/FlameGraph/flamegraph.pl > /root/profile.str01.svg

Следующим шагом для получения более полной картины было проведено инструментирование функциий _do__softirq, net_rx_action, vmxnet3_poll_rx_only, net_rps_send_ipi и process_backlog в течение 60 секунд с помощью bpftrace c использованием скрипта softirqlat.bt [10]:

[root@str01-t01-**r01 /] # bpftrace -c 'sleep 60' /root/softirqlat.bt
 
Tracing latencies of
 __do_softirq
     |- net_rx_action
         |- vmxnet3_poll_rx_only
         |- net_rps_send_ipi
         |- process_backlog
 
CPU CORE 0
 __do_softirq (self 19131964 usecs, child 17371519 usecs)
     |- net_rx_action (self 17371519 usecs, child 15148558 usecs)
         |- vmxnet3_poll_rx_only (self 6036193 usecs, pkts received 5716452)
         |- net_rps_send_ipi (self 1491625 usecs)
         |- process_backlog (self 7620740 usecs, pkts processes 6445139)
CPU CORE 1
 __do_softirq (self 18805067 usecs, child 17022120 usecs)
     |- net_rx_action (self 17022120 usecs, child 14840980 usecs)
         |- vmxnet3_poll_rx_only (self 6012230 usecs, pkts received 5697282)
         |- net_rps_send_ipi (self 1373021 usecs)
         |- process_backlog (self 7455729 usecs, pkts processes 6397867)
CPU CORE 2
 __do_softirq (self 20225967 usecs, child 18542331 usecs)
     |- net_rx_action (self 18542331 usecs, child 16473121 usecs)
         |- vmxnet3_poll_rx_only (self 7742061 usecs, pkts received 8581000)
         |- net_rps_send_ipi (self 1434057 usecs)
         |- process_backlog (self 7297003 usecs, pkts processes 6413051)
CPU CORE 3
 __do_softirq (self 18146713 usecs, child 16493474 usecs)
     |- net_rx_action (self 16493474 usecs, child 14537792 usecs)
         |- vmxnet3_poll_rx_only (self 5981788 usecs, pkts received 5658005)
         |- net_rps_send_ipi (self 1147239 usecs)
         |- process_backlog (self 7408765 usecs, pkts processes 6384332)

и

[root@str01-t01-**r02 /]# bpftrace -c 'sleep 60' /root/softirqlat.bt
 
Tracing latencies of
 __do_softirq
     |- net_rx_action
         |- vmxnet3_poll_rx_only
         |- net_rps_send_ipi
         |- process_backlog
 
CPU CORE 0
 __do_softirq (self 20552213 usecs, child 18688829 usecs)
     |- net_rx_action (self 18688829 usecs, child 16270724 usecs)
         |- vmxnet3_poll_rx_only (self 6845690 usecs, pkts received 6652314)
         |- net_rps_send_ipi (self 1620819 usecs)
         |- process_backlog (self 7804215 usecs, pkts processes 6392437)
CPU CORE 1
 __do_softirq (self 19829660 usecs, child 17929799 usecs)
     |- net_rx_action (self 17929799 usecs, child 15544991 usecs)
         |- vmxnet3_poll_rx_only (self 6277612 usecs, pkts received 5687827)
         |- net_rps_send_ipi (self 1392258 usecs)
         |- process_backlog (self 7875121 usecs, pkts processes 6394496)
CPU CORE 2
 __do_softirq (self 17845311 usecs, child 16057312 usecs)
     |- net_rx_action (self 16057312 usecs, child 13931757 usecs)
         |- vmxnet3_poll_rx_only (self 4932063 usecs, pkts received 3782523)
         |- net_rps_send_ipi (self 1046316 usecs)
         |- process_backlog (self 7953378 usecs, pkts processes 6407624)
CPU CORE 3
 __do_softirq (self 20872098 usecs, child 19241081 usecs)
     |- net_rx_action (self 19241081 usecs, child 17237208 usecs)
         |- vmxnet3_poll_rx_only (self 8364547 usecs, pkts received 9453994)
         |- net_rps_send_ipi (self 1370673 usecs)
         |- process_backlog (self 7501988 usecs, pkts processes 6372464)

Обобщая результаты

• Среднее время затрачиваемое в секунду на обработку трафика в NET_RX в обоих случаях почти одинаково: ~266ms vs. ~271ms;

• Среднее время (в процентах) затрачиваемое в секунду на обработку трафика функцией net_rx_action в обоих случаях почти одинаково: ~23.1% vs. ~23.4%;

• Среднее время затрачиваемое в секунду в функциях _do__softirq, net_rx_action, vmxnet3_poll_rx_only, net_rps_send_ipi и process_backlog в обоих случаях почти одинаково. Отклонение времени в vmxnet3_poll_rx_only на некоторых ядрах процессора зависит от количества пакетов полученных на этом ядре (если быть более точным — на rx-queue ассоциированной с соответствующим ядром процессора);

• Выглядит так, что проблема где-то в SOFTIRQ аккаунтинге.

Исследование SOFTIRQ accounting'а

После чтения исходных кодов ядра Linux методом пристального вглядывания, стало понятно, что SOFTIRQ accounting производится в разных функциях, одна из них —  irqtime_account_process_tick, и для нас она наиболее интересна. Комментарий в этой функции сообщает следующее: 

When returning from idle, many ticks can get accounted at once, including some ticks of steal, irq, and softirq time.

Эта функция может быть включена/отключена на уровне конфига ядра с помощью опции CONFIG_IRQ_TIME_ACCOUNTING. Когда она включена, SOFTIRQ accounting производится более аккуратно, и наоборот — когда эта опция отключена, тики процессора могут быть подсчитаны неточно :(

[root@str01-t01-**r01 ~] # cat /boot/config-4.19.125-1.el7.x86_64 | grep "CONFIG_IRQ_TIME_ACCOUNTING"
# CONFIG_IRQ_TIME_ACCOUNTING is not set

и

[root@str01-t01-**r02 ~] # cat /boot/config-5.4.17-2102.200.13.el7uek.x86_64 | grep "CONFIG_IRQ_TIME_ACCOUNTING"
CONFIG_IRQ_TIME_ACCOUNTING=y

Выглядит так, что CentOS 7 с ядром 4.19.125-1 считает тики процессора не точно, а Oracle Linux 7 с ядром 5.4.17-2102.200.13.el7uek показывает более реальную статистику утилизации процессора в SOFTIRQ. Для подтверждения этой гипотезы было собрано новое ядро Oracle Linux 7 5.4.17-2102.200.13.el7uek с отключенной опцией CONFIG_IRQ_TIME_ACCOUNTING (это было сделано на str01-t01-**r03):

• Левый график — нагрузка на str01-t01-**r01 с CentOS 7 с ядром 4.19.125-1 с отключенной CONFIG_IRQ_TIME_ACCOUNTING опцией;

• Центральный график — нагрузка на str01-t01-**r02 с Oracle Linux 7 с ядром 5.4.17-2102.200.13.el7uek с включенной CONFIG_IRQ_TIME_ACCOUNTING опцией;

• Правый график — нагрузка на str01-t01-**r03 с Oracle Linux 7 с пересобранным ядром 5.4.17-2102.200.13.el7uek с отключенной CONFIG_IRQ_TIME_ACCOUNTING опцией.

Заключение

Теперь можно точно сказать — Oracle Linux 7 c ядром 5.4.17-2102.200.13.el7uek и включенной опцией CONFIG_IRQ_TIME_ACCOUNTING более точно производит подсчет тиков процессора и показывает более реальную статистику утилизации процессора, чем CentOS 7 с ядром 4.19.125-1 и выключенной опцией CONFIG_IRQ_TIME_ACCOUNTING.

Спасибо, что прочли до конца, я буду рад вопросам и постараюсь на них ответить в комментариях.