Баги, которые мы пишем, ищем и исправляем
Привет! Меня зовут Денис, я — разработчик ПО SEDMAX. Это промышленное ПО для сбора и визуализации данных в энергетике. Как и у всех, у нас бывают баги. Мне бы хотелось поделиться опытом в поиске таких багов, а так же порассуждать на тему того, что необходимо было сделать, чтобы баг не появился. У нас серверная часть написана на go в виде некоторого множества сервисов, поэтому специфика большинства багов будет асинхронное взаимодействие, а код примеров представлен на go.
Мне очень нравится искать и исправлять баги. Я убеждён, что на ошибках учатся, а баги позволяют учиться не только на своих. Каждый баг убеждает меня в том, что архитектурные советы, паттерны разработки и всевозможные правила взяты не с потолка. И когда ты им не следуешь, вполне возможно, ты за это заплатишь в будущем. Примеры багов — подтверждение, как технический долг, образовавшийся от игнорирования правил, может выстрелить. Я бы и сам с удовольствием почитал о том, какие баги были в других продуктах и почему они возникли, но об этом пишут редко. Думаю, есть люди, которым будет интересно почитать про наши ошибки в разработке. Я специально не отсеивал даже самые простые баги, прочитав про которые, можно подумать: ну это же очевидно. Возможно не очень опытному разработчику это не так уж и очевидно, да и допустили эти ошибки далеко не новички.
Когда сигнал нужен многим
В нашем ПО есть так называемое «телеуправление», когда оператор с рабочего места меняет состояние выключателя (это коммутационный аппарат, который размыкает электрическую цепь или отключает оборудование от питания). Команда на основе конфигурации телеуправления должна дойти до определённого сервиса, а сервис уже отправляет команду на прибор, используя протокол этого прибора (modbus, iec104 и т.п). Каждый сервис отвечает за один конкретный протокол. Баг состоял в том, что команда телеуправления не выполнялась, причем только по одному протоколу (modbus), что сильно сузило круг поиска до одного сервиса.
SEDMAX работает с различными приборами и устройствами (собирает с них данные). Взаимодействие с прибором тестировать автоматически не просто: мок реального прибора всё равно не передаёт реального его поведения, поэтому мы всё тестируем только с реальными приборами. Именно поэтому автотесты работы SEDMAX с приборами не проводились. Ну, а раз не было автотестов, и нельзя пройтись по ним в режиме отладки, пришлось добавлять логи в сервис и анализировать их. Логи показали, что сигнал в сервис приходит, но почему-то не доходит до сущности, которая непосредственно посылает сигнал на устройство.
Требуется небольшое пояснение логики сервиса с псевдокодом, чтобы было понятно в чём ошибка. Например, название того типа, что отправляет сигнал на устройство — Entity, экземпляров этих структур много, так как и устройств много. Их созданием, обновлением и удалением занимается Manager на основе некой конфигурации, которая приходит в Manager через канал configuration. Внешний сигнал телеуправления приходит через канал signal, который должен обрабатываться каждым экземпляром Entity. Далее приведён код с багом.
type Manager struct{
entities map[id]Entity
configuration chan C
signal chan S
}
func (m Manager) run() {
for {
select {
case c := <-m.configuration
...
entity := NewEntity(m.signal)
m.entities[entity.ID] = entity
...
case ...
}
}
}
func (e Entity) run() {
for {
select {
case v := <-m.signal
e.doSomething(v)
case ...
}
}
}
В go многие вещи происходят по воле случая, например: проход по мапке в случайном порядке; выбор того, какой из case select-а отработает; в каком порядке будут работать горутины и т.п. Данный баг как раз про последний случай. Ошибка в том, что канал с сигналом передаётся каждому Entity через конструктор, и каждый Entity внутри своей функции run слушает этот канал. Одно сообщение из канала может прочитать лишь один Entity в случайном порядке. Исправляется это довольно просто. Не надо передавать канал с сигналом в конструктор Entity. Слушать сигнал должен только Mаnager и пересылать информацию о нём всем эксземплярам Entity.
type Manager struct{
entities map[id]Entity
configuration chan C
signal chan S
}
func (m Manager) run() {
for {
select {
case c := <-m.configuration
...
entity := NewEntity()
m.entities[entity.ID] = entity
...
case t := <- m.signal:
for _, e := range m.entities {
e.SendSignal(t)
}
}
}
}
В идеальном мире такие ошибки должны пресекаться автотестами, но я уже выше писал, что с приборами это реализовать затруднительно. Не значит, что невозможно, можно написать мок прибора, но это довольно дорого. Было бы неплохо отделять асинхронную логику от бизнес логики и тогда можно это протестировать, но самое смешное, что баг был именно в этой части. Правда она так же не была покрыта автотестами, так как эта часть общая для множества сервисов и протестирована этими сервисами досконально. Беда в том, что логика обработки сигнала телеуправления недавно поменялась, и обновилась эта логика пока только в одном сервисе, в котором и проявился баг. Этап ручного тестирования не обнаружил проблем, потому что проверялась только функциональность. Был создан лишь один экземпляр Entity, и до него сигнал доходил всегда. Случайный выбор из одного варианта всегда и есть этот вариант. Если бы в тесте был создан и второй экземпляр Entity, то тест иногда бы проваливался, что позволило бы не допустить такой баг.
Очень медленная рефлексия
В SEDMAX есть мнемосхемы — визуализация технологического процесса (в энергетике или в производстве), которая отображает в режиме реального времени сам процесс, взаимосвязь элементов и позволяет управлять этими элементами. Они очень гибкие и пользователь системы может нарисовать то, что ему нужно. Эта графическая информация сохраняется в формате svg, и эти файлы бывают довольно большими. Даже если сами файлы не очень большие, но их может быть много. Баг проявился в том, что появление мнемосхемы в просмотрщике после загрузки архива со всеми мнемосхемами происходило спустя 3 минуты. Общий объём структур с мнемосхемами оказался 900Мб — именно столько отправлялось из одного сервиса в другой по grpc. Для выяснения причины опять пришлось добавлять логирование с профилированием логики отправки. Выяснилось, что 2 из 3 минут занимает расчёт хеша структуры.
Небольшое отступление для чего хеш считается. Часто необходимо сравнить структуры. Причем было бы неплохо сделать это так, чтобы добавление нового поля в структуру автоматически попадало в сравнение. Для этого удобно высчитать хеш экземпляра структуры и положить результат прямо в поле самой структуры. Тогда при сравнении можно просто сравнивать эти поля с хешем. Для этой задачи существуют библиотеки, основанные на рефлексии, которые проходят по каждому полю структуры и считают его хеш, добавляя его к хеш сумме.
Казалось ответ найден: надо избавиться от рефлексии, раз она так долго работает. При этом хотелось бы оставить обратную совместимость, чтобы хеш, рассчитанный без рефлексии, совпадал с уже имеющимся хешем. Был написан генератор, который создаёт метод расчёта хеша для структуры, использует тот же алгоритм хеширования, но значения полей берёт просто вызовом нужных полей, вместо reflect.ValueOf и т.п. К сожалению, этот способ не возымел успеха. Бенчмарк показал, что время расчёта хеша сгенерированным методом расчёта уменьшилось незначительно относительно исходного, всего процентов на 10. Вышло так из-за желания оставить обратную совместимость. В этих структурах были сохранены svg файлы в виде слайса байт. Алгоритм, основанный на рефлексии, считал хеш по каждому байту, а это uint64, потом оно добавлялось к уже накопленному хешу. И вот этот процесс оказался очень долгий, а он сохранился и в генераторе. Чуда не случилось (
Было решено отказаться от обратной совместимости и изменить алгоритм расчёта хеша. Изменения коснулись только замены большого слайса байт на их MD5. Рефлексия по ним работала значительно быстрее. С 2-х минут расчёт хеша сократился до 3-х секунд.
Данный баг никак не проявлялся, так как не было такого большого объёма информации, такого бизнес кейса не было, а значит это и не баг вовсе. Ранее все реальные структуры были значительно меньшего размера и это замедление было совсем незначительным. Поэтому и заранее предотвратить это было нельзя. Как только возник данный прецедент, была произведена оптимизация. Единственная рекомендация: с подозрением относиться к библиотекам, которые используют рефлексию. Они могут быть медленнее не только из-за собственно вызовов пакета рефлексии, но и из-за того, что рефлексия накладывает определённые ограничения. В данном случае сыграло то, что нельзя получить значение всего слайса байт, а пришлось эти значения получать по одному.
Но это было только 2 минуты для отправки из 3. Про ещё одну оптимизацию я напишу, но саму оптимизацию попытайтесь найти сами, а в следующей статье о ней будет подробнее.
Для самостоятельной оптимизации
Отправка большого объёма данных у нас выполнено средствами grpc стриминга, большая структура превращается в массив байт и этот массив разбивается на пакеты и отправляется частями. Принимающая сторона собирает эти пакеты в единый слайс байт и, когда все пакеты собраны, получает из него нужные структуры.
Данная логика разбиения на пакеты и сбор пакетов инкапсулирована в отдельную библиотеку, и разработчик не задумываясь отправляет структуру целиком через эту библиотеку, а принимающая сторона просто получает эту структуру.
Немного про то, что с дженериками стало немного лучше. Библиотеке нет необходимости знать какая именно структура разбивается/собирается. Есть 3 пути оформления кода в go на данный момент. До дженериков было 2 и они, по моему мнению, не так хороши. Первый вариант — использование интерфейсов, но интерфейс не сама структура, поэтому клиенту приходится приводить к структуре, то есть страдает строгая типизация. Второй путь — генерация. Для каждой структуры генерируются файлы с реализацией этой логики, и тогда клиенту ничего приводить не надо. Он сразу получает нужную структуру. Генерация тоже имеет недостатки: можно забыть вызвать команду генерации, и тогда сгенерированные файлы не соответствуют импортированному пакету генератора. Даже был баг с этим связанный. В сгенерированном коде была ошибка, её поправили в генераторе, а вот перегенерировать забыли. Хотя это тоже решается этапом генерации в ci. У нас такого этапа нет. Ну, а дженерики позволяют добиться получения структуры клиентом без какой-либо генерации.
Я оставлю тут без изменений функцию из-за которой приём данных происходил слишком долго. Около 900Мб, разделённые приблизительно на 100 пакетов, принимались за время около минуты. Пакеты хранятся в мапке по индексу. Вторым аргументом передаётся количество пакетов. Функция возвращает собранный из пакетов слайс или false, если ещё не все пакеты пришли.
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
}
Думаю, тут можно догадаться, почему так долго.
Коварный »-1»
Следующий баг сложно показать кодом, так как задействовано много логики. Но есть желание им поделиться, чтобы показать, как иногда неожиданно может стрельнуть, если одна переменная используется для двух разных бизнес логик. Поэтому тут будет сразу описание того, что не так, а не то, как баг проявлялся.
SEDMAX работает с данными в реальном времени, которые он получает от множества приборов. Такие данные мы называем тегами. Есть сервис, который добавляет к ним некую информацию: качество, статус и т.п. Для понимания бага важно знать, что эта информация является неким числом из перечисления. Например статус равный 0, означает, что тег отключен в конфигурации, 4 — что по тегу выполнен ручной ввод и т.д. Данная информация пишется в базу временных рядов, как и само значение тега, так как от этого зависит то, как это значение будет отображено у пользователя.
Баг заключается в том, что пользователь не всегда видел данные, которые были реплицированы с другого сервера SEDMAX, при этом в базе значения были.
В качестве базы временных рядов используется InfluxDB. Оказалось, что она не очень хорошо реплицируется своими средствами. Иногда данные пропадали. Для нас это неприемлемо и поэтому была написана собственная репликация. Если какое-то поле записывается в базу, то оно отправляется на другой сервер и пишется в базу другого сервера. Проблема в том, что значение и дополнительные состояния этого значения — отдельные поля в базе и они отправляются по отдельности в разных сообщениях репликации.
Помимо записи в базу необходимо держать кеш последних значений для горячего резервирования. Если сервера поменяют роли, то на бывшем резервном сервере уже есть кеш последних значений. Поскольку дополнительные поля приходят отдельно от значений, то необходима логика сбора этих полей в одну структуру тега со всеми своими состояниями.
Когда-то было принято решение, помечать поля состояний -1, если сообщение репликации пришло без него. Выходили такие сообщения:
[]Tag{
{ID:42, Value: 100500, Status: -1, Quality: -1},
{ID:42, Value: nil, Status: 4, Quality: -1},
...
}
Когда в кеш приходило такое сообщение, было понятно, что надо в нём обновить. -1 фактически означало, что значение этого поля неизвестно.
В какой-то момент появилось ещё одно поле состояний State, и оно несколько отличалось от уже имеющихся.Формировалась не особо эффективная практика заведения на каждую новую бизнес логику нового поля, от которой мы решили отказаться. На этот раз взяли битовое поле вместо перечисления и разделили его биты на разный функционал. Например, установленный нулевой бит означал значение в будущем; первый, что значение не надо записывать в базу, но отправить подписчикам и т.д. А вот логику обновления в кеше не изменили. Если в сообщении репликации нет нового поля, то оно устанавливалось на -1 и игнорировалось кешем.
Поскольку новое поле состояний являлось битовым, а не перечислением, значение -1 устанавливало все биты в 1 из-за особенности хранения отрицательных чисел (см. «дополнительный код»). А каждый бит определяет часть бизнес логики, что и проявилось в баге.
Чтобы таких багов не появлялось, не стоит использовать одну переменную для разных бизнес процессов. Необходимо было завести флаги установки значений в сообщении в виде отдельных полей, чтобы их значения не влияли на логику полей состояний.
[]Tag{
{ID:42, Value: 100500, IsValueSet: true},
{ID:42, Status: 4, IsStatusSet: true},
...
}
Простота ключевого слова go
Хоть в go и есть сборщик мусора, это не значит, что память сервиса не может расти бесконтрольно. Одна из причин — утечка горутин. Этот баг проявился именно в этом: в одном из сервисов горутины всё время росли, что приводило к росту памяти сервиса до предела и неработоспособности всей системы.
Когда приходит баг с ростом горутин очень помогает понять в чем дело утилита pprof, поэтому настоятельная рекомендация — запускать http сервер этой утилиты в каждом сервисе. Если с её помощью посмотреть список запущенных горутин, то можно увидеть каких именно горутин слишком много, обычно они в самом конце списка. Как раз так и было выяснено, каких именно горутин слишком много.
В go очень простая на первый взгляд асинхронная модель. Если хочешь, чтобы некие действия шли асинхронно, не задерживая выполнения некой функции, просто пиши go process() и выполнение process будет происходить в отдельной горутине, возможно даже параллельно с функцией, которая запустила эту горутину. Поэтому обработка сигнала, не требующая ответа, часто выполняется в горутине.
func (Server) Handler() error {
go process()
return nil
}
Таким образом, мы и логику обработки сигнала выполняем и хендлер не задерживаем: отвечаем сразу, что сигнал принят. В SEDMAX есть сигнал, который мы внутри называем «колокольчик», который ловит множество сервисов и для них это означает «перечитать свои базы данных, обновить внутренние объекты». Сейчас такой подход не приветствуется, так как хотелось бы более управляемого обновления, с очередью и ответом, что обновление произошло. Но есть множество старых сервисов, которые пока не планируется менять, поэтому этот сигнал скорее всего будет жить вечно.
Так как может работать одновременно более одного экземпляра горутины process, вычитку данных из базы надо защищать мьютексом. Полное выполнение process занимает некоторое время. А если этот сигнал приходит достаточно часто? Тогда горутины process начнут расти и сразу блокироваться мьютексом, что приводит к утечке горутин, а значит и памяти.
Как же можно поправить данный баг? В этом случае на каждый сигнал выполняется одно и тоже действие. Выходит, что нет смысла запускать горутину process, если она уже запущена или ожидает запуска. Надо только убедиться, что из десятков сигналов, дойдёт только последний.
type Server struct {
ch chan struct{}
}
func NewServer() *Server {
s := &Server{
// 1 чтобы при записи в канал не ожидать, когда из него прочитают
ch: make(chan struct{}, 1),
}
go s.run()
return s
}
func (s *Server) Handler() error {
select {
case s.ch <- struct{}{}:
default:
}
return nil
}
func (s *Server) run() {
for range s.ch {
process()
}
}
Представлена упрощённая реализация, показывающая суть, всё лишнее убрано. Handler по прежнему не блокирующий. Если сигнал ещё не обработан, то select уйдёт в ветку default, а если сигнала в канале нет, то он запишется без блокировки, так как канал буферизированный. Обработка сигнала происходит в отдельной горутине. Новых горутин не запускается и утечки не будет, даже если сигнал будет приходить в тысячу раз быстрее, чем выполняется process. Обработается только первый и последний сигнал, все, что между ними — игнорируется. Более того, нет смысла защищать process внутри мьютексом, так как в один момент времени может работать только одна такая функция.
В SEDMAX есть библиотека, которая инкапсулирует множество шаблонов работы с каналами. Есть там и такой шаблон, когда сигнал не надо хранить в канале, если его никто не читает, а надо заменить. Сырые каналы в go довольно опасная штука. Именно поэтому была создана эта библиотека. И на ревью всегда вызывает настороженность использование сырых каналов и запуск горутин, которые имеют имя, отличное от run. Очень уж часто это приводит к багам.
