[prog.bugs] По следам недели охоты на жуков

Неделю с 27.06 по 01.07 смело могу охарактеризовать как bugs hunting week. Она практически вся ушла на поиск и устранения багов в программах, которые до этого успешно отработали не один месяц, а то и пару лет.

Первая проблема, почти что не моя:)

Есть у нас софтина, отвечающая за массовые рассылки SMS-ок. Работает давно, баги проявляются редко. Запущена в количестве нескольких десятков экземпляров. В добром десятке из них рассылки должны стартовать в 9:00 утра. И до прошлой недели так и было. Но потом вдруг в парочке экземпляров рассылка стартовала не в 9:00, а в 8:00. Целый день выкуривания логов привел к мысли – неправильно высчитывается часовой пояс получателя сообщения. Но почему непонятно. Непонятно так же и другое – из десяти экземпляров в восьми эта проблема не наблюдается, а в двух проявляется. Причем работает все это на одном и том же сервере, и версии бинарников у всех экземпляров одинаковые.

На следующий день, когда проблема проявилась вновь и последовал новый сеанс психоанализа копания в логах, начали проявляться слабые лучики надежды. Перед началом проблем произошел апгрейд версии программы и выяснилась такая вещь – заглючили те экземпляры, у которых регистрация новых рассылок производилась новой версией. А вот там, где новые рассылки регистрировались чуть раньше еще старой версией, все было нормально. Т.е. старая версия вычисляла часовой пояс абонента правильно и фиксировала в БД правильное время начала рассылки. А вот новая версия ошибалась на один час. Поэтому в БД попадало неправильное время, и рассылка стартовала не вовремя.

Но код по вычислению смещения времени от UTC в обоих версиях был одинаковый. Он вообще не изменялся лет пять. Тем не менее, старая версия работала правильно, а новая – нет. В чем же дело? В версии компилятора :)

Когда-то давно мне потребовался простой кроссплатформенный способ определения смещения локального времени от UTC, да еще с учетом летнего времени. Как водится, происходило все в условиях жуткого цейтнота, да и с ходу готового решения в сторонних библиотеках найдено не было. Зато был придуман такой простой способ:

valid_timezone_t valid_timezone_t::make_from_localtime()    {       std::time_t now = std::time( 0 );       std::time_t now_aux = std::mktime( std::gmtime( &now ) );       // Разница между локальным временем и UTC в секундах.       return valid_timezone_t( now - now_aux );    }

Т.е. берется локальное время, затем оно выдается за UTC, затем опять за локальное. И разница между двумя локальными временами даст искомое значение.

Этот способ отлично работал и для зимнего, и для летнего времени. В Visual C++ 7.1. А вот в Visual C++ 9.0 и 10.0 перестал. В новых версиях функция gmtime в стандартной библиотеки уже не учитывает признак наличия летнего времени по умолчанию. Посему такое преобразование дает на час меньше.

Как раз старая версия программы, для компиляции которой использовался старый добрый VC++ 7.1 работала правильно. А вот новая, для которой использовался VC++ 9.0 стала глючить.

Кстати говоря, проанализировав аналогичные функции в ACE и POCO, выяснилось, что корректно смещение от UTC с учетом летнего времени вычисляется в POCO, а не в ACE. ACE вообще для России выдает отрицательное смещение :)

Проблема вторая, почти что моя :)

Есть у нас большая (по моим деревенским меркам) БД, на основе которой делается расчет статистики, формирование отчетов и другие полезные для компании вещи. Информация в эту БД импортируется несколькими копиями специальных программ-импортеров и обрабатывается программой-репортером. Главное требование к импорту – это его скорость, нужно вставлять по несколько тысяч записей в секунду. Если не будем успевать, то генерация новой информации будет обгонять ее сохранение в БД, чего допускать, понятное дело, нельзя. Особенно в конце месяца, т.к. в начале месяца идет интенсивная обработка статистики.

Программы были написаны и внедрены. Вроде бы успешно работали. Изредка были жалобы о том, что иногда наблюдаются притормаживания импорта. Иногда кто-то зависает. Но, поскольку критически важными эти проблемы не объявлялись, а свободных людей, как всегда не было, то тщательное разбирательство с этими редкими инцидентами все время откладывалось до “лучших времен”. Коими стала среда 29 июня (т.е. за два дня до начала нового месяца).

Внезапно выяснилось, что программы импорта стали очень стабильно зависать. А программа-репортер стала стоить отчеты непозволительно долго. Т.е., если оценивать ситуацию объективно, наступила полная жопа. Повторюсь, выяснилось это за два дня до момента “Ч” – активного формирования отчетов.

К сожалению, здесь мы не смогли вовремя раскачаться. Сказалось то, что весь софт эксплуатируется в Москве, разработчики находятся в Гомеле. Прямого доступа к боевым серверам по умолчанию у нас нет. Пришлось потратить день на то, чтобы выяснить симптоматику, собрать максимум информации из логов программ и мониторов сервера БД, организовать нам доступ к боевым серверам, согласовать с эксплуатаций последовательность шагов по модификации программ для того, чтобы точно локализовать место проблемы. Плюс здесь я как-то отнесся к ситуации без должной серьезности, полагая, что когда мы нашпигуем программы подробным диагностическим логированием, ошибка обнаружится автоматически. Чего, в соответствии с законами Мэрфи, не произошло :)

Поэтому четверг выдался напряженным и нервным. Очень помогло то, что накануне нам обеспечили удаленный доступ к боевым серверам и мы могли в реальном времени наблюдать за развитием событий. Проблему обнаружили ближе к концу рабочего дня. Оказалось, что программа-импортер выполняет две весьма тяжелые операции – большой insert из временной таблицы в основную и большой update основной таблицы на основании информации из временной. И в какой-то ситуации этот update начинает выполняться не доли секунды, как положено, а сотни секунд, иногда десятки минут. Что блокирует все остальные импорты, которым нужна эта же основная таблица.

