?

Log in

No account? Create an account
 
 
14 Октябрь 2008 @ 23:14
Рецепты отладки. Компилятор или программист?  
При отладке этого бага в какой-то момент времени у меня даже появилась уверенность, что я имею дело с багом компилятора, а не с программистской ошибкой. Тем не менее, бага была найдена, работоспособность программы в 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. Изменение настроек компилятора и параметров функций для попыток вывести ошибку в другую область памяти;

Ключевым приемом стало, впрочем, именно прочтение документации ))))).

Приятной вам отладки.

Crossposted to http://blog.gamedeff.com
Метки: ,
 
 
Местонахождение: гостинницо
 
 
 
__kas__ on Октябрь, 14, 2008 19:46 (UTC)
дада, я помню как не любят сматреть примеры!
Михаил Певзнерpigmeich on Октябрь, 15, 2008 03:13 (UTC)
SQL-драйвер, это случаем не к основному проекту 1С? :)
Дядя Димаddima on Октябрь, 15, 2008 10:05 (UTC)
Не-а ))))
cofffecofffe on Октябрь, 15, 2008 06:27 (UTC)
эпично.
Alexander Porechnovscmorr on Октябрь, 15, 2008 07:00 (UTC)
Самый главный пункт это пятый. Меня реально до сих пор поражает как повсеместно это скипается.
virtulvirtul on Октябрь, 15, 2008 07:37 (UTC)
Спасибо, цикл про отладку очень впечатляет.

У меня просьба - а можно что-нибудь по heap corrution. Как ловить ошибки вроде
char* a = new char[10]; a[11] = 0; delete [] a;

или двойное удалениt, или вообще случайную запись как с тем bool. )
Дядя Димаddima on Октябрь, 15, 2008 08:44 (UTC)
Про heap corruption обязательно напишу, постараюсь на этой неделе после командировки. Но ошибки типа a[11] = 0 должны вообще ловиться автоматически при помощи отладочного менеджера памяти.
virtulvirtul on Октябрь, 15, 2008 11:00 (UTC)
a[11] ловятся для статик буферов при компиляции с /GS или /RTCs. crtdbg ловит для хипа?
Andy Melnikovnponeccop on Декабрь, 15, 2009 17:59 (UTC)
> crtdbg ловит для хипа?

Не ловит. Средства в нем есть, но они хуже средств, встроенных в Windows, которые включаются и отключаются с помощью AppVerifier и хуже того, что делает Rational Purify.
Andy Melnikovnponeccop on Декабрь, 15, 2009 17:49 (UTC)
> ошибки типа a[11] = 0 должны вообще ловиться автоматически
> при помощи отладочного менеджера памяти.

Собственно, AppVerifier это и делает. Замещает в указанном приложении менеджер кучи на отладочный. Он ещё dirtystacks делает, что позволяет ловить переполнения, пропущенные /GS /RTCs

(Удалённый комментарий)
virtulvirtul on Октябрь, 15, 2008 15:52 (UTC)
Видел, не совсем то. Интересует скорее нечто похожее на /RTCs для буфферов на хипе (перезапись), двойное/неправильное удаление, случайная запись и пр. Короче говоря "как написать (или какой существующий использовать) правильный менеджер памяти" )
(Удалённый комментарий)
Дядя Димаddima on Октябрь, 16, 2008 11:43 (UTC)
Re: Ну, как написать
Я пробовал верифаер, он у меня не запустился на компе. Чуть поподробнее описывал тут: http://ddima.livejournal.com/23300.html
Andy Melnikovnponeccop on Декабрь, 15, 2009 15:52 (UTC)
Re: Ну, как написать
> а могут внешние тулзы (BoundsChecker, AppVerifier(кстати, кто-нибудь пробовал это??))

Пробовал AppVerifier и IBM Rational Purify.
(Удалённый комментарий)
virtulvirtul on Октябрь, 21, 2008 07:23 (UTC)
А вот это уже интересно - спасибо.
Серега: fuckpap0nt on Октябрь, 15, 2008 10:37 (UTC)
вот так и отлаживаем ;)
просто нет слов. отличная статья.
Andy Melnikovnponeccop on Декабрь, 15, 2009 15:51 (UTC)
Отвратительная статья.
Дядя Димаddima on Декабрь, 15, 2009 16:30 (UTC)
Можно попросить развернуть ответ? Что именно в ней было не так?
Andy Melnikovnponeccop on Декабрь, 15, 2009 17:43 (UTC)
Пропаганда нездорового образа жизни. Статья не отражает того, что приемы, использованные вами в реальной жизни, не являются рекомендованными. Следовало бы включить в неё аналитический раздел - показать не только то, что было сделано, но и то, почему было сделано именно так, и что могло бы быть сделано для более быстрого поиска бага.

