Захватывающая ловля багов, которые портили работу Unbound

Привет, меня зовут Сергей Качеев, я старший разработчик в отделе сетевой инфраструктуры Яндекса. Сегодня я расскажу целый сетевой детектив о том, как мы искали баг, который убивал DNS сервер Unbound. Приготовьтесь, он будет долгим.

Всё началось с того, что мне предложили помочь ребятам из команды DNS найти такие метрики и наборы запросов, по которым будет однозначно понятно, какие настройки влияют на производительность Unbound и какие запросы вызывают у него проблемы.

В самом начале на графиках нагрузочного тестирования я увидел очень плохие результаты: случайным образом абсолютно все запросы нагрузочного теста таймаутились, но сервер, который был под нагрузкой, никак не реагировал на проблему. Как выяснилось позже, по чистой случайности я допустил ошибку в конфигурации нашего плагина Pandora, и в итоге он сам ходил в DNS на каждый запрос, чтобы узнать ip адрес тестируемого сервера. Возможно, это сыграло мне на руку и помогло найти первую из проблем, а потом и вовсе задало вектор поисков остальных багов. А в Unbound их накопилось достаточно.

Уточню, что тестирование проводилось в LXC-контейнере, которому было доступно 48 ядер и 128 Гб памяти. У сервера, на котором запущен контейнер, были следующие характеристики:  

CPU: x2 Intel(R) E5-2660 v4 @ 2.00GHz - total Cores: 28 Threads: 56 
MEM: x4 Samsung 32GiB 2933MHz - total 128GiB
NET: Intel 82599 10Gbit/s

Нагрузка подавалась по сети с контейнеров, расположенных на отдельных физических серверах.

Архитектура worker в Unbound

Начнём с того, как устроен Unbound. По сути, это демон, который запускает несколько тредов. Каждый тред запускает свой event loop. В библиотеку обработки событий Unbound передаёт набор callback-функций, которые реагируют на различные сетевые события: например, запрос от пользователя, передача файловых зон, ответ на рекурсивный запрос и другие.

Вот так работает Unbound

Вот так работает Unbound

Для балансировки между тредами Unbound использует опцию при создании прослушивающего сокета SO_REUSEPORT. С ней ядро Linux само решает, в какой тред направить тот или иной запрос пользователя. Об этом подробнее написано в статье Linux TCP SO_REUSEPORT — Usage and implementation.

Далее event loop получает от операционной системы уведомления о пришедших пакетах и запускает callback-функции. Всё просто.

Ещё одна важная деталь. Для ускорения ответов из кэширующих серверов мы используем конфигурацию hyperlocal zone. Она подразумевает, что на DNS серверах хранится копия auth-zone — то есть файла, в котором хранятся DNS-записи. За счёт этого ответы пользователям отдаются быстрее, потому что данные считываются на месте, а не создаётся отдельный запрос в authority-сервер. Передаются эти файлы с мастера на реплики через механизмы, встроенные в Unbound.

Вздрыжни. И причём тут файловые Authority Zone

В самом начале я упомянул про интересный случай. Инструмент для тестирования  перед каждым запросом резолвил адрес тестируемого сервера. Иногда такие запросы в DNS таймаутились.

Проблема была в том, что я не знал истинную причину таймаутов. Я не мог понять, что не так именно с моим стендом: почему тестирование у других коллег проходит без таких всплесков 100% таймаутов. Какая же была взаимосвязь между этими таймаутами и поведением load-стенда?

Пример плохого результата нагрузочного теста

Пример плохого результата нагрузочного теста

Поясню, что происходит на графиках. Тайминги запросов иногда очень большие и в это же время появляются 502 ошибки. Уточню, что изначально overload.yandex.net специализировался на показе результатов тестирования http-сервисов, и поэтому коды ответа показываются как HTTP. Но на самом деле в плагине Pandora мы используем такую трансляцию ошибок:

DnsServerTimeout:   	502,
DnsAmmoNotSupported:	503,
dns.RcodeSuccess:   	200,
dns.RcodeFormatError:   400,
dns.RcodeServerFailure: 401,
// NXDOMAIN
dns.RcodeNameError:  	402,
dns.RcodeNotImplemented: 403,
dns.RcodeRefused:    	404,
dns.RcodeYXDomain:   	405,
dns.RcodeYXRrset:    	406,
dns.RcodeNXRrset:    	407,
dns.RcodeNotAuth:    	408,
dns.RcodeNotZone:    	409,
dns.RcodeBadSig:     	410,
dns.RcodeBadKey:     	411,
dns.RcodeBadTime:    	412,
dns.RcodeBadMode:    	413,
dns.RcodeBadName:    	414,
dns.RcodeBadAlg:     	415,
dns.RcodeBadTrunc:   	416,
dns.RcodeBadCookie:  	417,

Я крутил всё, что только мог в настройках LXD-контейнера, в котором крутился стенд. Я переносил стенд на выделенные ядра и перемещал данные Unbound в tmpfs. Не помогало. Больше всего смущало то, что эффект совершенно не зависел от нагрузки: 1rps, 1Krps, 5Krps — неважно! Всё так же появлялись 100% таймаутов.

Я изучил все сомнительные места в коде Unbound: смотрел на всё, что только мог тулами из bcc-tools, bpf-tools и atop. И ведь нашёл что-то подозрительное! Иногда моменты вздрыжней (так мы назвали этот эффект в команде DNS) совпадали с моментом записи файловых зон.

В документации об этом написано так:

Authority zones can be read from zonefile. And can be kept updated via AXFR  and  IXFR. After  update the zonefile is rewritten.

