Pull to refresh

Утечки памяти в программах на С/С++ — история нескольких багов

Reading time 11 min
Views 9.8K
Истории нескольких проблем, связанных с утечками памяти. Большинство таких проблем являются достаточно тривиальными, легко воспроизводятся, легко обнаруживаются соответствуюшим инструментарием, и исправляются. Но, временами, проблемы оказываются необычными, и требуют необычного подхода или решения…

Кодопотерятор памяти

Очередное тестирование в QA выявило небольшую постоянную утечку памяти под нагрузкой в новой версии продукта. Воспроизведение не представляло проблемы, но первоначальный прогон программы под Valgrind не выявил утечек.

После некоторых раздумий была включена опция --leak-check=full и Valgrind начал отчитываться об утечках. Но среди ожидаемых утечек разного рода статических переменных, зачастую осознанно не освобождаемых, не находилось ничего, напоминающего утечку. Обычно при прогоне нескольких тысяч итераций несложно выделить аналогичное количество потерянных блоков памяти выделенных malloc-ом. В данном-же случае утечка на 10,000 запросов к серверу была минимальна.

После анализа стеков выделений памяти и отсева ожидаемых случаев, остался только один кандидат, который отвечал за несколько десятков потерянных блоков — количество, абсолютно не ассоциирующееся с 10,000 запросами. Но этому нашлось объяснение — выделения памяти происходили в классе строки STL, который активно использует memory pool для уменьшения количества выделений памяти. Поэтому вместо 10,000 потерянных блоков памяти Valgrind отчитывался о 40+. Стек вызовов выглядел примерно так:

==15882== 76,400 bytes in 8 blocks are definitely lost in loss record 2 of 3
==15882==      at 0x401B007: operator new(unsigned int) (vg_replace_malloc.c:214)
==15882==      by 0x40A40F0: std::__default_alloc_template<true, 0>::_S_chunk_alloc(unsigned int, int&) (in /usr/lib/libstdc++.so.5.0.3)
==15882==      by 0x40A3FFC: std::__default_alloc_template<true, 0>::_S_refill(unsigned int) (in /usr/lib/libstdc++.so.5.0.3)
==15882==      by 0x40A3B6B: std::__default_alloc_template<true, 0>::allocate(unsigned int) (in /usr/lib/libstdc++.so.5.0.3)
==15882==      by 0x40A9B67: std::string::_Rep::_S_create(unsigned int, std::allocator<char> const&) (in /usr/lib/libstdc++.so.5.0.3)
==15882==      by 0x40A9C98: std::string::_Rep::_M_clone(std::allocator<char> const&, unsigned int) (in /usr/lib/libstdc++.so.5.0.3)
==15882==      by 0x40A7A05: std::string::reserve(unsigned int) (in /usr/lib/libstdc++.so.5.0.3)
==15882==      by 0x8049826: std::basic_string<char, std::char_traits<char>, std::allocator<char> > std::operator+<char,
std::char_traits<char>, std::allocator<char> >(char const*, std::basic_string<char, std::char_traits<char>,
std::allocator<char> > const&) (basic_string.tcc:619)
==15882==      by 0x804956A: A::A(A const&) (class_a.cpp:20)
==15882==      by 0x80491BC: foo(int) (test.cpp:23)
==15882==      by 0x80492EA: main (test.cpp:32)


Вроде-бы источник утечки памяти был найден, но код выглядел абсолютно невинно — вызов функции с передачей ей временной копии объекта:

doSomething( condition ? Object( params ) : getObject() );

Мы были уже точно уверены, что память теряется в этой строке, и начали смотреть на код, генерируемый компилятором для данной строки. Вроде-бы все было на месте — вызов “basic_string::length()”, вызов конструктора класса параметра для одной ветви условия, вызов “Parent::getB()” и конструктора копирования для другой ветви, вызов собственно функции “A::create”, освобождения временных объектов — всё, кроме вызова деструктора временной копии класса — созданной на стеке, но содержащей внутри копию строки, которая и не освобождалась в результате!

