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

в 8:06, , рубрики: bpftrace, bug, DNS, gdb, load testing, Unbound, баги, Блог компании Яндекс, высокая производительность, нагрузочное тестирование, Серверное администрирование
Захватывающая ловля багов, которые портили работу Unbound - 1

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

ns-load.name:~$ sudo bpftrace -e 'tracepoint:syscalls:sys_enter_openat
                   //              |,---------------^
                   //  какое событие в системе мы собираемся мониторить.
                   //  Про это можно почитать в документации man bpftrace, 
 //  и там же про kprobe и uprobe.
//  // - это комментарий в коде bpftrace-скрипта.
//  ,- filter, ловить события только от Unbound,
//  |  запущенного в этом lxc-контейнере,
//  |  а если точнее — только в cgroup, 
//  |  созданной этим systemd-сервисом.
/cgroup == cgroupid("/sys/fs/cgroup/unified/system.slice/unbound.service")/
// Однострочник, срабатывающий на каждое системное событие — в данном случае tracepoint
{ printf("%s %s %sn", 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

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

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

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

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

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

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

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

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

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

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

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

Обратите внимание на процент времени CPU, который занимают подсвеченные функции (правый нижний угол Matched)
А вот flamegraph под нагрузкой с малым значением msg-cache-slabs. Всего  4Krps, но в gdb и perf уже видно контеншен на лок

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

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

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

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

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

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

Захватывающая ловля багов, которые портили работу Unbound - 10
Захватывающая ловля багов, которые портили работу Unbound - 11
Захватывающая ловля багов, которые портили работу Unbound - 12
Захватывающая ловля багов, которые портили работу Unbound - 13
Захватывающая ловля багов, которые портили работу Unbound - 14

Суровая реальность: сколько 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 = 1048576

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

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

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

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

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

Я написал рекомендацию в тикет, и был готов на следующей неделе проверить предположение о кривизне хэш-функции, заменив её. И тут случилась та самая суровая реальность: приходит коллега и говорит, что хоть наша канарейка и стала себя чувствовать лучше по 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 "npkbVZViNbVBWAUr05alpha02tt06yandex03net", d2=0x4483f5420eb1 "vGRcmudYeYHJMVSA05alpha02tt06yandex03net") 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 "npkbVZViNbVBWAUr05alpha02tt06yandex03net", d2=0x4483f5420eb1 "vGRcmudYeYHJMVSA05alpha02tt06yandex03net") 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 — на время поиска бага этого должно хватить.

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

Хэппи-энд: исправление бага

Потом были несколько дней изучения кода и 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://ajax.googleapis.com/ajax/libs/jquery/3.4.1/jquery.min.js