Привет, меня зовут Сергей Качеев, я старший разработчик в отделе сетевой инфраструктуры Яндекса. Сегодня я расскажу целый сетевой детектив о том, как мы искали баг, который убивал 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 использует опцию при создании прослушивающего сокета 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=<optimized out>, 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=<optimized out>, qnamelen=<optimized out>, 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=<optimized out>, 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=<optimized out>, 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[<slab_type>-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 / <type>-SLABS / len(LRUHASH->ARRAY.)
Видно, что это значение контролируется на старте через количество
<type>-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 [ <slab_type>-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Казалось, вот она — победа! Правильные настройки найдены, дальше только патчить 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.
msg-cache-slabs. Всего 4Krps, но в gdb и perf уже видно контеншен на лок
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 <ub_rrset_sizefunc>,
compfunc = 0x2fdfa10 <ub_rrset_compare>, delkeyfunc = 0x2fdfa90 <ub_rrset_key_delete>,
deldatafunc = 0x2fdfad0 <rrset_data_delete>, markdelfunc = 0x2f843c0 <rrset_markdel>,
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 = 1048576A некоторые 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. Но делает он это по первой части хеша, поэтому коллизии будут немного другие. В общем, надежда есть!
Я написал рекомендацию в тикет, и был готов на следующей неделе проверить предположение о кривизне хэш-функции, заменив её. И тут случилась та самая суровая реальность: приходит коллега и говорит, что хоть наша канарейка и стала себя чувствовать лучше по LA, у него есть запросы, тест которыми в 700-1000 rps можно убить сервер. Это было неожиданно.
Чуть позже мы пришли к выводу, что достаточно проводить тест вот такими записями.
$(RANDOM STRING).example.comВ CNAME со звёздочкой *.example.com — это CNAME на example.com.
И позже стало ясно, что в общем виде Pandora-плагин можно научить генерировать запросы по шаблону.
$(RANDOM_STRING).$(DOMAIN) - *.$(DOMAIN) CNAME на $(DOMAIN)Будем называть такие запросы udp-random.
Предварительный тест показал, что реальность действительно сурова: всего 701-rps и Unbound лежит под кучей горящих pthread_spin_lock. А с большим количеством слабов (1024) особо ничего не меняется. Я заметил, что Unbound падает уже на большем rps, где-то больше 1000, но разница так мала, что я не придал ей значения.
Начались выходные...
Ложный след: хэш-функция Unbound ни при чём
Конечно же, я не смог дотерпеть до понедельника!
Я начал думать, где же спряталась ошибка и почему даже с моей рекомендацией спинлоки так плохо работают. Я решил по-быстрому проверить замену хэш-функции: написал небольшой патч, где вставил XXH32, залил бинарник на лоад стенд и нагрузил обычными запросами. К этому моменту я уже понял, что нужно смотреть на два главных кэша, для которых мы выставляем большие размеры:
msg-cache, в котором хранится мета-информация про пришедшие запросы — опции, edns и прочие;rrset-cache, в котором хранится то, во что разрезолвился запрос пользователя RRset types.
Я думал, что проблема в msg-cache, но картина меня приятно удивила. Вот как должна выглядеть нормальная хэш функция:
(gdb) walklist daemon->env->msg_cache
slab_size=64
slab-0 max bin(417).length 6 count 13851
...
slab-63 max bin(2104).length 6 count 13561
Found total-max bin.length 8, total=869285 nodes
`- ЭТО ОЧЕНЬ ХОРОШО! Максимальная длина linked-list
внутри BIN не больше 8 элементов, а значит коллизии
в новой функции очень редкие`
(gdb) walklist &daemon->env->rrset_cache.table
slab_size=128
slab-0 max bin(5570).length 6 count 6856
...
slab-127 max bin(47).length 5 count 6902
Found total-max bin.length 8, total=872176 nodes
`- для RRset тоже всё суперКаюсь, тут я опять поторопился и не проверил запросами udp-random. Они тоже вызывают коллизию в rrset, но в msg_cache коллизии нет — и это уже хорошо! Значит, не будет повышенного LA даже с малым кол-вом слабов.
Для msg_cache слабов картина такая же, как в предыдущем комменте.
(gdb) walklist daemon->env->msg_cache
Args Passed: daemon->env->msg_cache
slab_size=64
Found total-max bin.length 8, total=894370 nodesА для rrset она меняется вот так.
(gdb) walklist &daemon->env->rrset_cache.table
Args Passed: &daemon->env->rrset_cache.table
slab_size=128
...
slab-0 max bin(5570).length 6 count 6856
... # <<<< тут очень хорошее распределение 4-6 entry на bin.
slab-108 max bin(4188).length 6 count 6824
slab-109 max bin(21947).length 25093 count 31838 # <<< аномалия — всего одна на все слабы.
slab-110 max bin(6428).length 6 count 6791
... # <<<< тут очень хорошее распределение 4-6 entry на bin.
slab-127 max bin(47).length 5 count 6902
Found total-max bin.length 25093, total=897272 nodesПримерно в этот момент, я понял, что надо бы проверить ещё и msg-cache для coredump, собранного автоматикой. Но вернулся к этому я только в понедельник.
В понедельник выяснилось, что я зря наговаривал на хэш-функцию Unbound. Проверка теории о коллизиях и свежая голова подтверждают, что хэш функция Unbound работает нормально. Смотрим на ту «интересную корку», с которой всё началось. Точнее, на результат распределения entry по бакетам (бинам) в lruhash->array c родной хэш функцией Unbound.
gdb /usr/sbin/unbound
core-file core_534009.gdb
source ./gdb_traverse.py
(gdb) frame function daemon_fork
#20 0x00000000021d5df3 in daemon_fork (daemon=daemon@entry=0x75b7f340000) at /-S/contrib/tools/unbound/daemon/daemon.c:789
789 /-S/contrib/tools/unbound/daemon/daemon.c: No such file or directory.
(gdb) walklist daemon->env->msg_cache
Args Passed: daemon->env->msg_cache
slab_size=32
slab-0 100% max bin(23557).length 7, count 459932 nodes
...
slab-0 max bin(23557).length 7 count 459932
slab-1 max bin(126260).length 8 count 460129
...
slab-31 max bin(149805).length 8 count 460061
Found total-max bin.length 9, total=14721205 nodesКак и ожидалось, для msg_cache распределение очень хорошее. И тут всё стало ясно: есть какая-то бага, которая приводит к тому, что linked-list в бинах rrcset_cache непонятным образом заполняются до больших размеров. На этот раз исследования заводят нас в очень сложный код iterator/iterator.c и services/mesh.c, поэтому поиски места возникновения баги потребовали некоторого времени.
К текущему времени я выяснил, что в бине c аномалией при тесте запросами udp-random у всех записей один и тот же хэш. При этом dname и метаинформация, на основе которой рассчитывается этот хэш, везде разные.
Исследования исследованиями, нам нужно защититься от этой опасной баги. Начинаем экспериментировать над настройками и нагружать Unbound, используя udp-random.
rrset-cache-size: 8G # Значение с продакшен сервера
rrset-cache-slabs: 1024 # Начнём с предыдущей рекомендации. При такой настройке
# не должно быть больше 20к записей на один BIN в худшем случаеЗалп 1Krps -> 2Krps и буквально сразу Unbound всеми тредами висит на жгучем pthread_spin_lock, графики в netdata пропадают, и все запросы таймаутятся. Ждём и аттачим gdb.
gdb /usr/sbin/unbound -ex "attach $(pidof unbound)"
...
(gdb) info threads
...
102 Thread 0x7f6eb6b76700 (LWP 437165) 0x00007f6f03aebd15 in pthread_spin_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
103 Thread 0x7f6eb6375700 (LWP 437166) 0x00007f6f03aebd15 in pthread_spin_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
* 104 Thread 0x7f6eb5b74700 (LWP 437167) 0x0000000002fd6830 in query_dname_compare (d1=0x4481e3ef1171 "npkbVZViNbVBWAUr\005alpha\002tt\006yandex\003net", d2=0x4483f5420eb1 "vGRcmudYeYHJMVSA\005alpha\002tt\006yandex\003net") at /-S/contrib/tools/unbound/util/data/dname.c:101
105 Thread 0x7f6eb5373700 (LWP 437168) 0x00007f6f03aebd15 in pthread_spin_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
106 Thread 0x7f6eb4b72700 (LWP 437169) 0x00007f6f03aebd12 in pthread_spin_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
...Зайдём в 104 тред и посчитаем длину бина вот таким скриптом, который очень похож на предыдущий gdb_traverse.py.
import gdb
class ListCounter(gdb.Command):
"""Prints the ListNode from our example in a nice format!"""
def __init__(self):
super(ListCounter, self).__init__("listcount", 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: %r" % 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
ref, next_elem_field_name = args.split()
next_elem = gdb.parse_and_eval(ref)
count = 0
while next_elem != 0:
count += 1
next_elem = next_elem[next_elem_field_name]
print(count)
ListCounter()Подтверждаем ещё раз предположение, что дело в больших linked-list у бинов.
(gdb) bt
#0 0x0000000002fd6830 in query_dname_compare (d1=0x4481e3ef1171 "npkbVZViNbVBWAUr\005alpha\002tt\006yandex\003net", d2=0x4483f5420eb1 "vGRcmudYeYHJMVSA\005alpha\002tt\006yandex\003net") at /-S/contrib/tools/unbound/util/data/dname.c:101
#1 0x0000000002fdfa48 in ub_rrset_compare (k1=0x4481cb32cf70, k2=0x4482ffee5830) at /-S/contrib/tools/unbound/util/data/packed_rrset.c:112
#2 0x0000000002fef50d in bin_find_entry (table=0x447f7fb66f00, bin=<optimized out>, hash=3008119653, key=0x4482ffee5830) at /-S/contrib/tools/unbound/util/storage/lruhash.c:223
#3 lruhash_insert (table=0x447f7fb66f00, hash=hash@entry=3008119653, entry=entry@entry=0x4482ffee5830, data=0x4481be1bc590, cb_arg=cb_arg@entry=0x447f486a2888) at /-S/contrib/tools/unbound/util/storage/lruhash.c:320
#4 0x0000000002ff0d8e in slabhash_insert (sl=sl@entry=0x447f7f1a68c0, hash=4114747056, hash@entry=3008119653, entry=0x4483f5420ec1, entry@entry=0x4482ffee5830, data=0x4481be1bc590, arg=arg@entry=0x447f486a2888) at /-S/contrib/tools/unbound/util/storage/slabhash.c:119
#5 0x0000000002f84685 in rrset_cache_update (r=0x447f7f1a68c0, ref=ref@entry=0x7f6eb5b71d60, alloc=0x447f486a2888, timenow=1671175065) at /-S/contrib/tools/unbound/services/cache/rrset.c:227
(gdb) up 3
#3 lruhash_insert (table=0x447f7fb66f00, hash=hash@entry=3008119653, entry=entry@entry=0x4482ffee5830, data=0x4481be1bc590, cb_arg=cb_arg@entry=0x447f486a2888) at /-S/contrib/tools/unbound/util/storage/lruhash.c:320
320 /-S/contrib/tools/unbound/util/storage/lruhash.c: No such file or directory.Команда list, к сожалению, тут не работает, поэтому обратимся к коду.
23 void
22 lruhash_insert(struct lruhash* table, hashvalue_type hash,
21 ┊ ┊ ┊ ┊ struct lruhash_entry* entry, void* data, void* cb_arg)
20 {
...
6 ┊ bin = &table->array[hash & table->size_mask]; // <<<<< Интересен этот объект
5 ┊ lock_quick_lock(&bin->lock);
4 ┊
3 ┊ /* see if entry exists already */
2 ┊ if(!(found=bin_find_entry(table, bin, hash, entry->key))) { <- (key: )
1 ┊ ┊ /* if not: add to bin */
322 ┊ ┊ entry->overflow_next = bin->overflow_list;
1 ┊ ┊ bin->overflow_list = entry;
...
31 }Дальше понятно, что нужно смотреть в бин.
(gdb) p bin
$13 = <optimized out> # <<<< бывает...
(gdb) p &table->array[hash & table->size_mask] # можно и вот так подсмотреть
$14 = (struct lruhash_bin *) 0x4484b4ec3650
(gdb) p *$14
$15 = {lock = 0, overflow_list = 0x4482ffef7b00}
(gdb) listcount $14->overflow_list overflow_next
Args Passed: u'$14->overflow_list overflow_next'
29413 # весь слаб в одном бине!Я хотел измерить, сколько на таких функциях работает bin_find_entry, но столкнулся с тем, что, судя по всему, компилятор заинлайнил bin_find_entry (вставил тело этой функции в другие функции), потому что bpftrace её не ловит. Замерять время работы lruhash_insert уже неинтересно, потому что в ней находятся локи. Остаётся только самописный strcmp, который называется query_dname_compare (который вызывается внутри bin_find_entry до 29413). Будем брать худший вариант для расчётов.
ns-load.name:~$ sudo bpftrace -e 'uprobe:/usr/sbin/unbound:query_dname_compare { @start[tid] = nsecs; } uretprobe:/usr/sbin/unbound:query_dname_compare /@start[tid]/ { @ns[pid] = hist((nsecs - @start[tid]) / 1e3); delete(@start[tid]); }'
Attaching 2 probes...
^C
@ns[4001695]:
[1] 9762689 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[2, 4) 147486 | |
[4, 8) 15356 | |
[8, 16) 2325 | |
[16, 32) 163 | |
[32, 64) 12 | |
[64, 128) 6 | |
[128, 256) 1 | |
`- микросекунды.
@start[4003804]: 2159892851713379В итоге, если бы мне удалось измерить bin_find_entry, можно было бы увидеть что-то похожее:
29413(ENTRY per BIN) * 4us(per query_dname_compare) = 118 msЭто не идёт ни в какое сравнение с рекомендованным временем операции под spinlock: 1—2us (которое примерно равно переключению контекстов в ядре).
Пока тред жжёт CPU на spinlock, шедулер ядра Linux может просто вытеснить тред, который занимается bin_find_entry. И тут происходит маленький коллапс...
Для тех, кто любит хардкор, под катом есть способ замерить bin_find_entry
Позже я понял, как правильно замерять время работы bin_find_entryиз reference_guide.md bpftrace. Кусок заинлайненного кода можно измерять по смещению в бинарнике — главное, чтобы смещения, которые вы нашли в бинарнике, и бинарник, который вы замеряете на проде/лоаде, были одними и теми же.
Приведу пример, как можно найти нужные смещения.
gdb unbound
(gdb) disassemble /s lruhash_insert
# Сокращённый вывод disassemble /s lruhash_insert
Dump of assembler code for function lruhash_insert:
/-S/contrib/tools/unbound/util/storage/lruhash.c:
302 {
0x0000000003123f4b <+443>: mov 0x10(%rsp),%rcx
...
317 lock_quick_lock(&bin->lock);
0x0000000003123e63 <+211>: shl $0x4,%rbp
0x0000000003123e67 <+215>: lea (%r15,%rbp,1),%rdi
0x0000000003123e6b <+219>: mov %rdi,0x18(%rsp)
0x0000000003123e70 <+224>: callq 0x41e53c0 <pthread_spin_lock@plt>
0x0000000003123e75 <+229>: test %eax,%eax
0x0000000003123e77 <+231>: je 0x3123e99 <lruhash_insert+265>
0x0000000003123e79 <+233>: mov %eax,%edi
...
221 struct lruhash_entry* p = bin->overflow_list;
0x0000000003123e99 <+265>: lea (%r15,%rbp,1),%rax
0x0000000003123e9d <+269>: add $0x8,%rax
0x0000000003123ea1 <+273>: mov %rax,0x10(%rsp)
0x0000000003123ea6 <+278>: mov 0x8(%r15,%rbp,1),%r12
222 while(p) {
0x0000000003123eab <+283>: test %r12,%r12
0x0000000003123eae <+286>: je 0x3123f5a <lruhash_insert+458>
...
330 (*table->sizefunc)(found->key, found->data);
0x0000000003123ef1 <+353>: mov 0x58(%r12),%rdi
0x0000000003123ef6 <+358>: mov 0x60(%r12),%rsi
0x0000000003123efb <+363>: callq *0x8(%r13)
0x0000000003123eff <+367>: mov 0x20(%rsp),%rcx
329 table->space_used += need_size -
0x0000000003123f04 <+372>: sub %rax,%rcx
0x0000000003123f07 <+375>: add %rcx,0x68(%r13)
0x0000000003123f0b <+379>: mov 0x8(%rsp),%rax
...
# Нет, тут я не перепутал листинг, это компилятор перевернул условие
# и посчитал, что по execution path правильнее вставить первым else, а затем уже if
318
319 /* see if entry exists already */
320 if(!(found=bin_find_entry(table, bin, hash, entry->key))) {
321 /* if not: add to bin */
322 entry->overflow_next = bin->overflow_list;
0x0000000003123f50 <+448>: mov (%rcx),%rax
0x0000000003123f53 <+451>: mov 0x8(%rsp),%rsi
0x0000000003123f58 <+456>: jmp 0x3123f6b <lruhash_insert+475>
0x0000000003123f5a <+458>: xor %eax,%eax
0x0000000003123f5c <+460>: mov 0x18(%rsp),%rbp
0x0000000003123f61 <+465>: mov 0x8(%rsp),%rsi
0x0000000003123f66 <+470>: mov 0x10(%rsp),%rcx
0x0000000003123f6b <+475>: mov %rax,0x38(%rsi)
323 bin->overflow_list = entry;
0x0000000003123f6f <+479>: mov %rsi,(%rcx)
...
347 struct lruhash_entry* n = reclaimlist->overflow_next;
0x0000000003124040 <+688>: mov 0x38(%rax),%rbx
349 (*table->delkeyfunc)(reclaimlist->key, cb_arg);
0x0000000003124044 <+692>: mov 0x58(%rax),%rdiИнтересно, что же происходит внутри bin_find_entry и lruhash_insert. Здесь я решил замерить только для вставки: это будет нормальным показателем, даже несмотря на то, что lruhash_lookup намного горячее.
Листинг bin_find_entry:
(gdb) list bin_find_entry
217 struct lruhash_entry*
218 bin_find_entry(struct lruhash* table,
219 struct lruhash_bin* bin, hashvalue_type hash, void* key)
220 {
221 struct lruhash_entry* p = bin->overflow_list;
222 while(p) {
223 if(p->hash == hash && table->compfunc(p->key, key) == 0)
224 return p;
225 p = p->overflow_next;
226 }
227 return NULL;Листинг lruhash_insert:
(gdb) list lruhash_insert
297 }
298
299 void
300 lruhash_insert(struct lruhash* table, hashvalue_type hash,
301 struct lruhash_entry* entry, void* data, void* cb_arg)
302 {
303 struct lruhash_bin* bin;
304 struct lruhash_entry* found, *reclaimlist=NULL;
305 size_t need_size;
306 fptr_ok(fptr_whitelist_hash_sizefunc(table->sizefunc));
307 fptr_ok(fptr_whitelist_hash_delkeyfunc(table->delkeyfunc));
308 fptr_ok(fptr_whitelist_hash_deldatafunc(table->deldatafunc));
309 fptr_ok(fptr_whitelist_hash_compfunc(table->compfunc));
310 fptr_ok(fptr_whitelist_hash_markdelfunc(table->markdelfunc));
311 need_size = table->sizefunc(entry->key, data);
312 if(cb_arg == NULL) cb_arg = table->cb_arg;
313
314 /* find bin */
315 lock_quick_lock(&table->lock);
316 bin = &table->array[hash & table->size_mask];
317 lock_quick_lock(&bin->lock);
318
319 /* see if entry exists already */
320 if(!(found=bin_find_entry(table, bin, hash, entry->key))) {
321 /* if not: add to bin */
322 entry->overflow_next = bin->overflow_list;
323 bin->overflow_list = entry;
324 lru_front(table, entry);
325 table->num++;
326 table->space_used += need_size;
327 } else {
328 /* if so: update data - needs a writelock */
329 table->space_used += need_size -
330 (*table->sizefunc)(found->key, found->data);
331 (*table->delkeyfunc)(entry->key, cb_arg);
332 lru_touch(table, found);
333 lock_rw_wrlock(&found->lock);
334 (*table->deldatafunc)(found->data, cb_arg);
335 found->data = data;
336 lock_rw_unlock(&found->lock);
337 }
338 lock_quick_unlock(&bin->lock);
339 if(table->space_used > table->space_max)
340 reclaim_space(table, &reclaimlist);
341 if(table->num >= table->size)
342 table_grow(table);
343 lock_quick_unlock(&table->lock);
344
345 /* finish reclaim if any (outside of critical region) */
346 while(reclaimlist) {
347 struct lruhash_entry* n = reclaimlist->overflow_next;
348 void* d = reclaimlist->data;
349 (*table->delkeyfunc)(reclaimlist->key, cb_arg);
350 (*table->deldatafunc)(d, cb_arg);
351 reclaimlist = n;
352 }
353 }Нам нужны смещения примерно с 221 строки, когда поток исполнения зашёл в bin_find_entry. И ещё либо 322, либо 328 и 329 строки, когда он оттуда вышел.
221 struct lruhash_entry* p = bin->overflow_list;
0x0000000003123e99 <+265>: lea (%r15,%rbp,1),%rax
322 entry->overflow_next = bin->overflow_list;
0x0000000003123f50 <+448>: mov (%rcx),%rax
329 table->space_used += need_size -
0x0000000003123f04 <+372>: sub %rax,%rcxБерём эти смещения и создаём несложный bpftrace-скрипт. Для примера я брал смещения на тестовом бинарнике, потому что в продакшен окружении нет таких удобных листингов. Запустим тест и проверим инструмент.
# для бинарника /usr/sbin/unbound-1.17.0-release-threaded-zone-write на ns-load
# https://github.com/NLnetLabs/unbound/blob/6f7da59b7744c345be580db2bd9b37380cab5a42
# 0x00000000030ab735 - util/storage/lruhash.c#L221
# 0x00000000030ab7db - util/storage/lruhash.c#L330
# 0x00000000030ab796 - util/storage/lruhash.c#L322
ns-load.name:~$ sudo bpftrace -e '
uprobe:/usr/sbin/unbound:0x00000000030ab735 { @start[tid] = nsecs; }
uprobe:/usr/sbin/unbound:0x00000000030ab7db /@start[tid]/ { @ns[pid] = hist((nsecs - @start[tid]) ); delete(@start[tid]); }
uprobe:/usr/sbin/unbound:0x00000000030ab796 /@start[tid]/ { @ns[pid] = hist((nsecs - @start[tid])); delete(@start[tid]); }'
Attaching 3 probes...
^C
@ns[1494524]:
[1K, 2K) 878 | |
[2K, 4K) 3670780 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ |
[4K, 8K) 809724 |@@@@@@ |
[8K, 16K) 6450716 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[16K, 32K) 527853 |@@@@ |
[32K, 64K) 39081 | |
[64K, 128K) 1852 | |
[128K, 256K) 100 | |
[256K, 512K) 7 | |И это для затюненного rrset-cache-size: 8G / rrset-cache-slabs: 131072 — то есть всего теста! И rrset тут вырос всего вот настолько:
ns-load.name:~$ sudo gdb /usr/sbin/unbound -ex "attach $(pidof unbound)"
...
(gdb) up 17
#7 0x0000000002274f00 in daemon_fork (daemon=daemon@entry=0x1745bf340000)
at /-S/contrib/tools/unbound/daemon/daemon.c:789
789 /-S/contrib/tools/unbound/daemon/daemon.c: No such file or directory.
(gdb) source /home/skacheev/gdb_traverse.py
(gdb) walklist &daemon->env->rrset_cache.table silent
Args Passed: &daemon->env->rrset_cache.table silent
slab_size=131072
Found total-max bin.length 210, total=326 nodesА это картинка для rrset-cache-slabs: 32. По понятным причинам здесь не весь тест — я не смог дождаться отлипания Unbound, он просто ел, ел и ел 100% CPU.
ns-load.name:~$ sudo bpftrace -e '
uprobe:/usr/sbin/unbound:0x00000000030ab735 { @start[tid] = nsecs; }
uprobe:/usr/sbin/unbound:0x00000000030ab7db /@start[tid]/ { @ns[pid] = hist((nsecs - @start[tid]) ); delete(@start[tid]); }
uprobe:/usr/sbin/unbound:0x00000000030ab796 /@start[tid]/ { @ns[pid] = hist((nsecs - @start[tid])); delete(@start[tid]); }'
Attaching 3 probes...
^C
@ns[1341345]:
[2K, 4K) 2476 |@@@@ |
[4K, 8K) 3057 |@@@@@ |
[8K, 16K) 251 | |
[16K, 32K) 576 |@ |
[32K, 64K) 911 |@ |
[64K, 128K) 2030 |@@@ |
[128K, 256K) 4050 |@@@@@@@ |
[256K, 512K) 5657 |@@@@@@@@@@ |
[512K, 1M) 13731 |@@@@@@@@@@@@@@@@@@@@@@@@@@ |
[1M, 2M) 26856 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ |
[2M, 4M) 21600 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ |
[4M, 8M) 596 |@ |
[8M, 16M) 245 | |
# K - микросекунды M - миллисекундыИ если остановить тест и чуть-чуть подождать момента, когда Unbound начнёт выходить из 100% CPU-ступора, а linked-list вырастет достаточно сильно, то можно ужаснуться! Топ времён вставки в lruhash_bin постепенно ползёт вниз до 32 миллисекунд и это, конечно, не предел.
ns-load.name:~$ sudo bpftrace -e '
uprobe:/usr/sbin/unbound:0x00000000030ab735 { @start[tid] = nsecs; }
uprobe:/usr/sbin/unbound:0x00000000030ab7db /@start[tid]/ { @ns[pid] = hist((nsecs - @start[tid]) ); delete(@start[tid]); }
uprobe:/usr/sbin/unbound:0x00000000030ab796 /@start[tid]/ { @ns[pid] = hist((nsecs - @start[tid])); delete(@start[tid]); }'
Attaching 3 probes...
^C
@ns[1341345]:
[2K, 4K) 46 |@ |
[4K, 8K) 440 |@@@@@@@@@@@@@@@@ |
[8K, 16K) 12 | |
[16K, 32K) 1 | |
[32K, 64K) 0 | |
[64K, 128K) 0 | |
[128K, 256K) 0 | |
[256K, 512K) 0 | |
[512K, 1M) 0 | |
[1M, 2M) 0 | |
[2M, 4M) 0 | |
[4M, 8M) 412 |@@@@@@@@@@@@@@@ |
[8M, 16M) 1364 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[16M, 32M) 330 |@@@@@@@@@@@@ |rrset вырос до 135433 записей в lruhash_bin->linked-list.
(gdb) walklist &daemon->env->rrset_cache.table
...
slab-14 max bin(247101).length 135433 count 135436
...
Found total-max bin.length 135433, total=135529 nodesВ итоге я провёл несколько итераций нагрузочного тестирования и пришёл к такой конфигурации:
msg-cache-size: 4G
# Это количество не очень важно, но всё равно, если позволяет память на старте, то чем больше тем лучше.
msg-cache-slabs: 512
rrset-cache-size: 8G
# А это значение очень важно, так как тут есть проблема с пухнущими linked-list из ENTRY
rrset-cache-slabs: 262144
# При таких настройках грубо 100 записей на BINНа таких настройках Unbound уже доживает примерно до 50Krps — на время поиска бага этого должно хватить.
Хэппи-энд: исправление бага
Потом были несколько дней изучения кода и coredump. В процессе дебага, как водится, была попытка воспроизвести баг по ложному предположению. Этому поспособствовало осознание причин странного поведения lruhash и фикс с пересчётом хэша непосредственно перед вставкой в lruhash. Но этот фикс не был настоящим фиксом, а был заплаткой на баг, который случается где-то ранее.
И после всех неудачных попыток быстро найти баг, я начал запускать бинарник Unbound под gdb, выполнять в него по одному запросу, расставлять кучу брейкпоинтов в разных местах и периодически пошагово проходить некоторые участки кода.
Самой полезной фичей в этот момент оказались conditional breakpoints и определение пользовательских команд в gdb. Для примера покажу кусочек из своего .gdbinit.
cat ~/.gdbinit
source listprint.py
source gdb_traverse.py
# ...
define print_entry
p *(struct ub_packed_rrset_key*)entry->key
listprint entry->overflow_next overflow_next
end
define print_cache
p iq->state
set $num = 0
p *iq->response.rep
while $num < iq->response.rep.rrset_count
p *iq->response.rep.rrsets[$num]
set $num = $num + 1
end
p *iq->response.rep.ref[0].key
p *iq->response.rep.ref[1].key
end
define set_breaks
br processQueryTargets thread 1
commands
print_cache
end
# ... - тут ещё куча разных точек остановки
br lruhash_insert thread 1
commands
print_entrype
cont
end
endЕщё немного поисков и фикс в одну строку, который выглядит вот так:
diff --git a/services/authzone.c b/services/authzone.c
index 6de1e431..ab4cedaa 100644
--- a/services/authzone.c
+++ b/services/authzone.c
@@ -2756,6 +2756,8 @@ az_change_dnames(struct dns_msg* msg, uint8_t* oldname, uint8_t* newname,
== 0) {
msg->rep->rrsets[i]->rk.dname = newname;
msg->rep->rrsets[i]->rk.dname_len = newlen;
+ // We MUST update the entry.hash due to the rk.dname change
+ msg->rep->rrsets[i]->entry.hash = rrset_key_hash(&msg->rep->rrsets[i]->rk);
}
}
}Баг заключается в том, что при ответе на запрос CNAME со звёздочкой Unbound переиспользует данные запроса для сохранения ответа в кэш. Данные запроса копируются в ответ и в них заменяется dname, но при этом автор этого кода забыл обновить entry.hash. Далее, попутешествовав весьма заковыристыми участками кода, entry попадает в кэш с плохим значением entry.hash, что и приводит к переполнению bin->linked_list. В hyperlocal zone конфигурации кэш используется для ускорения ответа, чтобы не спускаться в структуры auth-zone.
Я отправил секьюрити-репорт в Unbound с исправлением бага и его описанием. Фикс попал в release-1.17.1.
Также мы не могли оставить это место без мониторинга. Следующим патчем мы отправили код, который добавляет метрику, показывающую максимальное количество коллизий при вставке нового значения в BIN->linked_list.
В итоге багфикс вернул производительность Unbound при нагрузке запросами udp-random на нормальные 600-700 Krps на инстанс.
Но на этом история поиска багов в Unbound не заканчивается. Спасибо всем кто дочитал этот детектив до конца!