110:   return A::create(b1, b2, s.length() > 0 ? B(s) : getB());
  13d4:     83 ec 0c                   sub    $0xc,%esp
  13d7:     8d 45 d8                   lea    0xffffffd8(%ebp),%eax
  13da:     50                         push   %eax
  13db:     e8 fc ff ff ff             call   std::basic_string<wchar_t>::length() const <<=========
  13e0:     83 c4 10                   add    $0x10,%esp
  13e3:     85 c0                      test   %eax,%eax
  13e5:     74 18                      je     13ff <A::create+0x341>
  13e7:     83 ec 08                   sub    $0x8,%esp
  13ea:     8d 45 d8                   lea    0xffffffd8(%ebp),%eax
  13ed:     50                         push   %eax
  13ee:     8d 85 f8 fe ff ff          lea    0xfffffef8(%ebp),%eax
  13f4:     50                         push   %eax
  13f5:     e8 fc ff ff ff             call   B::B( std::basic_string<wchar_t> const & ) <<=========
  13fa:     83 c4 10                   add    $0x10,%esp
  13fd:     eb 21                      jmp    1420 <A::create+0x362>
  13ff:     83 ec 08                   sub    $0x8,%esp
  1402:     83 ec 04                   sub    $0x4,%esp
  1405:     ff 75 0c                   pushl  0xc(%ebp)
  1408:     e8 fc ff ff ff             call   Parent::getB() <<=========
  140d:     83 c4 08                   add    $0x8,%esp
  1410:     50                         push   %eax
  1411:     8d 85 f8 fe ff ff          lea    0xfffffef8(%ebp),%eax
  1417:     50                         push   %eax
  1418:     e8 fc ff ff ff             call   B::B( B const & ) <<=========
  141d:     83 c4 10                   add    $0x10,%esp
  1420:     83 ec 0c                   sub    $0xc,%esp
  1423:     8d 85 f8 fe ff ff          lea    0xfffffef8(%ebp),%eax
  1429:     50                         push   %eax
  142a:     0f b6 45 f6                movzbl 0xfffffff6(%ebp),%eax
  142e:     50                         push   %eax
  142f:     0f b6 45 f7                movzbl 0xfffffff7(%ebp),%eax
  1433:     50                         push   %eax
  1434:     ff 75 0c                   pushl  0xc(%ebp)
  1437:     ff 75 08                   pushl  0x8(%ebp)
  143a:     e8 fc ff ff ff             call   A::create(bool, bool, B) <<=========
  143f:     83 c4 1c                   add    $0x1c,%esp
  1442:     83 ec 0c                   sub    $0xc,%esp
  1445:     8d 85 68 ff ff ff          lea    0xffffff68(%ebp),%eax
  144b:     50                         push   %eax
  144c:     e8 fc ff ff ff             call   BS<100, char>::~BS()
  1451:     83 c4 10                   add    $0x10,%esp
  1454:     83 ec 0c                   sub    $0xc,%esp
  1457:     8d 45 d8                   lea    0xffffffd8(%ebp),%eax
  145a:     50                         push   %eax
  145b:     e8 fc ff ff ff             call   std::basic_string<wchar_t>::~basic_string()
  1460:     83 c4 10                   add    $0x10,%esp
  1463:     eb 55                      jmp    14ba <A::create+0x3fc>
  1465:     89 85 f0 fe ff ff          mov    %eax,0xfffffef0(%ebp)
  146b:     8b b5 f0 fe ff ff          mov    0xfffffef0(%ebp),%esi
  1471:     83 ec 0c                   sub    $0xc,%esp
  1474:     8d 85 68 ff ff ff          lea    0xffffff68(%ebp),%eax
  147a:     50                         push   %eax
  147b:     e8 fc ff ff ff             call   BS<100, char>::~BS()
  1480:     83 c4 10                   add    $0x10,%esp
  1483:     89 b5 f0 fe ff ff          mov    %esi,0xfffffef0(%ebp)
  1489:     eb 06                      jmp    1491 <A::create+0x3d3>
  148b:     89 85 f0 fe ff ff          mov    %eax,0xfffffef0(%ebp)
  1491:     8b b5 f0 fe ff ff          mov    0xfffffef0(%ebp),%esi
  1497:     83 ec 0c                   sub    $0xc,%esp
  149a:     8d 45 d8                   lea    0xffffffd8(%ebp),%eax
  149d:     50                         push   %eax
  149e:     e8 fc ff ff ff             call   std::basic_string<wchar_t>::~basic_string()
  14a3:     83 c4 10                   add    $0x10,%esp
  14a6:     89 b5 f0 fe ff ff          mov    %esi,0xfffffef0(%ebp)
  14ac:     83 ec 0c                   sub    $0xc,%esp
  14af:     ff b5 f0 fe ff ff          pushl  0xfffffef0(%ebp)
  14b5:     e8 fc ff ff ff             call   _Unwind_Resume


