"Раньше я жалел, что не стал конструктором самолетов... теперь я этому безмерно рад."
Началось это месяц назад. На центральном объекте в городе Б во время сбора очередного генерального месячного отчета по всей этой энергетической бухгалтерии стряслась беда. Обновленные как нельзя кстати алгоритмы расчетов и структура БД, не до конца протестированные на нагрузке, привели к парализации работы бутылочного горлышка системы -- сервера приложений, моей руки творения. Сервер просто падал в хлам, с хрестоматийной accsess violation, жирно и непредсказуемо. Нужно было срочно спасать ситуацию.
Первым делом увеличили детализацию логов. Но по ним ни черта нельзя было понять -- каждый раз привет наступал в новом месте, размер журнала составлял несколько десятков мегабайт, в нем были записи о сотне обрабатываемых клиентских сессиях и нескольких тысячах команд (и какого же количества тридов). В общем, нужен был дебаггер.
Система в городе Б установлена по всем правилам конспирологической паранойи. На машину с сервером я попадал через VPN и два RDP, и кроме этого канала ничего не было. При просьбе скачать кое-чего на машину из Интернета админы только нервно отсмеивались.
А как я запущу микрософтовский дебаггер на машине без Студии? Даже дебагнутая версия сервера не может стартовать на другой машине из-за хитро-линкуемых отладочных динамических библиотек. Некоторое время ушло на то, чтобы собрать дебаг-версию, слинкованную со статическими библиотеками. Это был отдельный квест, и микрософту отдельный за него поклон. Снаряженная масса сервера получилась 50 Мб. Кое-как удалось запустить его, но дамп, выдаваемый Dr. Watson, оказался насколько ужасен и громаден (а я сижу через два RDP, мне даже курсор мышки сдвинуть сложно, не то что дамп анализировать), что было принято решение запускать сервер под более вменяемым gdb.
Для этого срочно было все перекомпилировано с помощью MinGW'шного gcc 4.7.2. И новые 50 мегабайт сервера опять были скопированы в Б. И тут случилась великолепная шутка: запущенный под дебаггером сервер падал на инициализации ODBC драйверов. Без дебаггера отрабатывал нормально, а с ним -- падал. Причем падал сам gdb, что вообще нонсенс. Ясное дело, что проблема не в сервере, а в кривом отладчике. Танцы с бубном не помогли: и скачивание последней версии gdb, и запуск всей этой машинерии с gdbserver, и установка cygwin вместо MinGW с последующей пересборкой всего и заменой gdb, -- все это прошло впустую. Пришлось отказаться от gdb.
Сервер был собран обратно студийным компилятором и в дело был пущен дебаггер cdb. Да, от него пользы стало побольше. Наконец-то удалось увидеть номер трида, на котором обрывалась жизнь сервера, и последний callstack. А дальше начался мучительный поиск багов. Таких, за которые я бы руки отрубал... если б не сам был бы автором.
Через дня три-четыре стало ясно, что пробема в Питоне. Python 2.6 используется на сервере для выполнения скриптовых команд, которые являются обертками для алгоритмов, обслуживающих всяческие бизнес-процессы той системы, ради которой все это и затеяно.
Основные места боевых падений были связаны со встроенными С++ классами, выведенными в питоновское окружение. Тот же класс zerodbc в меру специфический и учитывает некоторые особенности системы, что в свое время исключило использование более вменяемого pyodbc.
Главная беда была в том, чтобы найти все места, где питоновская GIL отпускалась или хваталась раньше времени, что в одних случаях приводило к непредвиденным утечкам памяти, а в других -- к дедлокам. Раньше нагрузка на сервер была меньше, и таких ситуаций встречалось тоже мало. Фу, как непрофессионально. Я чувствовал себя студентом-первокурсником, исправляющим примитивнейшие опечатки в коде.
На определенном этапе ко мне присоединился Дима, коллега и друг из города Б, и с увлечением стал следить за моими потугами. Мы переписывались через джаббер и постоянно материли меня, кто во что горазд. О да, я заслужил такой порки =)
Почти все ошибки удалось найти и обезвредить. Уничтожая каждый новый баг мы приговаривали: "Как оно до этого работало?!" Многопоточное сложное приложение выполняется по принципу Мерфи: если какая-то невероятная ерунда может случиться, то она непременно произойдет. Это главное правило. Но несмотря на наши успехи, одна ошибка оставалась.
Обычный диалог был примерно следующего содержания:
nickela: ну это уже какой-то пиздец... access violation в SaveThread???
teal: да
nickela: ассемблерный дамп посмотри
В один из дней уже часов в одиннадцать вечера я решил расставить дополнительную проверку и блокировки, а также снабдить исчерпывающими логами потенциальные мемори-лико-генераторы. Дима подключился через скайп и выдал умопомрачительную по своей силе идею спрятать обработчики исключений OTL под скоуп питоновского GIL, чтобы исключить потенциальную проблему, что эксепшин в драйвере базы данных будет испорчен. Я с ним согласился и начал править код. К двум часам ночи все было готово, если б не одна досадная опечатка. В итоге весь следующий день мы ловили Fatal Python error: PyEval_SaveThread: NULL tstate. Так как последнюю правку кода я производил уже в полубредовом состоянии, то мало того, что не помнил толком, что менял, так еще и забыл сделать коммит в версионной системе. Поэтому день прошел очень весело. Ближе к концу рабочего дня мы были уже в истерике:
nickela: что-ты поправил этой ночью? признавайся!!!
Но в итоге ошибочка нашлась, чтоб ей пусто было. Это было непередаваемое облегчение -- увидеть как сервер падает на старой доброй, уже такой родной ошибке, а не на этой новой =)
В конечном итоге, перебрав все мыслимые и немыслимые сценарии, мы не пришли ни к чему. Сегодня меня случайно осенило: падение происходит потому, что в момент выполнения команды из-под нее вызывается другая команда (все это в питоне), но перед этим успевает отключиться клиент. Вместе с удаляемой клиентской сессией уходит и враппер интерпретатора, утаскивая за собой дикт сессии. В этот момент конструируется вторая команда, которая добавляет в дикт своего местного интерпретатора дикт сессии, которую она имеет по простому, не интеллектуальному указателю. В момент разыменования указателя случается бадабум.
Это многоходовка, но предусмотреть такую фигню с самого начала было очень сложно. Исправил, скопировал новую версию сервера и запустил. Работает. На этом можно наконец-то уйти на выходные. Сейчас смотрю на этот месяц, практически круглосуточный дебаг, аж страшно становится. Периодически посматриваю на watchdog -- все работает нормально. Аж не верится. Пожалуй, выпью-ка я сегодня коньячку =)
Через дня три-четыре стало ясно, что пробема в Питоне. Python 2.6 используется на сервере для выполнения скриптовых команд, которые являются обертками для алгоритмов, обслуживающих всяческие бизнес-процессы той системы, ради которой все это и затеяно.
Основные места боевых падений были связаны со встроенными С++ классами, выведенными в питоновское окружение. Тот же класс zerodbc в меру специфический и учитывает некоторые особенности системы, что в свое время исключило использование более вменяемого pyodbc.
Главная беда была в том, чтобы найти все места, где питоновская GIL отпускалась или хваталась раньше времени, что в одних случаях приводило к непредвиденным утечкам памяти, а в других -- к дедлокам. Раньше нагрузка на сервер была меньше, и таких ситуаций встречалось тоже мало. Фу, как непрофессионально. Я чувствовал себя студентом-первокурсником, исправляющим примитивнейшие опечатки в коде.
На определенном этапе ко мне присоединился Дима, коллега и друг из города Б, и с увлечением стал следить за моими потугами. Мы переписывались через джаббер и постоянно материли меня, кто во что горазд. О да, я заслужил такой порки =)
Почти все ошибки удалось найти и обезвредить. Уничтожая каждый новый баг мы приговаривали: "Как оно до этого работало?!" Многопоточное сложное приложение выполняется по принципу Мерфи: если какая-то невероятная ерунда может случиться, то она непременно произойдет. Это главное правило. Но несмотря на наши успехи, одна ошибка оставалась.
Обычный диалог был примерно следующего содержания:
nickela: ну это уже какой-то пиздец... access violation в SaveThread???
teal: да
nickela: ассемблерный дамп посмотри
В один из дней уже часов в одиннадцать вечера я решил расставить дополнительную проверку и блокировки, а также снабдить исчерпывающими логами потенциальные мемори-лико-генераторы. Дима подключился через скайп и выдал умопомрачительную по своей силе идею спрятать обработчики исключений OTL под скоуп питоновского GIL, чтобы исключить потенциальную проблему, что эксепшин в драйвере базы данных будет испорчен. Я с ним согласился и начал править код. К двум часам ночи все было готово, если б не одна досадная опечатка. В итоге весь следующий день мы ловили Fatal Python error: PyEval_SaveThread: NULL tstate. Так как последнюю правку кода я производил уже в полубредовом состоянии, то мало того, что не помнил толком, что менял, так еще и забыл сделать коммит в версионной системе. Поэтому день прошел очень весело. Ближе к концу рабочего дня мы были уже в истерике:
nickela: что-ты поправил этой ночью? признавайся!!!
Но в итоге ошибочка нашлась, чтоб ей пусто было. Это было непередаваемое облегчение -- увидеть как сервер падает на старой доброй, уже такой родной ошибке, а не на этой новой =)
В конечном итоге, перебрав все мыслимые и немыслимые сценарии, мы не пришли ни к чему. Сегодня меня случайно осенило: падение происходит потому, что в момент выполнения команды из-под нее вызывается другая команда (все это в питоне), но перед этим успевает отключиться клиент. Вместе с удаляемой клиентской сессией уходит и враппер интерпретатора, утаскивая за собой дикт сессии. В этот момент конструируется вторая команда, которая добавляет в дикт своего местного интерпретатора дикт сессии, которую она имеет по простому, не интеллектуальному указателю. В момент разыменования указателя случается бадабум.
Это многоходовка, но предусмотреть такую фигню с самого начала было очень сложно. Исправил, скопировал новую версию сервера и запустил. Работает. На этом можно наконец-то уйти на выходные. Сейчас смотрю на этот месяц, практически круглосуточный дебаг, аж страшно становится. Периодически посматриваю на watchdog -- все работает нормально. Аж не верится. Пожалуй, выпью-ка я сегодня коньячку =)
No comments:
Post a Comment