Я начал копать в этом месте. Очередная попытка: atop и bpftrace запущены, netdata открыта. Смотрим, ждём.

ns-load.name:~$ sudo bpftrace -e 'tracepoint:syscalls:sys_enter_openat
                   //              |,---------------^
                   //  какое событие в системе мы собираемся мониторить.
                   //  Про это можно почитать в документации man bpftrace, 
 //  и там же про kprobe и uprobe.
//  // - это комментарий в коде bpftrace-скрипта.
//  ,- filter, ловить события только от Unbound,
//  |  запущенного в этом lxc-контейнере,
//  |  а если точнее — только в cgroup, 
//  |  созданной этим systemd-сервисом.
/cgroup == cgroupid("/sys/fs/cgroup/unified/system.slice/unbound.service")/
// Однострочник, срабатывающий на каждое системное событие — в данном случае tracepoint
{ printf("%s %s %s\n", strftime("%H:%M:%S", nsecs), comm, str(args->filename)); }' | grep slave  # нам интересны только зоны
14:03:22 unbound /etc/unbound/slave/db.yandex.net.tmp2136807
14:03:29 unbound /etc/unbound/slave/cloud.yandex.net.tmp2136807
14:03:33 unbound /etc/unbound/slave/db.yandex.net.tmp2136807
14:03:41 unbound /etc/unbound/slave/cloud-preprod.yandex.net.tmp2136807
14:03:45 unbound /etc/unbound/slave/db.yandex.net.tmp2136807
14:03:53 unbound /etc/unbound/slave/db.yandex.net.tmp2136807
14:03:59 unbound /etc/unbound/slave/yandexcloud.net.tmp2136807

Хорошо, какую-то случайную корреляцию я поймал. Пусть она не стабильна, но это хоть какой-то результат.

В atop/htop видно, что при записи файловой зоны тред, который этим занимается, на несколько секунд съедал всё процессорное ядро под 100%. А самая большая из этих зон занимает приблизительно 70 МБ на диске — на ней проблема проявляется ярче всего.

Для проверки я решил отключить auth-zone и заменить одну из них на local-zone, которые не пишутся на диск. Попробовал провести нагрузку запросами, ходящими только в эту local-zone. И каково было моё удивление, когда первый тест выдал мне желаемый результат, а следующий был даже хуже предыдущих — вздрыжни не прошли.

В этот момент я начал сомневаться во всех инструментах, и во всех предыдущих догадках. Постепенно я перешёл к дебагу Pandora. Спустя время я нашёл проблему в конфигурации и поправил плагин, чтобы он не разрешал указывать DNS имя в качестве target. Получается, что я ловил те самые вздрыжни, но со стороны плагина, который ходил в DNS. Нагрузочное тестирование в local-zone и auth-zone тоже показало желаемое — проблемы в local-zone нет, а в auth-zone есть.

Возвращаемся к дебагу auth-zone. У меня было чёткое совпадение небольшого фона таймаутов с моментом перезаписи файла файловой зоны.

         15:38:59: open path: slave/db.yandex.net.tmp926625 # << сброс файловой
                                                            # зоны во временный файл,
                                                            # тут начинает гореть CPU у треда
       7 2022-11-18T15:38:59   # << кол-во ошибок
      32 2022-11-18T15:39:00
   	 15:39:03: open path: slave/cloud.yandex.net.tmp926625
   	 15:39:12: open path: slave/cloud.yandex.net.tmp926625
   	 15:39:15: open path: slave/yandexcloud.net.tmp926625
   	 15:39:19: open path: slave/cloud.yandex.net.tmp926625
   	 15:39:21: open path: slave/db.yandex.net.tmp926625
       2 2022-11-18T15:39:21
      22 2022-11-18T15:39:22
       3 2022-11-18T15:39:23
   	 15:39:28: open path: slave/cloud.yandex.net.tmp926625
   	 15:39:33: open path: slave/yandexcloud.net.tmp926625
   	 15:39:37: open path: slave/db.yandex.net.tmp926625
      29 2022-11-18T15:39:37
      13 2022-11-18T15:39:38

Из кода я понял, какой callback-функцией Unbound отвечает пользователю: comm_point_udp_callback. Чтобы увидеть медленные ответы на запросы, достаточно замерить время работы её внутренней функции worker_handle_request.

Смотрим на её тайминги:

srv58:~$ sudo funclatency-bpfcc -u  /usr/sbin/unbound-1.17.0-release:worker_handle_request -p 1953108
Tracing 1 functions for "/usr/sbin/unbound-1.17.0-release:worker_handle_request"... Hit Ctrl-C to end.
^C
     usecs               : count     distribution
         0 -> 1          : 3        |                                        |
         2 -> 3          : 304      |                                        |
         4 -> 7          : 5630     |******                                  |
         8 -> 15         : 35734    |****************************************|
        16 -> 31         : 12844    |**************                          |
        32 -> 63         : 1281     |*                                       |
        64 -> 127        : 215      |                                        |
       128 -> 255        : 53       |                                        |
       256 -> 511        : 46       |                                        |
       512 -> 1023       : 26       |                                        |
      1024 -> 2047       : 0        |                                        |
      2048 -> 4095       : 1        |                                        |
Detaching...

Все ответы выполняются в пределах одной миллисекунды — где же таймауты?

Вспоминаем, что Unbound использует разные виды callback-функций и для записи файловых зон используется функция auth_xfer_transfer_tcp_callback:

ns-load.name:~$ sudo bpftrace -e '
uprobe:/usr/sbin/unbound-1.17.0-release:auth_xfer_transfer_tcp_callback { @start[tid] = nsecs; }
uretprobe:/usr/sbin/unbound-1.17.0-release:auth_xfer_transfer_tcp_callback /@start[tid]/ { @ns[comm,pid] = hist((nsecs - @start[tid]) / 1e3); delete(@start[tid]); }'
Attaching 2 probes...
^C

@ns[unbound, 2020368]:
[64K, 128K)            4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@                  |
[128K, 256K)           6 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[256K, 512K)           3 |@@@@@@@@@@@@@@@@@@@@@@@@@@                          |
[512K, 1M)             0 |                                                    |
[1M, 2M)               0 |                                                    |
[2M, 4M)               2 |@@@@@@@@@@@@@@@@@                                   |
# K — миллисекунды, M — секунды

В выводе видно, что большинство вызовов функции auth_xfer_transfer_tcp_callbackвыполняется примерно за 256 миллисекунд — это относительно быстро. Но есть и такие, которые занимают по 4 секунды, и это очень долго.

Когда я снова вернулся к архитектуре и коду Unbound, выяснилось, что ответ пользователю comm_point_udp_callback с worker_handle_request внутри и auth_xfer_transfer_tcp_callback с auth_zone_write_file — это два разных callback, которые не могут одновременно работать в треде.

Вот как это работает. Когда Ядро Linux принимает udp/tcp-пакет, оно отправляет его в очередь на приём случайного треда из-за включенной опции SO_REUSEPORT. Затем libevent получает нотификацию и запускает callback, а другие udp/tcp пакеты в очереди этого треда ждут его выполнения. Поэтому важно, чтобы callback выполнялся быстро.

Я выяснил, что в случае auth_xfer_transfer_tcp_callback его тормозит auth_zone_write_file. Получается, что запросы ждут записи файловой зоны. При этом перемещение файловых зон в tmpfs не даёт желаемого эффекта, потому что основное время уходит на сериализацию и бесконечное множество вызовов write.

Посоветовавшись, мы вынесли запись файловых зон в отдельный тред, который ничем другим не будет заниматься. Мы подготовили патчи в наш локальный форк и в upstream PR#794 (правда, пока он требует доработки под все поддерживаемые платформы).

Продолжаем поиски ошибок

Как мы знаем, баги не приходят поодиночке, поэтому я приступил к поискам остальных. После очередного разбора инцидента c Unbound ребята из команды DNS добавили во внутренний инструмент автоматизации несколько функций:

  • автоматическое снятие дампа памяти процесса Unbound;

  • снятие стек трейсов по всем тредам (не через thread apply all bt, а индивидуально для каждого треда);

  • замер производительности perf утилитой;

  • сбор логов.

Всё, что оставалось — дождаться момента активации триггера на аномальное повышение Load Average системы и изучить всё собранное. А я продолжил заниматься лоад-стендом.

Немного спустя у нас появился  дамп памяти, собранный при аномальном повышении Load Average, и тут начинается самое интересное. Первое, что бросилось в глаза при осмотре снятых stack trace — почти все треды висели на pthread_spin_lock. Unbound использует их в местах, где, по его мнению, будет очень быстрый доступ. 

Для наглядности покажу, как это выглядело в coredump

gdb /usr/sbin/unbound
(gdb) core-file core_534009.gdb
warning: core file may not match specified executable file.
[New LWP 534009]
...
#0  0x00007f8fa0d22d15 in pthread_spin_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
[Current thread is 1 (Thread 0x7f8fa1557dc0 (LWP 534009))]
(gdb) info threads
  Id   Target Id                           Frame
* 1    Thread 0x7f8fa1557dc0 (LWP 534009)  0x00007f8fa0d22d15 in pthread_spin_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
// тут много тредов относящиеся к yp_dns, нам они неинтересны
...
  87   Thread 0x7f8f68f74700 (LWP 535239)  0x00007f8fa0d22d12 in pthread_spin_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
  88   Thread 0x7f8f68773700 (LWP 535240)  0x00007f8fa0d22d15 in pthread_spin_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
  89   Thread 0x7f8f6715f700 (LWP 535241)  0x00007f8fa0d22d15 in pthread_spin_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
  90   Thread 0x7f8f6695e700 (LWP 535242)  0x00007f8fa0d22d15 in pthread_spin_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
  91   Thread 0x7f8f6615d700 (LWP 535243)  0x00007f8fa0d22d15 in pthread_spin_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
  92   Thread 0x7f8f650f3700 (LWP 535244)  0x0000000002fef501 in bin_find_entry (table=0x75b7fb42c80, bin=, hash=2852359060, key=0x75f1ab5cdd0) at /-S/contrib/tools/unbound/util/storage/lruhash.c:223
  93   Thread 0x7f8f648f2700 (LWP 535245)  0x00007f8fa0d22d12 in pthread_spin_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
... // Все треды, висящие на pthread_spin_lock
  104  Thread 0x7f8f5db8d700 (LWP 535256)  0x00007f8fa0d22d15 in pthread_spin_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
  105  Thread 0x7f8f5d38c700 (LWP 535257)  0x00007f8fa0d22d15 in pthread_spin_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
... // Все треды, висящие на pthread_spin_lock
  117  Thread 0x7f8f18385700 (LWP 535269)  0x00007f8fa0d22d15 in pthread_spin_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0  0x00007f8fa0d22d15 in pthread_spin_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x0000000002fef852 in lruhash_lookup (table=0x75b7fb42c80, hash=2948070628, key=key@entry=0x7fff134b2ae8, wr=wr@entry=0) at /-S/contrib/tools/unbound/util/storage/lruhash.c:362