Так и не найдя вызов деструктора к коде, начали искать похожие проблемы, и практически сразу нашли "gcc 3.2 bug 9946 — object destructor not called, potentially causing a memory leak".

Проблема была в генерации кода для оператора “?:”, и решалась либо обновлением компилятора, либо косметическим изменением оператора “?:” на простой if().

// Есть функция, возвращающая константную ссылку на объект
const Object & getObject();

// Другая функция принимает объект по значению
void doSomething( Object obj );

// При вызове подобном нижеследующему, может произойти утечка памяти.
// Автоматически созданный на стеке экземпляр объекта может быть не освобожден,
// приводя к утечке памяти если экземпляр содержал динамически выделенную память.
doSomething( condition ? Object( params ) : getObject() );


Простая тестовая программа выводила следующее (обратите внимание на количество созданных и освобожденных экземпляров класса А):

main() start
A::A( 'on stack' )
B::B()
A::A( 'static instance' )
A::A( 'copy of static instance' )
B::boo()
B::~B()
A::~A( 'on stack' )
main() end
A::~A( 'static instance' )
Class A created 3 times and destroyed 2 times
Class B created 1 times and destroyed 1 times


Проблема происходила только при генерации 32-битного кода в gcc 3.2.3, и не происходила в 64 битном коде, или коде сгенерированном более поздними версиями компилятора.

Я — не я, и память не моя

Одно время я поддерживал и дорабатывал программу для сбора данных и передачи их на сервер. Эта программа работала на добром десятке платформ, в том числе на Linux. Так как программа была коммерческая, то компилировалась она компилятором, соответствующим минимальной поддерживаемой версии Linux, в нашем случае gcc 3.3.x, и предоставлялись исполняемые файлы.

В один прекрасный момент, в нашем отделе QA зарегистрировали и даже сумели воспроизвести (во время длительного, несколько дней, теста под большой нагрузкой) падение программы по причине нехватки памяти — процесс съедал 3GB памяти и благополучно падал, создавая core dump аналогичного объема. Причем взрывной рост использования памяти происходил буквально за 10-15 минут до печального конца, и в это время нагрузка процессора была порядка 12% (на сервере было 4 двух-ядерных процессора, так что один поток, крутящийся в цикле, как раз и должен использовать 12.5%).

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

(gdb) where
#0  0xffffe410 in __kernel_vsyscall ()
#1  0xb7dbd8d0 in raise () from /lib/libc.so.6
#2  0xb7dbeff3 in abort () from /lib/libc.so.6
#3  0xb7f86da5 in dlopen () from /usr/lib/libstdc++.so.5
#4  0xb7f86de2 in std::terminate () from /usr/lib/libstdc++.so.5
#5  0xb7f85e89 in __cxa_allocate_exception () from /usr/lib/libstdc++.so.5
#6  0xb78f7f07 in Uuid::Uuid () from .../lib32/libourlibrary.so
#7  0xb782409d in ...


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

Поиск похожих стеков вызовов не дал практически никаких результатов, и ситуация была тупиковая. Надо было как-то обнаружить причину утечки памяти без использования отладчика.

В одной реализации библиотеки выделения памяти для С++, с которой я сталкивался, каждый блок, выделяемый под новый экземпляр класса, в отладочной версии библиотеки помечался строкой, содержащей имя этого класса. Такой способ позволял легко определит по core dump-y, какие объекты того или иного типа были выделены. Я попробовал поискать строки, содержащиеся в core dump файле, запустив сначала программу «strings», а затем отсортировав с «sort».

Любопытно, но обнаружилось, что файл содержит 32,123,751 строк вида «++CCUNG0o» — только эти строки занимали около 275 MB в файле размером 3 GB. При поиске этих строк в файле выяснилось, что каждая такая сигнатура начинала блок размером 96 байт (96b * 32,000,000 = 3Gb!!!)

Блоки начинались инвертированной строкой «++CCUNG0o» с нулем в начале (так как она инвертированная), и отличались только парой из четырех байт в разных местах, образуя, по-видимому, связанный список.

