Привет, меня зовут Сергей Качеев, я старший разработчик в отделе сетевой инфраструктуры Яндекса. Сегодня я расскажу целый сетевой детектив о том, как мы искали баг, который убивал 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>: mov0x10(%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>: mov0x8(%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>: mov0x58(%r12),%rdi 0x0000000003123ef6 <+358>: mov0x60(%r12),%rsi 0x0000000003123efb <+363>: callq *0x8(%r13) 0x0000000003123eff <+367>: mov0x20(%rsp),%rcx 329 table->space_used += need_size - 0x0000000003123f04 <+372>: sub%rax,%rcx 0x0000000003123f07 <+375>: add%rcx,0x68(%r13) 0x0000000003123f0b <+379>: mov0x8(%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>: mov0x8(%rsp),%rsi 0x0000000003123f58 <+456>: jmp0x3123f6b <lruhash_insert+475> 0x0000000003123f5a <+458>: xor%eax,%eax 0x0000000003123f5c <+460>: mov0x18(%rsp),%rbp 0x0000000003123f61 <+465>: mov0x8(%rsp),%rsi 0x0000000003123f66 <+470>: mov0x10(%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>: mov0x38(%rax),%rbx 349 (*table->delkeyfunc)(reclaimlist->key, cb_arg); 0x0000000003124044 <+692>: mov0x58(%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 не заканчивается. Спасибо всем кто дочитал этот детектив до конца!
ссылка на оригинал статьи https://habr.com/ru/articles/729764/
Добавить комментарий