понедельник, 6 ноября 2017 г.

Windbg debugging series, part 2 of n. Stack overflow

Вторая часть, в которой мы обсудим ошибки переполнения стека. В основном, мы будем обсуждать переполнение стека в ядре, т.к. там все более драматично, чем в user-mode. Про user-mode расскажу в конце статьи.

Вступление

Однажды у нас зафейлились ночные тесты, некоторые тестовые машины не могли стартовать после перезагрузки - случался BSOD. Подключив kernel debug, я принялся за анализ.

Что самое главное в продуктивной отладке - правильно, наличие отладочных символов - .reload /f и можно пойти попить кофе, пока грузятся символы. После этого .logappend windbg_analysis.log и приключение начинается.

Анализ

Следующая команда, которая обычно чаще всего выполняется - !analyze -v — это замечательное расширение создано для того чтобы проводить анализ зависаний, падений, крешей и прочего. Я не буду приводить весь вывод этой команды, вместо этого, я укажу несколько интересных кусочков, на которые стоит обратить внимание:

0: kd> !analyze -v

UNEXPECTED_KERNEL_MODE_TRAP (7f)

Arguments:
Arg1: 00000008, EXCEPTION_DOUBLE_FAULT
Arg2: 807f6000
Arg3: 00000000
Arg4: 00000000

Мы видим, что случился BugCheck с кодом 0x7F, и первый аргумент указывает, что произошел double fault. Вообще, есть описание всех BugCheck, которые могут произойти в ядре - я всячески рекомендую проводить анализ, используя эту документацию.

Ладно, идем дальше - нам показали инструкцию, где произошел Double Fault:

nt!MiGetPhysicalAddress+0x8:
8129ca76 53              push    ebx

Сломались на относительно безобидной инструкции push - она могла сломаться если не смогла положить на стек содержимое регистра ebx - а это может быть когда страница памяти, в которой лежит этот кусок стека не присутствует в физической памяти. Нужно понимать, что когда какая-то инструкция обращается к какому-то виртуальному адресу, который отсутствует в физической памяти, то случается page fault - срабатывает обработчик этого fault, и он пытается загрузить нужную страницу в физическую память (с диска, или же создать пустую страницу - в данный момент это не важно). Но у обработчика page fault даже это сделать не получилось - он сломался еще раньше. Если быть точным, дело до него не дошло, потому что, процессор при обработке любого fault сначала сохраняет некоторый контекст на стек, в данном случае на наш кончившийся стек - у него это не получилось, и поэтому сработал double fault. У double fault немного другой механизм работы - он обычно выполняется на другом стеке, созданном заранее для обработчика double fault, как раз, чтобы не свалиться сразу в triple fault. Больше информации можно почерпнуть на osdev.


Но и это еще не всё, дальше в выводе команды analyze мы видим следующее:

STACKUSAGE_IMAGE: The module at base 0xFFFFFFFF824B0000 was blamed for the stack overflow. It is using 7780 bytes of stack.

Мы можем посмотреть список всех загруженных модулей с пощью команды lm, и увидеть, что по этому адресу загружен наш драйвер :)

Итак, на текущий момент мы установили, что произошло переполнение стека, и даже есть виновник, который отхватил 7.5KB стека, из 12KB максимально доступных в ядре для x86. Теперь мы можем посмотреть на сам call stack, чтобы понять, какая функция (или функции) отхватили такой кусок стека (перерисовал call stack ручками :)):

 # Child-SP Return   Call Site
23 830b559c 824e07d0 klfde!SomeFunc28
24 830b55c8 824e0842 klfde!SomeFunc27
25 830b562c 824e0aa8 klfde!SomeFunc26
26 830b565c 824e040f klfde!SomeFunc25
27 830b56c8 824ee063 klfde!SomeFunc24
28 830b56ec 824edec9 klfde!SomeFunc23
29 830b5730 825034df klfde!SomeFunc22
2a 830b57a4 825034df klfde!SomeFunc21
2b 830b5824 8268c4cc klfde!SomeFunc20
2c 830b58a4 8268c0f9 klfde!SomeFunc19
2d 830b5908 824ccbdd klfde!SomeFunc18
2e 830b597c 8256796a klfde!SomeFunc17
2f 830b5a58 825675e5 klfde!SomeFunc16
30 830b6124 825683dc klfde!SomeFunc15
31 830b6660 82577083 klfde!SomeFunc14
32 830b6714 8251d4f4 klfde!SomeFunc13
33 830b6874 825026f6 klfde!SomeFunc12
34 830b6b10 82503169 klfde!SomeFunc11
35 830b6d58 82500d9a klfde!SomeFunc10
36 830b6ea0 824d0d7a klfde!SomeFunc09
37 830b6ed0 824bfdfe klfde!SomeFunc08
38 830b6fa8 8250b6e0 klfde!SomeFunc07
39 830b7000 8250990c klfde!SomeFunc06
3a 830b7198 8250e3a0 klfde!SomeFunc05
3b 830b732c 824c453c klfde!SomeFunc04
3c 830b7368 824b30f2 klfde!SomeFunc03
3d 830b73b8 824b31a9 klfde!SomeFunc02
3e 830b73e0 86069fd7 klfde!SomeFunc01