0x248b818: 0x00 0x2b 0x2b 0x43 0x43 0x55 0x4e 0x47 <<== строка «++CCUNG0o»
0x248b820: 0x30 0x6f 0xf8 0xb7 0x00 0x00 0x00 0x00
0x248b828: 0x6c 0xa8 0x78 0xb7 0x00 0x00 0x00 0x00
0x248b830: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x248b838: 0xa8 0x0e 0xd3 0xb7 0x3c 0xa2 0xfa 0xb7
0x248b840: 0xe8 0xae 0x82 0xb7 0x65 0x00 0x00 0x00
0x248b848: 0xc0 0x0e 0xd3 0xb7 0x38 0x9c 0xc8 0xb7
0x248b850: 0xf4 0x9b 0x04 0x08 0xe4 0x9c 0x04 0x08
0x248b858: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x248b860: 0x03 0x00 0x00 0x00 0xbe 0x80 0x79 0xb7
0x248b868: 0x58 0x80 0x79 0xb7 0x54 0xa9 0x78 0xb7
0x248b870: 0x98 0xb8 0x48 0x02 0x00 0x00 0x00 0x00

0x248b878: 0x00 0x2b 0x2b 0x43 0x43 0x55 0x4e 0x47 <<== строка «++CCUNG0o»
0x248b880: 0x30 0x6f 0xf8 0xb7 0x00 0x00 0x00 0x00
0x248b888: 0x6c 0xa8 0x78 0xb7 0x00 0x00 0x00 0x00
0x248b890: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x248b898: 0xa8 0x0e 0xd3 0xb7 0x3c 0xa2 0xfa 0xb7
0x248b8a0: 0xff 0xff 0xff 0xff 0x65 0x00 0x00 0x00
0x248b8a8: 0xc0 0x0e 0xd3 0xb7 0x38 0x9c 0xc8 0xb7
0x248b8b0: 0xf4 0x9b 0x04 0x08 0xe4 0x9c 0x04 0x08
0x248b8b8: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x248b8c0: 0x03 0x00 0x00 0x00 0xbe 0x80 0x79 0xb7
0x248b8c8: 0x58 0x80 0x79 0xb7 0x54 0xa9 0x78 0xb7
0x248b8d0: 0xf8 0xb8 0x48 0x02 0x00 0x00 0x00 0x00


Поиск такой строки в Интернете поначалу не принес каких-либо полезных результатов, но потом обнаружилась одна ссылка на http://www.opensource.apple.com/ (к сожалению, уже не рабочая) со следующим фрагментом:

// This is the exception class we report -- "GNUCC++\0".
const _Unwind_Exception_Class __gxx_exception_class
= ((((((((_Unwind_Exception_Class) 'G'
        << 8 | (_Unwind_Exception_Class) 'N')
       << 8 | (_Unwind_Exception_Class) 'U')
      << 8 | (_Unwind_Exception_Class) 'C')
     << 8 | (_Unwind_Exception_Class) 'C')
    << 8 | (_Unwind_Exception_Class) '+')
    << 8 | (_Unwind_Exception_Class) '+')
  << 8 | (_Unwind_Exception_Class) '\0');


Тогда я вернулся к стекам вызовов других потоков, и обнаружил очень подозрительный поток, явно работающий в цикле в момент падения — и этот цикл тоже занимается обработкой исключения:

(gdb) thread 20
[Switching to thread 20 (process 27635)]#0  0xb7e87921 in dl_iterate_phdr () from /lib/libc.so.6
(gdb) where
#0  0xb7e87921 in dl_iterate_phdr () from /lib/libc.so.6
#1  0x0804e837 in _Unwind_Find_FDE (pc=0xb782409c, bases=0xb70209b4) at ../../gcc/unwind-dw2-fde-glibc.c:283
#2  0x0804c950 in uw_frame_state_for (context=0xb7020960, fs=0xb7020860) at ../../gcc/unwind-dw2.c:903
#3  0x0804cfbf in _Unwind_RaiseException_Phase2 (exc=0xbfde3f38, context=0xb7020960) at ../../gcc/unwind.inc:43
#4  0x0804d397 in _Unwind_Resume (exc=0xbfde3f38) at ../../gcc/unwind.inc:220
#5  0xb78f82b0 in Uuid::Uuid () from /home/'work/lib32/libourlibrary.so
#6  0xb782409d in ...


