Привет! Меня зовут Денис, я — разработчик ПО SEDMAX. Это промышленное ПО для сбора и визуализации данных в энергетике. Как и у всех, у нас бывают баги. Мне бы хотелось поделиться опытом в поиске таких багов, а также порассуждать на тему того, что необходимо было сделать, чтобы баг не появился. У нас серверная часть написана на go в виде некоторого множества сервисов, поэтому специфика большинства багов будет асинхронное взаимодействие, а код примеров представлен на go.

В прошлой статье были сделаны следующие выводы:

Стоит разделять асинхронную логику от бизнес логики. Асинхронный код вызывает множество проблем при написании и анализе, поэтому стоит выделить паттерны, которые часто используются в разработке и написать библиотеку, которая протестирована со всех сторон и предоставляет удобное АПИ разработчику.
Рефлексия иногда драматически замедляет выполнение. Как правило на малых нагрузках это незаметно, но растёт экспоненциально на всё больших и больших данных. Лучше предпочесть дженерики для обобщённых алгоритмов слабо зависящих от типа или генерацию для логики, которая сильно завязана на свойствах самого передаваемого типа.
Не стоит использовать -1 код в значении перечисления, если это значение не является одним из вариантов значений этого перечисления.
Очень внимательно относится к запуску горутин внутри хендлеров, вызываемых другими программами, так как они могут вызывать его независимо друг от друга, одновременно и много.

В этой части я немного изменю формат статьи. Буду меньше писать про то, как баг проявился у пользователя, сразу переходить к самому багу.

Нет преаллокации — готовься к тормозам

Этот баг описан в прошлой статье и предлагался для читателей в качестве упражнения в поиске проблемы. К сожалению, никто в комментариях не попытался написать что не так. Следующий код очень сильно тормозил выполнение.

func mergeData(data map[int][]byte, count int) ([]byte, bool) {
	result := make([]byte, 0)
	for i := 0; i < count; i++ {
		part, ok := data[i]
		if !ok {
			return nil, false
		}
		result = append(result, part...)
	}
	return result, true
}

Можно заметить, что внутри цикла есть условие, по которому можно выйти из функции. При этом всё, что накопилось внутри слайса result отбрасывается. Но можно ещё до запуска цикла определить условие выхода из функции. Если размер мапки меньше count, то это условие выполнится 100%, а значит нет смысла собирать слайс. В нашем случае эта функция вызывалась около 100 раз и все, кроме последнего, собирали информацию зря. Причем при логировании было хорошо видно, что чем больше частей передаётся в функцию (они шли по нарастающей), тем дольше функция выполнялась.

Вторая оптимизация — сделать преаллокацию результирующего слайса. Ведь его размер известен заранее — сумма всех частей в мапке. Есть линтер prealloc, который может подсказать места, где можно сделать преаллокацию, но он работает только в простых случаях. В данном примере он не сработал. Пример оптимизации:

func mergeData(data map[int][]byte, count int) ([]byte, bool) {
	if len(data) != count {
		return nil, false
	}
	l := 0
	for _, v := range data {
		l += len(v)
	}
	result := make([]byte, 0, l)
	for i := 0; i < count; i++ {
		part, ok := data[i]
		if !ok {
			return nil, false
		}

		result = append(result, part...)
	}

	return result, true
}

Бенчмарк показал, что первая оптимизация по размеру мапки ощутимо ускорило с минуты до пары секунд. Вторая уже не так заметна.

Оптимизация с преаллокацией — частый случай, про которые разработчики могут забыть. К примеру, есть открытая библиотека open62 541, которая написана на си и у неё много звёзд на github. Мы используем её в качестве ядра нашего opcua сервера. В этой библиотеке есть хеш таблица, которая хранит некие ноды, по которым можно записать данные нашего сервера и запросить сторонними программами через opcua протокол. И всё было хорошо для малых конфигураций. Когда количество нод выросло до 1 миллиона вдруг выяснилось, что инициализация сервера происходит 14 часов. А всё дело в этом хранилище. В нём нету никакого метода заранее задать его размер, он захардкожен числом всего 64 и указан в виде макроса #define, а значит и изменить его можно только на этапе компиляции. Печально. Мы ещё не решили, что мы будем с этим делать, но проблема довольно серьёзная.

Иногда стоит изучать реализации сторонних библиотек при использовании

Логика резервирования в SEDMAX отчасти построена на обмене сообщениями между серверами через брокер NATS. У каждого сервера есть свой брокер и каждый сервер передаёт сообщения в брокер NATS соседнего сервера и слушает свой брокер NATS для координации действий. Для начала приведу кусочек кода, который определяет адреса этих брокеров.

func (r *Replicator) update(nodes []Node) {
	urls := struct{ own, reserve string }{}
	for _, n := range nodes {
		if n.GetAddr() == r.Addr {
			urls.own = n.GetNats()
		} else {
			urls.reserve = n.GetNats()
		}
	}
    ...
}

Далее эти адреса уже используются для подключения к NATS и отправке сообщений. Когда сервер получает сообщение от соседнего сервера он должен выполнить определённые действия. В прошлой статье уже было рассказано про сигнал «колокольчик». Вкратце это сигнал обновления внутренних кешей в сервисах. Если на одном сервере сработал сигнал колокольчика, то он отправляется на соседний. Там он должен повториться, но не отправиться обратно на первый сервер. Иначе будет зацикливание.