Статья написана недостаточно детально, и её процитировали как пример системных проблем с С++. Собственно, так я к вам и попал. Хотя у вас просто совпало:

1) что разработчик, писавший SqlDiver::Bind, либо неправильно понял документацию в MSDN по последнему параметру SQLBindCol (хотя там всё четко), либо каким-то чудом допустил редкую на практике детсадовскую ошибку.

2) что у вас стоит антивирус, падающий при установке глобалфлагс (это практически фаза луны!)

3) что у вас в организации не принято использовать дополнительную билд-конфигурацию с release crt и отключенной оптимизацией, и вам пришлось ковыряться в ESI и подозревать чуть ли не баги компилятора, и вы не догадались (или не смогли по каким-то уважительным, но не упомянутым в статье причинам) её создать или просто временнно отключить оптимизацию хотя бы для конкретных подозреваемых файлов. Вы отключали только WPO, и мотивировали в статье это совершенно другими причинами.

А также:

4) Вы не указали rationale для "переноса переменной SQLINTEGER sz в статическую область памяти", и строка выглядит как рекомендация использовать подобные горбатые решения для затыкания дыр. Если сделали горбато - так и напишите, что "ни в коем случае так не делайте без уважительных причин". Прямое решение - делать sz членом SqlDive или передача переменной для будущего размера колонки дополнительным параметром по ссылке в bind(). Если это было невозможно - следовало бы написать.

5) Из 4-х приемов, перечисленных в конце, действительно рекомендуемым в данной ситуации был только пункт 3, а остальные приемы были сделаны либо по причине, что вы сплоховали (эвфемически, "в рабочей обстановке сработали субоптимально"), либо по неким умалчиваемым причинам, не следующим из текста статьи.
Дядя Димаddima on Декабрь, 15, 2009 18:27 (UTC)
Спасибо большое за развернутый ответ. На самом деле я хотел проиллюстрировать именно то, что ошибки changed memory global могут приводить не к более частым ситуациям неожиданного изменения переменной на стеке или в dataseg, а вот к таким странным проявлениям, когда запорот ESI, использовавшийся в родительской функции как нулевая (!) константа.

Совпадений действительно много, хотя почти все они и объяснимы.

1. Кто разработчик SqlDiver::Bind - так и не удалось выяснить, это был чей-то страшный "middleware sample" :).
2. Про антивирус и global flags - честно говоря, недопонял, можно пояснить?
3. Конфигураций компиляции по умолчанию - четыре, и только на одной из них проявлялось подобное поведение. Я не исследовал подробно ситуации, по каким адресам стека находилась SQLINTEGER sz в Debug или Release без оптимизации и почему модификация этой области стека была там некритична. Но симптомы при любых попытках собрать билд в другой конфигурации описаны - пропадания ошибки, зависания в NTDLL, падения в других местах. Я действительно не перечислил в статье все варианты изменения конфигураций и кода, каюсь, но их за пару часов было сделано не меньше десятка - WPO, разные типы оптимизаций, SEH, security checks, добавочное логгирование и т.п. Ни один из них не дал новой пищи для размышлений.

То, что решение "горбатое" - целиком и полностью согласен, и в это меня уже тыкали в коментах выше. Но в тот момент времени это было "проверочное" решение, а поскольку задача не стояла как "сделать отличный универсальный SqlDiver", а "локальным кодом считать таблицу из XLS", это было вполне себе промежуточное решение. К слову, в той организации, в которой я в тот момент времени был в командировке, подобные хаки должны сопровождаться тегами с подробным комментированием и планами по последующему рефактору неудачно скопипастенного из инета написанного семпла.

По поводу приемов в конце - я их перечислял в порядке применения. Знать бы, где находится баг в незнакомом для меня SQL API, возможно, проблема нашлась бы раньше. Анализ дизасма как раз и требовался для того, чтобы исключить действительно подходящий по всем симптомам баг компилятора. Поэтому никаких умолчаний, порядок применения приемов был ровно такой, какой я пробовал в течение дваух часов дебаггинга. Повторюсь, что за все годы это был первый случай в моей практике, когда порча стека так избирательно влияла на спасенный ESI, который никаким инспектами переменных было не обнаружить. Да, наверняка сработал неоптимально, но отладка была бы еще дольшей, если бы изначально падали "не там".

А какие изменения в последовательности поиска ошибки предложили ли бы вы (по тем симптомам, которые описаны в первых трех абзацах поста)?