Избегайте утечки в тривиальном использовании Boost Log

Я получаю отчеты об утечках valgrind из приложения на стороне сервера, использующего boostlog, который распространяется с boost 1.56. отчет valgrind:

==8021== 37 088 байт в 1 159 блоках определенно потеряны в записи о потерях 1 613 из 1 642

==8021== по адресу 0x4A05588: memalign (vg_replace_malloc.c:727)

==8021== по 0x3FDA61118F: tls_get_addr_tail (в /lib64/ld-2.12.so)

==8021== по 0x3FDA61165F: __tls_get_addr (в /lib64/ld-2.12.so)

==8021== по 0x3FE6ABBDCB: __cxa_get_globals (в /usr/lib64/libstdc++.so.6.0.13)

==8021== от 0x730C528: boost::log::v2_mt_posix::aux::unhandled_exception_count() (в /opt/sesteksdk/lib/libboost_log.so.1.56.0)

==8021== by 0x5D54D1F: sestek::mrcp::audio::recognition::AsynchronousRecognizer::Notify(sestek::voice::recognition::IRecognizerNotification const*) (record_ostream.hpp:259)

эта утечка исходит из такой простой строки, как:
LOGGER(debug)<< _chanProp->GetId() << " got recognition ended notification from recognizer";

Мы получаем 5 таких утечек только за один короткий тестовый прогон.

мы используем бэкенд текстового файла, с синхронным приемником, включена автоматическая очистка. В основном:

void InitializeFileLog(const std::string & logDir)
    {   
        boost::shared_ptr< logging::core > loggingCore = logging::core::get();


        loggingCore->add_global_attribute("TimeStamp", attrs::local_clock());

        string logPath = logDir + "/gvzmrcpsr_%N.txt";

        boost::shared_ptr< sinks::text_file_backend > backend =
            boost::make_shared< sinks::text_file_backend >(
                // file name pattern
                keywords::file_name = logPath,
                // rotate the file upon reaching 5 MiB size...
                keywords::rotation_size = 5 * 1024 * 1024,
                // ...or at midnight, whichever comes first
                keywords::time_based_rotation = sinks::file::rotation_at_time_point(0, 0, 0)                    
            );

        backend->auto_flush(true);

        // Wrap it into the frontend and register in the core.
        // The backend requires synchronization in the frontend.
        typedef sinks::synchronous_sink< sinks::text_file_backend > sink_t;
        boost::shared_ptr< sink_t > sink = boost::make_shared< sink_t>(backend);

        loggingCore->add_sink(sink);


        sink->flush();
        sink->set_formatter
            (
            expr::stream
            << expr::attr< boost::posix_time::ptime >("TimeStamp")
            << " : [" << expr::attr< sestek::log::LogLevel >("Severity")
            << "] " << expr::smessage
            );

        backend->set_file_collector(sinks::file::make_collector(
            // rotated logs will be moved here
            keywords::target = logDir + "/old_mrcpsr_plugin_logs",
            // oldest log files will be removed if the total size reaches 100 MiB...
            keywords::max_size = 100 * 1024 * 1024,
            // ...or the free space in the target directory comes down to 50 MiB
            keywords::min_free_space = 50 * 1024 * 1024
        ));

        try
        {
            backend->scan_for_files(sinks::file::scan_all);
        }
        catch(std::exception & )
        {
            //LOGGER(sestek::log::fatal) << "exception during scanning : " << e.what();

        }

    }

Система скомпилирована и запущена на Centos 6.6 с использованием devtoolkit2.0. версия gcc 4.8.2.

Так есть ли проблема в нашем использовании журнала повышения? Или действительно ли в журнале повышения есть такая проблема (ы). Я думаю, что наше использование можно считать тривиальным, мы просто запускаем приведенный выше код конфигурации во время запуска.

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


