Рецепты отладки. Компилятор или программист?
При отладке этого бага в какой-то момент времени у меня даже появилась уверенность, что я имею дело с багом компилятора, а не с программистской ошибкой. Тем не менее, бага была найдена, работоспособность программы в Release конфигурации восстановлена, а репутация компилятора MSVC осталась {пока что} “непокобелимой”.
Код, который пришлось отлаживать, был аццким. Это был страшный запрос к SQL драйверу, который получал килограммы информации и распихивал ее по разным структурам. В черновом виде этот код можно было представить как:
char column1[256]; char column2[256]; char column3[256]; char column4[256]; ... sqlDiver.Bind(1, column1, sizeof(column1)); sqlDiver.Bind(2, column2, sizeof(column2)); sqlDiver.Bind(3, column3, sizeof(column3)); sqlDiver.Bind(4, column4, sizeof(column4));while (sqlDiver.MoveNext()) { if (stage == NONE) { ... Анализируем column1 и заполняем stage правильно } else if (stage == STAGE_PROCESS_INFO1) { ... Кидаем данные из column2...4 в списки } else if (stage == STAGE_PROCESS_INFO2) { ... Кидаем данные из column2...4 в списки } else ... } |
_Winnie C++ Colorizer |
Проблема была в том, что код в дебаге работал нормально, в релизе – нет. Кстати, при просмотре в коде уже были обнаружены разные дополнительные строчки со страшными комментариями, что вставлены они только для того, чтобы все в Release заработало. Действительно работало, но недолго :(.
Изначально оказалось, что поведение системы в Release заключалось в следующем: никакие списки INFO1, INFO2 и другие не заполнялись вообще. Поэтому после считывания данных из SQL таблицы системы рапортовала, что не может найти никаких данных для анализа, и успокаивалась. В Debug при этом все работало правильно.
Вполне естественное желание в этой ситуации – это заглянуть в дизассемблер и посмотреть, где мы там гуляем. Код, разумеется, оптимизированный до безобразия, но по вызовам ключевых функций можно было догадаться, что ни в один if() мы не попадаем. После более тщательного анализа было найдено, что переменная stage лежит на стеке, а вот оптимизатор в самом начале функции решил записать ноль в переменную ESI и сравнивать с ней. Так что получилось примерно следующее:
_ESI = 0; ... char column1[256]; ... if (stage == _ESI) { ... Анализируем column1 и заполняем stage правильно ... |
_Winnie C++ Colorizer |
Выяснилось, что _ESI к моменту выполнения первого if() содержит не 0, а 0xFFFFFFFF, и соответственно, никакое из условий не выполняется. Также быстро выяснилось, что значение ESI меняется в процессе вызова sqlDiver.MoveNext().
Лирическое отступление. Компилятор, разумеется, сохраняет значение основных регистров в процессе вызова функций. Для этого используется стек примерно следующим образом:
bool SqlDiver::MoveNext() { 0090B430 push ebp 0090B431 mov ebp,esp 0090B433 push 0FFFFFFFFh 0090B435 push offset __ehhandler$?MoveNext@SqlDiver@easyodbc@@QAE_NXZ (0C3FC40h) 0090B43A mov eax,dword ptr fs:[00000000h] 0090B440 push eax 0090B441 push ecx 0090B442 sub esp,0D8h 0090B448 push ebx 0090B449 push esi 0090B44A push edi 0090B44B push ecx ... 0090B489 call @ILT+42070(_SQLFetchScroll@12) (6D845Bh) ... 0090B4DA pop ecx 0090B4DB pop edi 0090B4DC pop esi 0090B4DD pop ebx 0090B4DE add esp,0E8h 0090B4E4 cmp ebp,esp 0090B4E6 call @ILT+88040(__RTC_CheckEsp) (6E37EDh) 0090B4EB mov esp,ebp 0090B4ED pop ebp 0090B4EE ret |
_Winnie C++ Colorizer |
Весь код внушал здоровый оптимизм, но тем не менее, вызов pop esi получал 0xFFFFFFFF вместо ожидаемого нуля. Вызов внутренней функции SQLFetchScroll() вместе с одновременным просмотром содержимого Memory 1 действительно показывал, что в том месте, где было сохранено значение ESI, появлялось 0xFFFFFFFF. Data Breakpoint показал, что по указанному адресу трижды происходило сохранение “левых” данных.
0x0012291E 12 00 00 00 00 00 01 00 00 00 3c 2a ..........<* 0x0012292A ff ff ff ff 90 00 01 00 00 00 a4 26 ...........& 0x00122936 8c 02 d1 1e 38 f4 e0 33 12 00 00 34 ..С.8фа3...4 |
_Winnie C++ Colorizer |
Начиная с этого момента основная концентрация сил произошла вокруг вызова SQLFetchScroll(). Имело место быть гипотеза, что неправильная комбинация аргументов приводила к тому, что затирался стек. Однако затирка была очень странная – происходило затирание четырех байтов стека выше функции вызова – это совсем не было похоже ни на buffer overrun, ни на другие проявления ошибок памяти. Целенаправленно терлись именно 4 байта посередине стекфрейма. Кроме того, гугль про ошибки на стеке при вызове SQLFetchScroll() молчал как партизан.
Чтобы было понятнее, подробнее расскажу, что делалось. Метод Bind() связывал информацию из столбцов с указанными переменными column1…4, метод MoveNext() считывал следующую строчку из SQL таблицы и распихивал данные по указанным ранее переменным (особо сложных аргументов у него не было). Метод Bind() выглядел примерно так:
bool SqlDiver::Bind(int col_no, char* buff, int len) { SQLINTEGER sz = 0; SQLRETURN rc = SQLBindCol(m_hStmt, col_no, SQL_C_CHAR, buff, len, &sz); if (rc == SQL_ERROR) { HandleError(); } ... } |
_Winnie C++ Colorizer |
Бага не поддавалась. Было перепробовано несколько вариантов, добавлялось отладочное протоколирование системы (поскольку после прохода по дизассмблеру было предположение, что в Bind() передаются некорректные адреса column1…4), отключалось whole program optimization (так как линковка приложения занимала непозволительно долгое время). Все эти изыскания приводили либо к тому, что бага пропадала, либо к тому, что программа зависала (внутри NTDLL!), либо к тому, что падение начинало происходить в совсем неожиданных местах. Ключевым моментом в понимании процессов стало то, что я попробовал увеличить размеры column1…4 в несколько раз, сохранив размеры передаваемых аргументов как 256 байт. Ошибка осталась на том же месте, и это стало основой для понимания того, что с буферами никаких проблем нет. Также никаких изменений в поведении программы не было при переносе colunm1…4 в статическую область памяти.
Отчаявшись найти ошибку таким образом, я таки решил “прочитать инструкцию” и посмотреть, что из себя представляют SQL методы SQLBindCol и SQLFetchScroll. Озарение пришло в момент просмотра туториала – в туториале последний аргумент SQLBindCol() ссылался на глобальную область памяти. Мгновенно стало ясно, что buff и sz должны быть глобальными переменными, адреса которых ЗАПОМИНАЮТСЯ в SQLBindCol() и ЗАПОЛНЯЮТСЯ при вызове SQLFetchScroll(). В нашем случае ацйкий инди-код от стороннего туториала передавал в SQLBindCol() адрес ЛОКАЛЬНОЙ переменной sz, которая теряла всякую осмысленность после возврата из метода Bind. При последующем вызове MoveNext() по этому адресу оказывалось значение сохраненной переменной ESI, куда и записывалось -1 или 0xFFFFFFFF. После возврата из MoveNext() поведение программы зависело от фазы луны.
Ошибка была исправлена после переноса переменной SQLINTEGER sz в статическую область памяти. Суммарный дебаг занял около двух часов.
Выводы из дебага:
1. Нам сильно повезло, что изначальное проявление ошибки было именно в области ее возникновения. Если бы изначально ошибка проявлялась в зависании в NTDLL, на поиск можно было бы потратить сильно больше двух часов. Пример такой отладки я приводил ранее, в статье “Рецепты отладки. Четырехмесячный дебаг.”.
2. Несмотря на то, что симптомы ошибки очень напоминали сбой компилятора, в ошибке все равно надо было разобраться подробно. Когда-нибудь, когда я натолкнусь на действительный баг компилятора, я опишу последовательность событий. В данном случае попытка однозначной классификации как баг компилятора или как баг программиста дала положительный (для компилятора, разумеется :)), ответ.
3. Ошибка возникала и ранее, в коде были видны попытки добавить stub-вызовы таким образом, чтобы исключить эффект от затирания ESI. Хорошо, что ошибка стала проявляться снова еще в период разработки ПО, а не у заказчика (или, например, стала бы проявляться после защиты старфорсом).
4. Ошибка могла и не проявиться вообще. Например, если бы компилятор не стал бы оптимизировать работу с ESI или если бы вызов SQLFetchScroll() не отработал бы на базе данных ни разу. Тем не менее, ошибка присутствовала в коде, и только у-порно-дебаг позволил ее найти и исключить.
5. Читайте документацию и изучайте туториалы. Они вам могут понять, как надо использовать функции (а не как вы их хотите использовать).
6. Несанкционированное изменение значений переменных и регистров – часто результат работы с локальными переменными предыдущих функций. Это может либо возврат адреса локальной переменной в вызывающую функцию, либо (как в этом экзотическом случае) сохранение адреса локальной переменной для последующей работы.
7. Внешние семплы и врапперы – не всегда в помощь ))))
Какие конкретно приемы были использованы для поиска бага:
1. Анализ дизассемблера сбойной функции для понимания того, какие изменения в регистрах произошли и того, что они произошли несанкционированно для компилятора/оптимизатора;
2. Анализ дизассемблера вызываемой функции, чтобы исключить ошибки компилятора внутри MoveNext();
3. Memory Watch и Data breakpoint для проверки несанкционированного изменения стека;
4. Изменение настроек компилятора и параметров функций для попыток вывести ошибку в другую область памяти;
Ключевым приемом стало, впрочем, именно прочтение документации ))))).
Приятной вам отладки.
Pingback: highly professional scums » Blog Archive » Рецепты отладки. 3 типа нестабильностей.()
Pingback: highly professional scums » Blog Archive » One-liner()