Неплохая вложенность вызовов, видите здесь проблему - нет? Я пока тоже не вижу. Для того чтобы понять, кто сколько съел стека нужно взять значение ChildSp для текущего фрейма и вычесть из следующего. Вот, например, сколько стека потребила функция SomeFunc02:  830b73e0 - 830b73b8 = 0x28- всего 40 байт. Вот так, для каждой функции можно руками посчитать потребление стека.

Для того чтобы облегчить жизнь, в замечательном расширении mex есть команда t, которая выводит информацию о потоке, в частности, у нее есть параметр -fv, который позволяет посчитать, чтолько байт на стеке откушала та или иная функция:

0: kd> !mex.t -fv

 # Memory  Child-SP Return   Call Site
23    44 B 830b559c 824e07d0 klfde!SomeFunc28
24   100 B 830b55c8 824e0842 klfde!SomeFunc27
25    48 B 830b562c 824e0aa8 klfde!SomeFunc26
26   108 B 830b565c 824e040f klfde!SomeFunc25
27    36 B 830b56c8 824ee063 klfde!SomeFunc24
28    68 B 830b56ec 824edec9 klfde!SomeFunc23
29   116 B 830b5730 825034df klfde!SomeFunc22
2a   128 B 830b57a4 825034df klfde!SomeFunc21
2b   128 B 830b5824 8268c4cc klfde!SomeFunc20
2c   100 B 830b58a4 8268c0f9 klfde!SomeFunc19
2d   116 B 830b5908 824ccbdd klfde!SomeFunc18
2e   220 B 830b597c 8256796a klfde!SomeFunc17
2f  1,7 KB 830b5a58 825675e5 klfde!SomeFunc16
30 1,31 KB 830b6124 825683dc klfde!SomeFunc15
31   180 B 830b6660 82577083 klfde!SomeFunc14
32   352 B 830b6714 8251d4f4 klfde!SomeFunc13
33   668 B 830b6874 825026f6 klfde!SomeFunc12
34   584 B 830b6b10 82503169 klfde!SomeFunc11
35   328 B 830b6d58 82500d9a klfde!SomeFunc10
36    48 B 830b6ea0 824d0d7a klfde!SomeFunc09
37   216 B 830b6ed0 824bfdfe klfde!SomeFunc08
38    88 B 830b6fa8 8250b6e0 klfde!SomeFunc07
39   408 B 830b7000 8250990c klfde!SomeFunc06
3a   404 B 830b7198 8250e3a0 klfde!SomeFunc05
3b    60 B 830b732c 824c453c klfde!SomeFunc04
3c    80 B 830b7368 824b30f2 klfde!SomeFunc03
3d    40 B 830b73b8 824b31a9 klfde!SomeFunc02
3e    32 B 830b73e0 86069fd7 klfde!SomeFunc01


Module      Byte Count Stack Usage
=========== ========== ===========
klfde             7780      7,6 KB
nt                3292     3,21 KB
storport           500       500 B
CLASSPNP           360       360 B
partmgr            232       232 B
hal                224       224 B
VerifierExt         60        60 B
lsi_sas             56        56 B

Total Stack Usage: 12,21 KB

Вывод этой команды также довольно однозначно нам говорит, что больше всех стека съел klfde, и также указал полное потребление стека (что согласуется с лимитом стека в ядрве для x86). Также теперь видно, что основные виновники - функции SomeFunc15 и SomeFunc16. После этого, найти и исправить потребление стека в нужных функция остается делом техники - в нашем случае, на стеке выделялись довольно жирные структуры, порядка 500 байт каждая.

Пару слов об общем потреблении стека - вообще цифра 7.6KB - это очень много, но в данном случае проблема была на дебажном билде драйвера, а там компилятор генерирует код, который очень расточительно пользует стек, в конце статьи я приведу пример потребления стека в различных режимах сборки.


Переполнение user-mode стека

Здесь все гораздо проще - во-первых, размер стека по умолчанию равен 1мб. Для того чтобы его переполнить нужно сделать не менее 1000 вызовов функции с 1000 байт во фрейме каждой функции, поэтому обычно виновата рекурсия. Во-вторых, когда случается page fault при науступании на отсутствующую страницу в user-mode, то этот page fault сначала обрабатывается в ядре, поэтому весь контекст для обработки page fault складывается на ядерный стек, а не на кончившийся user-mode стек, поэтому double fault не происходит - и падает только наше приложение.

Вообще говоря, про user-mode стек тоже можно много чего рассказать - там и guard page, и _chkstk (которая тесно связана с guard page) и много чего другого - в общем тема для целой статьи.


Потребление стека Release/Debug

Итак, как обещал - потребление стека в различных режимах компиляции. Будем рассматривать такой пример:

#include <cstdio>

struct Bar {
    void* data[32];
    