После этого мы начали смотреть внимательнее на исходный код, где вызывалось исключение, и предположили, что проблема лежит в операторе placement new, который использовался в данном участке кода. Простой тест подтвердил предположение — создание исключения в конструкторе объекта, вызванном из оператора placement new, приводил к бесконечному циклу и взрывной утечке памяти. Тест был простой — симуляция исключительной ситуации в проблемном участке кода, но к сожалению, совсем не простой в отрыве от контекста нашего приложения — небольшие тестовые программы проблему не воспроизводили. Так же оказалось, что данная проблема присутствует только в версии компилятора, которую мы использовали, то есть в gcc 3.4 проблема отсутствовала. На радостях, что конкретная проблема, уже обошедшаяся в копеечку, решена, дальнейшее расследование свернули.

Не совсем утечка

Однажды, после обновления программного продукта, предварительное тестирование у клиента обнаружило утечку памяти, не происходившую ранее.

Программа работала под Solaris, под нагрузкой, и использование памяти росло резкими скачками по 10-100 MB, при этом достаточно редко — временами раз в 2-3 дня, а временами 2-3 раза в день. Рано или поздно память, используемая процессом, вырастала до 2+ GB. При этом даже при снижении нагрузки до нуля, используемая память (значения RSS и VSS) никогда не уменьшалась.

Непосредственный доступ к серверам получить было нельзя (для настройки libumem, к примеру), а воспроизвести проблему в QA не получалось. Хорошо и то, что удалось получить обрезанный core dump файл — снимок памяти процесса. Но анализ core dump файла практически ничего не дал — стек вызовов показывал падение при выделении памяти из-за нехватки оной. При этом бОльшая часть памяти не использовалась — почти весь core dump файл был занят пустыми страницами по 4 KB, забитыми нулями.

Ситуация была странная, но постепенно, методом исключения различных компонент системы и вдумчивого анализа лог-файлов, была восстановлена картина происходящих событий.

При обновлении системы, одна из клиентских программ перестала посылать часть сообщений, предназначенных для мониторинга системы. По случайности, отсутствующие сообщения сигнализировали о закрытии транзакций, и они должны были чистить внутренние буферы. Соответственно, при повышении нагрузки, начинали накапливаться буферизованные сообщения, ждущие пары. По случайному совпадению, в данном случае сообщения были нетипично большими (десятки килобайт вместо сотен байт), и количество клиентских процессов было относительно велико (несколько десятков вместо обычных 2-5). Но на самом деле все эти параметры великолепно укладывались в ограничения, поддерживаемые системой (при условии нормального функционирования). И, хотя программа не ограничивала размер внутренних буферов, но она поддерживала механизм для очистки “потерянных” транзакций — все неполные сообщения старше 10 минут автоматически удалялись. И как раз этот счетчик всегда показывал 0 из-за ошибки — механизм был предназначен для практически невероятной исключительной ситуации, практически никогда не задействован, и недостаточно проверен. Сама очистка исправно работала, но была недостаточно эффективна из-за большой нагрузки на память, вызванной большим количеством клиентов и большим размером нестандартных сообщений. А диагностика проблемы оказалась сильно затруднена из-за неисправного счетчика в статистике.

Почему-же память не возвращалась при снижении нагрузки? Очень просто — стандартный диспетчер памяти процесса в Solaris только увеличивает адресное пространство процесса, и резервирует освобождаемую процессом память для повторного использования, оставляя страницы «занятыми» процессом с точки зрения стороннего наблюдателя.

В нашем случае, одиночные пики активности проблемных клиентов приводили к периодическим большим выделениям памяти, в большинстве случаев незаметных, так как не превышался предыдущий максимум. И только если последний максимум превышался, получалась очередная ступенька, которая уже никогда не уменьшалась. Через 10 минут после пика вся память освобождалась, но снаружи этого было не видно, только снимок памяти показывал, что большая часть памяти забита нулями и не используется.

Решение было простым даже до исправления проблемных клиентов и защиты от переполнения буферов — возраст “старых” транзакций был временно ограничен 30 секундами, и этого было вполне достаточно для своевременной вычистки буферов при данной нагрузке, с большим запасом. Но диагностика и поиск неисправности отняли немалое время, главным образом из-за некорректной статистики в логах.

Вместо эпилога

У кого были интересные случаи в практике — пишите!
Tags:
Hubs:
+61
Comments 40
Comments Comments 40

Articles