Бага в том, что зацикливание всё таки произошло, что нагрузило систему. Нет худа без добра, благодаря такому странному поведению мы нашли слабые места в сервисах, которые не позволяли ddos‑ить себя этим сигналом, и поправили их. Но вернёмся к багу: как же так вышло?

Если внимательно посмотреть на код выше, можно заметить, что заполнение строк в структуре urls не гарантировано. Вполне возможно, что один из них или даже оба окажутся пустыми строками. В это раз так и вышло: urls.reserve оказался пустой строкой. Далее эта строка используется для создания клиента NATS. В SEDMAX используется фреймворк go-micro. Эта библиотека, которая упрощает работу с сервисами на go. Оказалось, что при создании клиента он вполне может принять пустую строку. Мы ожидали, что пустая строка не валидна, и созданный клиент будет возвращать ошибку при отправке. Но это не так. Где-то в глубинах реализации этой библиотеки пустая строка заменяется на localhost. Это было совсем не очевидно, так как в документации нигде про такое поведение не написано. Оно реально запрятано глубоко внутри за интерфейсами и асинхронным кодом. Добраться до этого куска логики было сложновато.

Итого. Мы получили пустую строку в качестве URL резервного сервера. При отправке сообщений пустая строка заменилась на localhost, а значит отправка сообщений производилась самому себе, что и зациклило наш колокольчик. Не все изучают реализацию библиотек, которые используют. Да и накладно это. Разработчикам библиотеки стоит описать такое поведение в комментарии к апи этой библиотеки, так как это реально важная информация.

Синхронизация не до конца

Когда работаешь конкурентно с данными, их необходимо защищать примитивами синхронизации. В go даже есть встроенный race detector для структуры map, который запаникует, если во время работы вдруг произойдет одновременные чтение и запись в мапку. Поэтому все уже привыкли к тому, что, если обращение к мапке происходит в нескольких горутинах, то её нужно защитить мьютексом. Что и было сделано в используемой нами фреймворке go-micro. Например, чтобы запросить данные по grpc у сервиса, надо только знать его название и иметь клиента с необходимыми методами, которые генерируются через proto файлы. Для нас как пользователей этой библиотеки удалённый вызов выглядит, как вызов метода. Но внутри происходит много интересного.

Сначала необходимо найти запущенный сервис (нода) по названию. Для этого есть сущность, называемая registry. Там хранится список нод в мапке, где ключом является имя сервиса. Когда сервис запускается, он регистрируется, передавая свой ip и порт для обращения. Все сервисы получают эту информацию и сохраняют в registry. Когда сервис завершает работу, он дерегистрируется, все сервисы удаляют у себя в registry эту ноду. Далее, зная ip и порт конкретного запущенного сервиса происходит grpc запрос. Там всё несколько сложнее, но баг был именно в registry, поэтому я вкратце описал только его.

В registry мапка с нодами защищена мьютексом, так как обращение к ней происходит из множества горутин, где надо сделать удалённый вызов. В мапке лежит слайс нод сервисов, который мы и получаем. Если сервис дерегистрируется, то в другой горутине нода сервиса удаляется из слайса. Вот тут и случился баг, который довольно сложно заметить и проявляет себя он довольно редко. В go слайс это ссылочная структура. Она хранит в себе указатель на данные. Если данные по этому указателю меняются, то они меняются у всех слайсов с этим указателем. Последовательность бага следующая:

мы запрашиваем список нод
сначала блокируется мьютекс с мапкой
значение (слайс нод) возвращается нам для работы
мьютекс освобождается
мы работаем с полученным слайсом
параллельно с п.5 в другой горутине приходит сигнал дерегистрации, блокируется мьютекс с мапкой, удаляется нода из слайса по ключу, освобождается мьютекс

Получается, что в п.5 и п.6 происходит работа с одной и той же памятью в разных горутинах, что и привело к неожиданным последствиям. Сервис просто зависал, так как обращался к уже удалённой ноде.

К чести разработчиков в более поздних версиях библиотеки этот баг уже поправлен. Необходимо в пункте 4 перед освобождением мьютекса скопировать слайс, чтобы не было обращений к одному участку памяти из разных горутин.

Чтобы словить такие баги на этапе тестирования, надо запускать тесты с флагом -race. Тогда во время тестирования работает race detector на подобии того, что есть в мапке, но для всей памяти. Поскольку это сторонняя библиотека, в SEDMAX этот код не был покрыт подобными тестами.

Выводы

Лучше не делать лишних аллокаций или реаллокаций. На малых объёмах это незаметно, но при большой нагрузке выходит боком.
При использовании сторонних библиотек лучше убедится, что они работают как ожидается при всех вариантах аргументов.
Запускать тесты с флагом -race, чтобы находить ошибки синхронизации.

Следующая статья будет про то, как мы правили баги, возникшие из-за большой нагрузки на базу временных рядов influxdb. Про то, как эта база себя ведёт при увеличении нагрузки, написано не так много. Нам пришлось собрать все грабли самим.

Баги, которые мы пишем, ищем и исправляем #2