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

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

Очередное тестирование в 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 секундами, и этого было вполне достаточно для своевременной вычистки буферов при данной нагрузке, с большим запасом. Но диагностика и поиск неисправности отняли немалое время, главным образом из-за некорректной статистики в логах.

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

У кого были интересные случаи в практике — пишите!