#2  0x0000000002ff0dae in slabhash_lookup (sl=sl@entry=0x75b7f1a68c0, hash=2948070628, key=0x7fff134b2a01, key@entry=0x7fff134b2ae8, wr=wr@entry=0) at /-S/contrib/tools/unbound/util/storage/slabhash.c:125
#3  0x0000000002f849e6 in rrset_cache_lookup (r=0x75b7f1a68c0, qname=, qnamelen=, qtype=qtype@entry=1, qclass=qclass@entry=0, flags=flags@entry=0, timenow=1670937529, wr=0) at /-S/contrib/tools/unbound/services/cache/rrset.c:293
... // Остальное нам пока неинтересно.
(gdb) thread 92
[Switching to thread 92 (Thread 0x7f8f650f3700 (LWP 535244))]
#0  0x0000000002fef501 in bin_find_entry (table=0x75b7fb42c80, bin=, hash=2852359060, key=0x75f1ab5cdd0) at /-S/contrib/tools/unbound/util/storage/lruhash.c:223
223	/-S/contrib/tools/unbound/util/storage/lruhash.c: No such file or directory.
(gdb) bt
#0  0x0000000002fef501 in bin_find_entry (table=0x75b7fb42c80, bin=, hash=2852359060, key=0x75f1ab5cdd0) at /-S/contrib/tools/unbound/util/storage/lruhash.c:223
#1  lruhash_insert (table=0x75b7fb42c80, hash=hash@entry=2852359060, entry=entry@entry=0x75f1ab5cdd0, data=0x75f31a7f4e0, cb_arg=cb_arg@entry=0x75b60f3c088) at /-S/contrib/tools/unbound/util/storage/lruhash.c:320
#2  0x0000000002ff0d8e in slabhash_insert (sl=sl@entry=0x75b7f1a68c0, hash=448122320, hash@entry=2852359060, entry=0x75f30e5e366, entry@entry=0x75f1ab5cdd0, data=0x75f31a7f4e0, arg=arg@entry=0x75b60f3c088) at /-S/contrib/tools/unbound/util/storage/slabhash.c:119
#3  0x0000000002f84685 in rrset_cache_update (r=0x75b7f1a68c0, ref=ref@entry=0x7f8f650f0d60, alloc=0x75b60f3c088, timenow=1670937529) at /-S/contrib/tools/unbound/services/cache/rrset.c:227
...

Итак, я обнаружил два узких места: выполнение bin_find_entry и ожидание лока в функции lruhash_lookup.

Снова про архитектуру — кэши

Я вновь погрузился в изучение кода — на этот раз в архитектуру кэшей. В Unbound есть самописная concurrent hash map для хранения кэшей запросов. Это структура в lruhash.h#L147, которая выглядит вот так:

 struct lruhash {
	lock_quick_type lock;       /** lock for exclusive access, to the lookup array */
	struct lruhash_bin* array;  /** lookup array of bins */

	size_t num; 	            /** the number of entries in the hash table. */
	size_t size;                /** the size of the lookup array */
	size_t space_used; 	    /** the amount of space used, roughly the number of bytes in use. */
	size_t space_max; 	    /** the amount of space the hash table is maximally allowed to use. */
        // ... я оставил только полезные нам поля
};

Внутри lruhash хранится массив бинов, в которые и помещаются записи кэш запросов — классическая хэш-таблица с linked list. Один lruhash_bin (для краткости просто BIN) выглядит так:

struct lruhash_bin {
	lock_quick_type lock;                   /* Lock for exclusive access to the linked list	 */
	struct lruhash_entry* overflow_list; 	/* linked list of overflow entries */
};

lruhash_entry (для краткости просто ENTRY) — это запись нашего запроса в кэше. В детали тут можно не вдаваться.

Доступ к разным lruhash выполняется без локов. Все lruhash спрятаны внутри slabhash. Хэш мап — фиксированного размера и работает только на чтение. slabhash-структура в slabhash.h#L57 выглядит вот так:

struct slabhash {
    // Просто предаллоцированный массив lruhash,
    // доступ к которым идёт по кусочку от хэша данных из запроса/ответа
    struct lruhash** array;  /** lookup array of hash tables */
 
    // это используется для адресации
    size_t size; 	      	/** the size of the array - must be power of 2 */
    uint32_t mask; 	  /** size bitmask - uses high bits. */
    unsigned int shift;  	  /** shift right this many bits to get index into array. */
};

Любимые самописные хэш таблицы с такими любимыми багами и фичами! Ниже я попытался схематично изобразить структуру slabhash:

                       ,- Доступ по этому индексу выполняется без локов,        
                      /   потому что этот массив фиксированного размера, заданного на старте,
                     /    а индекс используется только для чтения массива.
                    /
slabhash->array[-size]

                        ,------  Для доступа по этому индексу уже используется spin_lock(*1), потому-что
                       /         этот массив может быть реаллоцирован и это операция на запись. Для экономии
   [0]lruhash->array [...]       места на старте процесса этот массив маленького размера — всего 1024.
                                 Когда массив заполняется (lruhash->num >= lruhash->size) он реаллоцируется
                                 по мере заполнения кэша. Например, для 10G, этот размер может вырасти до
                                 1048576. А это значит, что после очередной реаллокации придётся
                                 скопировать по новому массиву 1048576/2 BIN-ов из старого.
                                 Эта операция не требует перевычисления хэша или вызова `strcmp`.
                                 Её сложность О(N) от размера массива, но делается она под локом!
   
   [1]lruhash->array [BIN, BIN, BIN, BIN, _, ...] - массив, реаллоцируемый при необходимости.
   [2]...              8    8    8     \
                            8    8      ` - на BIN тоже берётся  spin_lock (*2)
                            8
   [3]...                    `- linked-list из ENTRY, используется для разрешения коллизий в нижней части хэша,
   [4]...                       которая нужна для адресации внутри `lruhash->array`.
                                Unbound, как и все хэш таблицы, старается держать по одному элементу в бине, 
                                но хэш функция, как правило, даёт коллизии, 
                                и в бине хранится от 0 до 13 entry (выяснено на практике).
                                Для изменения ENTRY защищены (*3)mutex-ом.
                                Размер linked-list ограничен по следующей формуле:
                                CACHE-SIZE / -SLABS / len(LRUHASH->ARRAY.)
                                Видно, что это значение контролируется на старте через количество
                                -SLABS(параметр в конфигурации), а дальше — в runtime через длину
                                len(LRUHASH-ARRAY) после каждой реаллокации.
   [5]...
   [6]lruhash->array
   [7]lruhash->array [...]