Причина длительного выполнения update банальна – в БД не было индекса, который бы сервер БД мог использовать для оптимизации. Соответственно, использовался перебор. Но, судя по всему, в подавляющем большинстве случаев перебор проходил очень быстро. И только иногда превращался в полный перебор большой таблицы. Как раз в конце июня таких невезучих моментов стало больше. После добавления индекса в БД и небольшой корректировки SQL-я в программе-импортере операция update просто взлетела.

Оглядываясь назад просто офигиваешь от вопроса “Как же получилось, что индекс для оптимизации update не было добавлен с самого начала?” Ответ, к сожалению, прост до невозможности. Разработчик тупо об этом забыл, тем более что наши автономные тесты на ограниченных, хоть и больших, выборках реальных данных ее не показывали (да и в реальной работе она проявлялась не часто). А я, как ответственный за эту разработку не проконтролировал. Т.е. посмотрел, что в БД индекс для оптимизации insert-а есть, а вот про оптимизацию update не подумал :(

Проблема третья, полностью моя :)

Не успели слегка притупиться впечатления от первой из описанных проблем с программой рассылки SMS, как в ней в пятницу, 1-го июля, обнаружился еще один жук. Из десяти запущенных экземпляров один вовремя не начал рассылку. Хотя все данные в БД были нормальные, логи писались, на внешние раздражители он реагировал. Но SMS-ки рассылать отказывался напрочь.

Первые полтора часа поиска ошибки были просто непередаваемыми. Такого абсолютного непонимания происходящего и ощущения полной беспомощности у меня не было уже давно. Первая зацепка появилась при анализе активности запросов проблемного экземпляра к БД. Выяснилось, что среди множества выполняемых запросов нет одного – выборки готовых к отсылке SMS. Но почему этих запросов нет?

Выкуривание исходников показало, что в отсутствии каких-либо ранее неизвестных багов такое возможно в одном случае – если для программы задана нулевая скорость рассылки. Но она не нулевая. Скорость была установлена в 20 сообщений за 60 секунд (т.е. один SMS раз в три секунды). Причем программа это указание восприняла – это было видно и логам, и по мониторингу внутренних параметров приложения. Тем не менее, программа почему-то поступала так, как будто скорость была нулевой.

Тут я ради эксперимента на пару секунд поставил скорость в 60 sms/60 sec. И рассылка пошла! Вернул 20/60 – остановилась. Опять 60/60 – пошла, 20/60 – стоит. Значит дело в магическом сочетании 20/60. Уже хорошо. Делаю скорость 21/60, рассылка стартует, а я начинаю в спокойной обстановке разбираться с магией сочетания 20/60.

Дело оказалось в способе обработки дробных скоростей, т.е. когда получается скорость в 201.27 sms/sec или, как в этом случае, 1/3 sms/sec. Я отдельно учитывал целую и дробные составляющие скорости. Т.е. для 201.27 целая составляющая 201, дробная – 0.27. Для 1/3 (тех самых 20/60) целая – 0, дробная – 0.33(3). Каждую секунду программа суммировала дробные составляющие и если на очередной секунде эта сумма превышала 1, то отсылался лишний SMS, после чего за начальное значение бралась дробная часть накопленной суммы. Так, если дробная часть 0.27, то получалась последовательность – 0.27, 0.54, 0.81, 1.08 (отсылка еще одного дополнительного SMS), 0.08, 0.35, 0.62, 0.99, 1.26 (отсылка еще одного дополнительного SMS), 0.26,…

Вполне себе работающая схема. Только для 1/3 почему-то не сработавшая. А вот чтобы объяснить причину придется сделать небольшое лирическое отступление. В университете я специализировался на кафедре “Вычислительная Математика и Программирование”, где программирование рассматривалось как инструмент для организации численных вычислений на компьютере. Так вот, нам вбивали в голову с младых лет, что нельзя (не просто нельзя, а НЕЛЬЗЯ) сравнивать два вещественных числа на равенство. Ну не бывает в реальной жизни совпадения a==b, если a и b были получены в результате вычислений. Нужно сравнить на равенство – требуй, чтобы модуль разности a и b был меньше нужной тебе точности. По другому никак.

Именно поэтому, в программе я написал так:

const double fractional_part_value =       m_fractional_part_accumulator +       // С помощью такого умножения мы обрабатываем ситуации,       // когда из-за каких-либо задержек check_for_new_period       // вызывается не каждую секунду, а через несколько секунд.       seconds_from_start * m_calculated_load.fractional_part(); if( fractional_part_value > 1 )    m_planned_load += 1; m_fractional_part_accumulator = get_fractional_part_of_number(       fractional_part_value );

Т.е. я требовал, чтобы fractional_part_value была строго больше единицы. А вот для скорости 1/3 на каждой третьей секунде fractional_part_value получалась ровно 1.0. Поэтому этот if не отрабатывал, SMS не отсылался. А затем в m_fractional_part_accumulator помещалось значение 0.0. Т.е. последовательность оказалась такой – 0.333, 0.667, 1.0, 0.0, 0.333, 0.667, 1.0, 0.0… Тогда как я, записывая строгое неравенство ожидал 0.333, 0.666, 0.999, 1.332 (отсылка), 0.332, 0.665,…

Исправление элементарное – строгое неравенство заменяется на нестрогое. Но больше всего в этой ошибки меня поразила не сама ошибка и даже не ее причина. Сильно вставило осознание такого факта – кроме как разработчик никто  не смог бы ни понять в чем же дело, ни даже предположить ситуацию, при которой этот баг себя проявит.

---

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