    __declspec(noinline)
    Bar() {
        ::printf("%s\n", "ctor");
    }
    
    __declspec(noinline)
    ~Bar() {
        ::printf("%s\n", "dtor");
    }
};
static_assert(sizeof(Bar) == 128, "");


__declspec(noinline)
void Baz() {
    __debugbreak();
}

__declspec(noinline)
void Foo() {
    {
        Bar b1;
    }
    
    {
        Bar b2;
    }
    
    {
        Bar b3;
    }
    
    Baz();
}

int main() {
    Foo();
}

Итак, в дебажном билде (cl /Od /Fd:main.pdb main.cpp /link /debug) потребление стека следующее:

# Memory Child-SP Return   Call Site
0        006ffa7c 0125a9ca main!Baz+0x3                      
392 B 006ffa84 0125a9d8 main!Foo+0x4a                     
2    8 B 006ffc0c 01256a70 main!main+0x8                     
                     


Мы видим, что функция Foo использовала 392 байта памяти, хотя могла намного меньше.
Дело все в том, что в дебажном билде компилятор не учитывает область видимости объектов и кладет их каждый раз на новое место, что подтверждается дизассемблером:

main!Foo:
0125a980 55              push    ebp
0125a981 8bec            mov     ebp,esp
0125a983 81ec80010000    sub     esp,180h
0125a989 8d4d80          lea     ecx,[ebp-80h]
0125a98c e8ec6bffff      call    main!ILT+1400(??0BarQAEXZ) (0125157d)
0125a991 8d4d80          lea     ecx,[ebp-80h]
0125a994 e81392ffff      call    main!ILT+11175(??1BarQAEXZ) (01253bac)
0125a999 8d8d00ffffff    lea     ecx,[ebp-100h]
0125a99f e8d96bffff      call    main!ILT+1400(??0BarQAEXZ) (0125157d)
0125a9a4 8d8d00ffffff    lea     ecx,[ebp-100h]
0125a9aa e8fd91ffff      call    main!ILT+11175(??1BarQAEXZ) (01253bac)
0125a9af 8d8d80feffff    lea     ecx,[ebp-180h]
0125a9b5 e8c36bffff      call    main!ILT+1400(??0BarQAEXZ) (0125157d)
0125a9ba 8d8d80feffff    lea     ecx,[ebp-180h]
0125a9c0 e8e791ffff      call    main!ILT+11175(??1BarQAEXZ) (01253bac)
0125a9c5 e8d891ffff      call    main!ILT+11165(?BazYAXXZ) (01253ba2)
0125a9ca 8be5            mov     esp,ebp


Итак, мы видим, что компилятор отступил 0x180 для стека - что равно 3 * sizeof(Bar), затем, загрузил для каждого объекта свой this в ECX, и позвал конструктор, а затем деструктор.

Тоже самое, но в релизном билде (cl /O2 /Oy- /Fd:main.pdb main.cpp /link /debug):

# Memory Child-SP Return   Call Site
0        005cfac4 010067fe main!Baz                          
136 B 005cfac8 01006865 main!Foo+0x3e                     
2    4 B 005cfb50 01006a9b main!main+0x5                     
3                    


Дизассемблер функции Foo показывает нам, что стек был переиспользован.
main!Foo:
010067c0 55              push    ebp
010067c1 8bec            mov     ebp,esp
010067c3 81ec80000000    sub     esp,80h
010067c9 8d4d80          lea     ecx,[ebp-80h]
010067cc e8a7adffff      call    main!ILT+1395(??0BarQAEXZ) (01001578)
010067d1 8d4d80          lea     ecx,[ebp-80h]
010067d4 e8a2b9ffff      call    main!ILT+4470(??1BarQAEXZ) (0100217b)
010067d9 8d4d80          lea     ecx,[ebp-80h]
010067dc e897adffff      call    main!ILT+1395(??0BarQAEXZ) (01001578)
010067e1 8d4d80          lea     ecx,[ebp-80h]
010067e4 e892b9ffff      call    main!ILT+4470(??1BarQAEXZ) (0100217b)
010067e9 8d4d80          lea     ecx,[ebp-80h]
010067ec e887adffff      call    main!ILT+1395(??0BarQAEXZ) (01001578)
010067f1 8d4d80          lea     ecx,[ebp-80h]
010067f4 e882b9ffff      call    main!ILT+4470(??1BarQAEXZ) (0100217b)
010067f9 e85fafffff      call    main!ILT+1880(?BazYAXXZ) (0100175d)



Итого

Мы посмотрели, как анализировать проблемы переполнения стека, как себя ведет винда в этом случае. Рассмотрели команды и расширения windbg, которые облегчают и ускоряют анализ проблемы. Также немного поговорили о потреблении стека.

Кстати, в Visual Studio есть несколько статических анализаторов (в т.ч. и для Kernel Mode проектов). Я раньше запускал какой-то анализатор, и у него было правило для анализа потребления стека в ядре, но, к сожалению, сходу я его не нашел - в общем, это тоже тема для дальнейшего исследования.

Комментариев нет:

Отправить комментарий