Для уменьшения lock contention (то есть попыток захватить уже захваченный другим тредом лок) используется slabhash->array — глобальный lock-free объект. Каждый отдельный lruhash->array — это тоже глобальный объект и все треды работают с ним конкурентно. Но каждый lruhash работает со своим набором локов. То есть два lruhash могут работать параллельно на двух тредах, не блокируя друг друга.

Немного подробностей про способ адресации в этих структурах. Допустим, есть некий хэш 1234567890. В зависимости от количества выбранных слабов Unbound выбирает mask и shift. Это нужно, чтобы определять, в какой lruhash и bin попадает запись. Условно, для размера 32 Unbound делит хэш примерно так:

   , - Верхняя часть хэша берётся для адресации внутри slabhash->array[N] — то есть, между слабами.
  /     ,- Нижняя часть хэша урезается по текущему размеру LRU и определяет 
 /     /   индекс в lruhash->array, в какой bin попадёт entry.
12 | 34567890
  \
   ` - Формируется так: битовая маска, рассчитанная на основе размера slabhash->array
                        (hash & 0b11111000000000000000000000000000) >> shift (на количество нулей в маске)

Слабы защищены набором локов: pthread_spin_lock для slab->array->lock / bin->lock и pthread rw lockна entry->lock.

Итак, при большом количестве SLABS (lruhash-таблиц внутри slabhash->array) поток запросов будет меньше блокироваться, потому что в разные lruhash запросы пройдут без лока. А это значит, что на каждый lruhash придётся меньше запросов в единицу времени, и lock contention на *1-spin → *2-spin → *3-mutex в lruhash->array будет меньше.

               | | | | | | | | | | | | | | | |
slabhash       [    -size         ]
               | | | | | | | | | | | | | | | |
               | | | | | | | | | | | | ...
                \/ | | | | | | | | | |
[1]lruhash->array   \/ | | | | | |
    [2]lruhash->array   \/ | | | |
        [3]lruhash->array  | | ...
                      	...

А для малого количества SLABS больше запросов будут утекать в один lruhash, увеличивая lock contention на его spinlock.

         | | | | | | | | | | | | | | | |
          \| | | | | | | | | | | | | |/
            \| | | | | | | | | | | |/
              \| | | | | | | | | |/
                \| | | | | | | |/
                  \| | | | | |/
                    \| | | |/
slabhash             [size]
                     ||| |||
       [1]lruhash->array |||
            [2]lruhash->array ...
                          `- напомню, что тут spin_lock

Конечно, минусы у больших значений SLABS тоже есть. Они заключаются в размере кэша на старте, и, как показала практика, в накладных расходах на сбор статистики слабов. При большом значении SLABS Unbound должен на старте аллоцировать огромный массив slabhash->array и создать кучу lruhash->array, у каждого из которых есть стартовый размер 1024. Но этот минус даёт и плюс: из-за большого размера slabhash->array каждый linked-list внутри lruhash->array[BIN] ограничен формулой, которую я привёл на диаграмме. То есть, вот такого не произойдёт:

entry->entry->entry->entry-> x278555 entry->entry->entry->entry->entry->...

Поиск по такому linked-list требует для каждого entry->dname вызывать strcmp.

Каждый запрос проходит через кэш как минимум один раз, при этом локи на кэш берутся многократно. Unbound местами слишком оптимистично берёт лок на lruhash→array на всю операцию c ENTRY внутри BIN и порой не отпускает его очень долго. Другими словами: поле для ускорения Unbound всё ещё есть!