person Mert    schedule 04.02.2015    source источник
comment
Я думаю, что Boost Log создает какой-то начальный объект, когда он инициализирует себя, объект, который жив на протяжении всей жизни процесса. Это означает, что он будет считаться ложным срабатыванием при проверке на наличие утечек, потому что он будет выпущен, когда процесс завершится.   -  person Some programmer dude    schedule 04.02.2015
comment
valgrind сообщает об этих утечках как о потерянных. Вид, который вы объясните, будет сообщен как возможно потерянный. За один прогон я получаю пять таких отчетов, поэтому это не может быть однократная инициализация.   -  person Mert    schedule 04.02.2015
comment
Вы используете треды? Сколько потоков запущено? Когда и где в потоках (если вы их используете) находится заявление об утечке (первое ведение журнала? последнее ведение журнала? где-то посередине?) Всегда ли утечка происходит в одном и том же утверждении ведения журнала?   -  person Some programmer dude    schedule 04.02.2015
comment
Программа интенсивно использует потоки. Каждый запрос от клиентов запускает несколько потоков. (мы так часто используем многопоточность, что на самом деле планируем использовать пул потоков в краткосрочной перспективе)   -  person Mert    schedule 04.02.2015
comment
Я не проверял, не протекает ли первый лог. Но я видел течи из разных мест. Я проверю это.   -  person Mert    schedule 04.02.2015
comment
Первый лог не течет, это не последний лог. Но я заметил, что каждая утечка произошла из другого потока. Таким образом, это вполне может означать, что журнал boost выполняет инициализацию для каждого потока, из которого он использовался, и когда этот поток выходит, происходит эта утечка. Еще одна подсказка может заключаться в том, что отчет Valgrind содержит вызовы, связанные с tls, в трассировке стека.   -  person Mert    schedule 04.02.2015
comment
Я сделал больше тестов относительно использования потока. Я не смог найти соотношение между количеством потоков и количеством утекших блоков, но утечки увеличиваются с увеличением количества потоков. мои тесты: 0 запросов вызывают утечку 3 блоков. 1 запрос вызывает утечку 3 блоков. 50 запросов вызывают утечку 47 блоков (3 разных места в коде).   -  person Mert    schedule 04.02.2015
comment
Я понимаю, что если мы не ограничим количество используемых нами потоков (предполагая, что каждый используемый нами поток в какой-то момент ведет журнал), решение будет трудным или почти невозможным. Если это так, я думаю, что использование пула потоков вместо создания новых потоков каждый раз должно быть решением.   -  person Mert    schedule 04.02.2015
comment
Спасение полезной части моей попытки полезности: Пришло время сделать SSCCE и обратиться к документации по правильным последовательностям завершения работы< /я>. На самом деле, если создать SSCCE, я с удовольствием сделаю остальные части (я тоже научусь). Как это бывает, стартовые вложения для меня слишком велики.   -  person sehe    schedule 04.02.2015
comment
Редко бывает, чтобы что-то хорошее получалось от постоянного создания/завершения/уничтожения потоков во время работы приложения. Используйте пулы потоков или потоки времени жизни приложения. Обменивайтесь сообщениями/работами/задачами через очереди. Не используйте создание/присоединение. Не собирайте 200 долларов.   -  person Martin James    schedule 04.02.2015
comment
Я убежден, что если мы изменим наш подход к многопоточности, чтобы использовать пул потоков, эта проблема исчезнет. Может ли кто-нибудь резюмировать, что системы ведения журналов обычно имеют такое поведение, поэтому я могу принять это как ответ. @sehe Я думаю, что это такой общий случай, что любой работающий код журнала повышения будет вести себя так же. Так что я сомневаюсь, что он заслуживает SSCCE. Теоретического ответа было достаточно. Спасибо за вашу помощь кстати.   -  person Mert    schedule 05.02.2015
comment
Я добавил пул потоков в систему. Течи действительно исчезли. Я жду, что кто-то обобщит ответы, иначе я отвечу на него сам и закрою его.   -  person Mert    schedule 09.02.2015


Ответы (3)


Boost Log, как и многие другие библиотеки ведения журналов, использует tls внутри. Для системы ведения журнала сложно (а иногда кажется невозможным) очищать переменные tls, когда поток завершается. Boost сталкивается с теми же трудностями.

Для долго работающего приложения, содержащего код ведения журнала, отсоединение многих потоков и их завершение по завершении их задачи нецелесообразно. Лучшим подходом в многозадачной системе является использование пула потоков вместо того, чтобы каждый раз запускать новые потоки.

Я преобразовал приложение для использования пула потоков, и утечки в вопросе исчезли. Переменные TLS все еще существуют, но поскольку теперь потоки используются повторно, переменные tls также повторно используются соответствующими потоками.

person Mert    schedule 12.02.2015

Я не очень понимаю вопрос. Вы показываете доказательства утечки и спрашиваете «есть ли утечка». Ну да. Это вряд ли удивительно. Регистраторы используют локальные "одиночки" потока. В зависимости от того, как вы организовали свои потоки, будет возможно / почти невозможно правильно их разорвать.

Пришло время выполнить SSCCE и ознакомиться с документацией по правильной последовательности завершения работы.

Примечание

Отключение регистраторов общеизвестно сложно. Вам нужно иметь дело с вероятностью того, что что-то должно войти в журнал во время выключения (запах дизайна); Хуже того, разные приемники могут зависеть друг от друга и препятствовать завершению работы в любом конкретном порядке).

Довольно много фреймворков просто оставляют ОС для очистки.

PS Ничто не указывает на повторяющуюся утечку, так как это похоже на утечку в потоке.

person sehe    schedule 04.02.2015
comment
Вопрос был таков: есть ли проблема в нашем использовании журнала повышения? Или действительно ли в журнале повышения есть такая проблема (ы). Я не спрашивал, течет ли он?. Вы вопрос внимательно прочитали? - person Mert; 04.02.2015
comment
@ Мерт Я сделал. Трудно понять, что именно вы хотите знать. Я ответил в основном на это: i.imgur.com/wVTv9kN.png комментарий слишком длинный, чтобы добавить комментарий - person sehe; 04.02.2015
comment
Я хочу знать, как исправить очевидную утечку, которую я вижу. Я хочу узнать, что, если я делаю очевидную ошибку в своем использовании, которое, с моей точки зрения, было очень тривиальным. Повышает ли утечка журналов при тривиальном использовании — вот предложение, которое излагает мои мысли в нескольких словах, которые могут вписаться в предметную область. - person Mert; 04.02.2015
comment
@Mert Идея: если вы используете std::thread, вы можете попробовать заменить это на использование boost::thread. Функциональность почти идентична, но я думаю, что видел, как boost::thread обеспечивает правильную очистку thread_specific_ptr. Кроме того, никогда не забывайте join потоков. - person sehe; 05.02.2015
comment
Я где-то читал ту же идею и проверял. Я вижу те же утечки из потока повышения. Ниже приведена строка из похожей утечки: ==18126== by 0x80099D9: thread_proxy (в /opt/sesteksdk/lib/libboost_thread.so.1.56.0). Код всегда мгновенно отключает потоки, а синхронизация всегда выполняется через условные переменные (на самом деле это основано на задаче, но каждая задача важна и выполняется в своем собственном потоке). Здесь будет легко разместить пул потоков, поэтому я делаю это сейчас. - person Mert; 05.02.2015

Утекший объект является внутренней частью среды выполнения C++, которая явно не создается Boost.Log. Из того, что я вижу, этот объект создается для каждого потока и поэтому должен быть уничтожен при завершении потока. Ваше использование Boost.Log мне кажется нормальным.

person Andrey Semashev    schedule 05.03.2015