Почему важно чаще отпускать лок? Дело в том, что хоть Unbound и старается держать в бинах по одному элементу, иногда случается коллизия хэш-функции и в бин может попасть несколько элементов. Для поиска элемента в бине используется самописный strcmp [slabhash.c#L50]→[daemon.c#L991]→[msgreply.c#L623]→[dname.c#L100], который находится очень далеко в плане скорости от spinlock.

В какой-то из книжек по Linux я читал, что нормальное использование спинлока — это защититься для взятия указателя, и не более. Потом я нашёл замечательную статью spinlock vs mutex performance, которая подтвердила мои догадки, описанные ниже.

Итак, пока выполняется сравнение строк DNS записей для поиска нужного элемента, в BIN все треды ждут на spin_lock lruhash->array, где находится данный BIN. Если вдруг linked-list из ENTRY в нём длиннее десяти записей, все треды ждут ощутимый промежуток времени и здорово греют воздух. На этом этапе должно быть очевидно, что больше слабов — хорошее решение.

На этом же этапе можно возразить: «Да ладно, обход коллизии даже в 1000 элементов не должен взрывать Unbound так, чтобы вызвать отказ в обслуживании. Греть воздух будет здорово, но не взрывать».

И тут я спешу напомнить про реаллокацию [lruhash.c#L338]→[lruhash.c#L231]→[lruhash.c#L117]. Особенность реализации lruhash->array такова, что какой бы большой кэш мы не выбрали, на старте у него будет размер 1024 элементов HASH_DEFAULT_STARTARRAY. Когда этот массив заполняется, Unbound аллоцирует новый массив в два раза большего размера и копирует под spinlock старый массив в новый. Теперь точно не должно быть возражений :)

Как действуют SLABS

Предыдущая часть была немного утомительной — настало время размяться. Берём наши текущие настройки:

     msg-cache-size: 4G   # В проде замечено 14 - 16 М записей
     msg-cache-slabs: 32  # По рекомендации из официальной доки

Получаем, что у нас в одном lruhash->array может быть 14М / 32 = 437500 элементов. Доступ до элемента slabhash->array[hash(левая часть хэша) % modulo]->lruhash->array[hash(правая часть хэша) % modulo]везде идёт по смещению — кажется, тут нечему тупить. Вспоминаем, что под локом ещё выполняется strcmp.

Дальше представляем, что есть не одна коллизия и есть бины больше одного элемента. В итоге получаем, увеличенный фон LA. Проверяем эту теорию. Ставим четыре слаба, чтобы стало заметнее, берём примерно 900к уникальных записей, добавляем 60% попадания в кэш.

awk -v cache=dns-30k.ammo '
{
  print; n=0;
  while(n < 2){
    ret=getline < cache;
    if (!ret){close(cache);}else{n++; print;}
  }
}' < dns.ammo > dns-870k+60prc-hits.ammo

Запускаем тестирование постоянной нагрузкой в 5Krps. Видим, что реаллокации портят тайминги.

Зелёным отмечен рост кэша. 

Зелёным отмечен рост кэша. 

Если взять msg-cache-slabs: 1024, то каждый слаб будет содержать примерно по 10к сообщений размером 512 байт. Это сильно сокращает накладные расходы на реаллокацию и поиск в случае коллизий.

Перезапускаем Unbound, подаём ту же нагрузку — и теперь не страшно посмотреть даже на 100-ый перцентиль ответов.

Тайминги при msg-cache-slabs: 1024

Тайминги при msg-cache-slabs: 1024

Казалось, вот она — победа! Правильные настройки найдены, дальше только патчить Unbound — то есть ювелирно отпускать лок на lruhash->array во всех местах, где это возможно, в том числе при реаллокации массива.

Больше доказательств!

А вот ещё замеры моментов сработки table_growчерез bpftrace и её тайминги. Тут представлены времена реаллокаций:

ns-load.name:~$ sudo bpftrace -e '
BEGIN { printf("%s GO go go!\n", strftime("%H:%M:%S", nsecs)); } uprobe:/usr/sbin/unbound-1.17.0-release-threaded-zone-write:table_grow {printf("%s Oops! table_grow!\n", strftime("%H:%M:%S", nsecs)); }'
Attaching 2 probes...

11:11:29 GO go go!
11:11:48 Oops! table_grow!
11:11:48 Oops! table_grow!
11:11:48 Oops! table_grow!
11:11:48 Oops! table_grow!
11:11:48 Oops! table_grow!
11:11:48 Oops! table_grow!
11:11:48 Oops! table_grow!
11:11:48 Oops! table_grow!
11:11:50 Oops! table_grow!
11:11:50 Oops! table_grow!
11:11:50 Oops! table_grow!
11:11:50 Oops! table_grow!
…

А тут — тайминги работы table_grow (всего на 900к записях, это далеко не 18М):

ns-load.name:~$ sudo bpftrace -e '
uprobe:/usr/sbin/unbound-1.17.0-release-threaded-zone-write:table_grow { @start[tid] = nsecs; } uretprobe:/usr/sbin/unbound-1.17.0-release-threaded-zone-write:table_grow /@start[tid]/ { @ns[pid] = hist((nsecs - @start[tid]) / 1e6); delete(@start[tid]); }'
Attaching 2 probes...
^C

@ns[3540330]:
[0]                    8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[1]                    5 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@                    |
[2, 4)                 3 |@@@@@@@@@@@@@@@@@@@                                 |
[4, 8)                 6 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@             |
[8, 16)                2 |@@@@@@@@@@@@@                                       |
[16, 32)               4 |@@@@@@@@@@@@@@@@@@@@@@@@@@                          |
[32, 64)               4 |@@@@@@@@@@@@@@@@@@@@@@@@@@                          |
[64, 128)              4 |@@@@@@@@@@@@@@@@@@@@@@@@@@                          |
#     |                 `- Количество вызовов. По нему можно судить о том,
#     |                     что растут msg-, rrset- и ещё какие-то слабы
#      `- Миллисекунды!
#         128 миллисекунд!
#         Все CPU, которые захотели в реаллоцируемый слаб,
#         ждали на spinlock до 128 миллисекунд!

Это всё подтверждает flamegraph. Ниже представлен итог, собранный инструментом автоматизации, вместе с интересным coredump.

Обратите внимание на процент времени CPU, который занимают подсвеченные функции (правый нижний угол Matched)

Обратите внимание на процент времени CPU, который занимают подсвеченные функции (правый нижний угол Matched)

А вот flamegraph под нагрузкой с малым значением msg-cache-slabs. Всего  4Krps, но в gdb и perf уже видно контеншен на лок

А вот flamegraph под нагрузкой с малым значением msg-cache-slabs. Всего  4Krps, но в gdb и perf уже видно контеншен на лок

И flamegraph под нагрузкой с большим значением msg-cache-slabs. Картинка улучшается почти в два раза: при больших rps и большем наполнении кэша разница будет ещё больше не в пользу slabs: 32

И flamegraph под нагрузкой с большим значением msg-cache-slabs. Картинка улучшается почти в два раза: при больших rps и большем наполнении кэша разница будет ещё больше не в пользу slabs: 32

Мы сразу решили проверить всё это на практике и выкатили настройку на проблемный хост.

Самый говорящий график — это, конечно же, LA. Я думаю, ни у кого не будет сомнений, что эффект очевиден.

Дальше я покажу скрины netdata про последние два рестарта: первый до увеличения количества слабов, второй — после.

Суровая реальность: сколько rps убивает Unbound

И на этом моменте читатель может задаться вопросом: «Но ведь тут такая интересная корка! Почему о ней ничего нет?» Настало время рассказать и про неё. Coredump здесь и правда очень интересный. Прежде всего тем, что в нём можно покопаться и увидеть реальную картину происходящего.

Итак, параллельно с изучением кода и проведением нагрузочных тестов я занимался изучением дампа памяти процесса. Напомню, что Unbound пытается держать размеры бинов равными единице и это условие успеха: тогда лок на lruhash->array всегда будет браться и отпускаться моментально, кроме случая table_grow.

С помощью coredump можно оценить, насколько долго будет держаться лок взятый на lruhash->array, исследуя размеры бинов. Чтобы выяснить, насколько Unbound удаётся выполнить условие «один бин — одна запись», нужно взять корку с плохой ноды (у нас как раз такая есть) и посмотреть на реальные размеры бинов. Но возникает вопрос — как?  

Я знал, что в gdb есть поддержка Python. Пишем простенький скрипт gdb_traverse.py.

Код скрипта gdb_traverse.py

import gdb


class TraverseNodesPrinter(gdb.Command):
    """Prints the ListNode from our example in a nice format!"""

    def __init__(self):
        super(TraverseNodesPrinter, self).__init__("walklist", gdb.COMMAND_USER)

    def invoke(self, args, from_tty):
        # You can pass args here so this routine could actually evaluate different
        # variables at runtime
        print("Args Passed: %s" % args)

        # Let's walk through the list starting with the head
        #
        # We can access value info by looking at:
        #  https://sourceware.org/gdb/onlinedocs/gdb/Values-From-Inferior.html#Values-From-Inferior
        argv = args.split()
        ref = argv.pop(0)
        silent = bool(argv)

        slab_ptr = gdb.parse_and_eval(ref)
        slab_size = slab_ptr["size"]
        print("slab_size=%s" % slab_size)

        total = {}
        for si in range(slab_size):
            slab_max = 0
            percent_max = 0
            count = 0
            node_ptr = slab_ptr["array"] + si
            array = node_ptr["array"]
            size = int(node_ptr["size"])
            next_prc = 10
            if not silent:
                print("slab-%s" % si)
            most_overloaded_bin = 0
            mob_prc = 0
            for i in range(size):
                elem = array + i
                if elem == 0:
                    continue

                overflow_list = elem["overflow_list"]
                local_max = 0
                while overflow_list != 0:
                    local_max += 1
                    overflow_list = overflow_list["overflow_next"]
                if local_max > slab_max:
                    slab_max = local_max
                    most_overloaded_bin = i
                if local_max > percent_max:
                    percent_max = local_max
                    mob_prc = i
                count += local_max

                prc = float(i) / size * 100
                if prc > next_prc:
                    next_prc = prc + 10  # every N%
                    if not silent:
                        print("%s prc current max bin(%s).length %s count %s" % (int(prc), mob_prc, percent_max, count))
                    percent_max = 0
            total[si] = (most_overloaded_bin, slab_max, count)
            if not silent:
                print("100 prc max bin(%s).length %s, count %s nodes" % (most_overloaded_bin, slab_max, count))
                print("")

        total_sum = 0
        global_max = 0
        for si in total:
            most_overloaded_bin, slab_max, count = total[si]
            total_sum += count
            global_max = max(slab_max, global_max)
            if not silent:
                print("slab-%s max bin(%s).length %s count %s" % (si, most_overloaded_bin, slab_max, count))
        print("Found total-max bin.length %s, total=%s nodes" % (global_max, total_sum))


TraverseNodesPrinter()

Загружаем gdb и корку — удачно оказываемся в треде почти в нужном нам контексте (но это сыграет с нами злую шутку).

Вот, что получаем в итоге

$ gdb unbound-1.17.0-r10415458-spinlock
...
Reading symbols from unbound-1.17.0-r10415458-spinlock...
...
(gdb) core core_534009.gdb
warning: core file may not match specified executable file.
[New LWP 534009]
[New LWP 534066]
...
(gdb) bt
#0  0x00007f8fa0d22d15 in ?? ()
#1  0x0000000002fef852 in lruhash_lookup (table=0x75b7fb42c80, hash=2948070628,
    key=key@entry=0x7fff134b2ae8, wr=wr@entry=0)
    at /-S/contrib/tools/unbound/util/storage/lruhash.c:362
#2  0x0000000002ff0dae in slabhash_lookup (sl=sl@entry=0x75b7f1a68c0, hash=2948070628,   	 <<<<< нам нужно сюда
    key=0x7fff134b2a01, key@entry=0x7fff134b2ae8, wr=wr@entry=0)
... # остальное можно опустить

(gdb) up 2
#2  0x0000000002ff0dae in slabhash_lookup (sl=sl@entry=0x75b7f1a68c0, hash=2948070628,
    key=0x7fff134b2a01, key@entry=0x7fff134b2ae8, wr=wr@entry=0)
    at /-S/contrib/tools/unbound/util/storage/slabhash.c:125
125  	  return lruhash_lookup(sl->array[slab_idx(sl, hash)], hash, key, wr);
(gdb) print *sl
$2 = {size = 32, mask = 4160749568, shift = 27, array = 0x75b7f980200}
# ОК, видим 32 слаба и массив слабов
# array тут — это slabhash->array[32] 
...
# один lruhash внутри slabhash->array выглядит так
(gdb) print *sl->array[0]
$6 = {lock = 1, sizefunc = 0x2fdf9c0 ,
  compfunc = 0x2fdfa10 , delkeyfunc = 0x2fdfa90 ,
  deldatafunc = 0x2fdfad0 , markdelfunc = 0x2f843c0 ,
  cb_arg = 0x75b7f340078, size = 524288, size_mask = 524287, array = 0x75e00800000,
  lru_start = 0x75b4c0c19e0, lru_end = 0x75c9c818ff0, num = 424038, space_used = 145144085,
  space_max = 268435456}
 
# один bin выглядит так
(gdb) print sl->array[0]->array[0]
$7 = {lock = 1, overflow_list = 0x75e5da92e10}


# Загружаем наш чудо-инструмент и запускаем его

(gdb) source gdb_traverse.py
(gdb) set pagination off
(gdb) walklist sl

# без silent-режима для большого количества слабов этот инструмент
# напечатает очень много текста, поэтому я сократил вывод

#     ,- N номер слаба в slabhash->array[N]
#   /     		 , - M номер бина в slabhash->array[0](lruhash)->array[M]->lruhash_bin
#  |    		 /      		 ,- размер linked-list у lruhash_bin->overflow_list
slab-0 max bin(309871).length 2748 count 424038 # <- сколько всего записей в этом lruhash
slab-1 max bin(436426).length 164 count 421672
slab-2 max bin(329311).length 18 count 420069
slab-3 max bin(261246).length 8 count 420491
slab-4 max bin(280420).length 33 count 421381
slab-5 max bin(285169).length 905 count 422057
slab-6 max bin(346884).length 6621 count 428844
slab-7 max bin(149391).length 44 count 420415
slab-8 max bin(475314).length 64 count 420950
slab-9 max bin(271580).length 25 count 419529
slab-10 max bin(372061).length 13 count 419983
slab-11 max bin(156506).length 50 count 421106
slab-12 max bin(65704).length 10 count 421407
slab-13 max bin(405913).length 31 count 421779
slab-14 max bin(182546).length 1383 count 422440
slab-15 max bin(51181).length 8 count 420793
slab-16 max bin(305677).length 10 count 420843
slab-17 max bin(229787).length 278 count 420631
slab-18 max bin(383134).length 98 count 420769
slab-19 max bin(278627).length 17 count 419738
slab-20 max bin(243904).length 59 count 421958
slab-21 max bin(232340).length 278555 count 707175
slab-22 max bin(108784).length 30 count 420950
slab-23 max bin(378505).length 190 count 420991
slab-24 max bin(244475).length 78 count 421245
slab-25 max bin(158331).length 8 count 421249
slab-26 max bin(294639).length 8 count 421501
slab-27 max bin(151957).length 13 count 421052
slab-28 max bin(362737).length 64837 count 486955
slab-29 max bin(344255).length 3920 count 424799
slab-30 max bin(399645).length 223 count 422094
slab-31 max bin(419568).length 127725 count 548963
Found total-max bin.length 278555, total=13967867 nodes
                     #      |              `- сколько всего записей в данном слаб
                     #      |                -кэше (slabhash)
                     #       `- самый большой список linked-list, найденный среди всех бинов

Согласитесь, что с первого взгляда и даже со второго totalнам явно показывает, что хэш-функция Unbound, мягко говоря, ненормальная.

Found total-max bin.length 278555, total=13967867 nodes

Она даёт жуткие перекосы на некоторые бины. Из-за таких перекосов обращение в бин с большим linked-list тормозит все треды на жгучем spinlock. Это и заставляет Unbound в агонии просить помощи через алерты на load-average системы. А взрываться оно начинает тогда, когда все жирные слабы (даже в небольшом количестве) насыщаются одновременно и начинают триггерить table_grow.

Эта корка как раз ловит такой момент: у большинства тредов по ~420631 записей в слабах, а это очень близко к следующему table_grow.

Рассчитать моменты реаллокации можно так.

# lruhash->array должен иметь размер степени двойки
# при этом стартовый размер у него 1024
1024*2^9 = 524288 -> 1024*2^10 = 1048576

A некоторые lruhash->array его уже перевалили: у слаба slab-21 — 548963 записей. Вангую, что на десятом реаллокейте вообще всё умрёт :)

Важно: быстрое предположение и неудачное совпадение может повести вас по ложному пути и в итоге привести к ложным выводам. Будьте внимательны и осторожны! Мне повезло, потому что вовремя пришёл коллега с очень интересными примерами запросов, но об этом ниже.

По логике хэш-функцию Unbound надо бы выкинуть и вставить туда какой-нибудь xxhash или whyhash. Либо использовать вариант для бедных: жить с большим количеством мелких слабов.

При маленьких слабах по 8 мб по моим (как выяснилось позже не совсем точным) расчётам в один BIN->linked-list не должно налиться больше 20к записей. Это значит, что даже при очень аномальном поведении хэш функции Unbound, обойти один бин в 20к записей в разы легче, чем один бин в 278k записей.

Жаль, что Unbound между слабами раскидывается той же кривой хэш-функцией slabhash.c#L111→dname.c#L287→lookup3.c#L346. Но делает он это по перво

© Habrahabr.ru