Avoid leak in Boost Log trivial usage

Question

I am getting valgrind leak reports from a server side application that use boostlog that is distributed with boost 1.56. the valgrind report is :

==8021== 37,088 bytes in 1,159 blocks are definitely lost in loss record 1,613 of 1,642

==8021== at 0x4A05588: memalign (vg_replace_malloc.c:727)

==8021== by 0x3FDA61118F: tls_get_addr_tail (in /lib64/ld-2.12.so)

==8021== by 0x3FDA61165F: __tls_get_addr (in /lib64/ld-2.12.so)

==8021== by 0x3FE6ABBDCB: __cxa_get_globals (in /usr/lib64/libstdc++.so.6.0.13)

==8021== by 0x730C528: boost::log::v2_mt_posix::aux::unhandled_exception_count() (in /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)

this leak is coming from a line as simple as :
LOGGER(debug)<< _chanProp->GetId() << " got recognition ended notification from recognizer";

We get 5 of these leaks just from a single, short lived test run.

we use text file backend, with syncronous sink, auto flush is on. Basically:

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();

        }

    }

The system is compiled and run on centos 6.6 using devtoolkit2.0. gcc version is 4.8.2.

So is there a problem in our usage of boost log? Or does boost log really have such problem(s). I think our usage can be considered as a trivial one, we just run the configuration code above during start-up.

Note: Even though a single leak size may be small enough, our software is run as a service on a server, so this kind of repetitive leak is problematic for us.

Stenson

I think that Boost Log creates some initial object when it initializes itself, an object that is live throughout the life of the process. That means it will be counted as a false positive when checking for leaks, because it will be released when the process ends. – Subinfeudate

valgrind reports these leaks as "definitely lost" . The kind you explain would be reported as "possibly lost". In a single run I get five reports like this so it cannot be a one time initialization. – Stenson

Are you using threads? How many threads are running? When and where in the threads (if you use any) is the "leaking" statement (first logging? last logging? somewhere in the middle?) Is the leak always on the same logging statement? – Subinfeudate

The program use threads heavily. Each request from the clients kicks up a few threads. (we use threading so much that we are actually planing to use a threadpool in the short-run) – Stenson

I did not check if the first logging leaks. But i saw leaks from different places. I will check that. – Stenson

The first logging does not leak, its also not the last logging. But I noticed that each leak has happened from a different thread. So this may quite possibly mean that boost log is doing an initialization for each thread it has been used from and when that thread exits this leak is occurring. Another clue might be that Valgrind report contains tls related calls in the stack trace. – Stenson

I made more tests regarding the thread usage. I could not find a ratio between the number of threads and number of leaked blocks but leaks increase with number of threads. my tests : 0 requests cause 3 blocks to leak. 1 request cause 3 blocks to leak. 50 requests cause 47 block(3 different location in code) to leak. – Stenson

I understand that if we do not limit the number of threads we use (assuming that each thread we use do logging at some point) the solution would be hard or near impossible. If that is so I guess using a thread pool instead of making new threads each time ought to be the solution. – Stenson

Salvaging the useful bit from my attempted helpfulness: "Time to make a SSCCE and hit the documentation on proper shutdown sequences". In fact, if make the SSCCE, I would do the other parts gladly (I'll learn too). As it happens, the start-up investment is too much for me. – Eventempered

It's rare that anything good comes from continually creating/terminating/destroying threads during an app run. Use thread pools or app-lifetime threads. Communicate messages/jobs/tasks via queues. Don't use create/join. Don't collect $200. – Milfordmilhaud

I am convinced that if we change our threading approach to use a thread pool this problem will go away. Can someone summarize that the logging systems typically have this kind of behavior so I can accept it as an answer. @Eventempered I think this is such a general case that any working boostlog code would have the same behaviour. So I doubt it deserves a SSCCE. The theoretical answer was just enough. Thanks for your help btw. – Stenson

I've added the threadpool to the system. The leaks really are gone. I am waiting someone to summarize the answers otherwise I will answer it myself and close it. – Stenson

Answer 1

Boost Log - like many other logging libraries - uses tls internally. It is hard(and it seems sometimes impossible) for a logging system to clean up tls variables when a thread terminates. Boost faces the same difficulties.

For a long running application that contains logging code, detaching many threads and terminating them when their task is done is not a good use. A better approach in a heavily multitasking system is to use a thread-pool instead of kicking off new threads each and every time.

I converted the application to use a thread pool and the leaks in the question have disappeared. Tls variables are still there but since now threads are reused tls variables too are reused by their corresponding threads.

Stenson

Answer 2

I don't really get the question. You show evidence of a leak, and ask "does it leak". Well yes. This is hardly surprising. The loggers use thread local "singletons". Depending on how you organized your threads, it will be possible/nigh impossible to properly tear those down.

Time to make a SSCCE and hit the documentation on proper shutdown sequences.

Note

Shutdown of loggers is notoriously hard. You need to deal with the off chance that something needs to log during shutdown (a design smell); Worse, different sinks could depend on each other and prevent shutdown in any particular order).

Quite a few frameworks just leave it to the OS to cleanup.

PS Nothing indicates a repetitive leak, as it looks like a leak per-thread.

Eventempered

The question was : "So is there a problem in our usage of boost log? Or does boost log really have such problem(s)". I did not ask "does it leak?". Did you read the question carefully? – Stenson

@Stenson I did. It's hard to work out what exactly you want to know. I resorted to answering mainly this: i.imgur.com/wVTv9kN.png Anyways, - my comment was too long to put in a comment – Eventempered

I want to know how to fix the obvious leak I see. I want to learn that if I am making an obvious error in my usage which in my point of view was very trivial. "Does boost log leak in trivial usage" was the sentence that puts my thoughts in a few words that could fit into the subject area. – Stenson

@Stenson An idea: if you use std::thread you can try replacing that with boost::thread usage. The functionality is almost identical but I think I've seen boost::thread provide proper cleanup of thread_specific_ptr. Also, never forget to join threads. – Eventempered

I've read the same idea somewhere and checked it. I see the same leaks from boost thread too. The following is a line from a similar leak : ==18126== by 0x80099D9: thread_proxy (in /opt/sesteksdk/lib/libboost_thread.so.1.56.0). The code always detach the threads instantly and synchronizations are always done through condition variables(actually it is task based but each task is significant and runs in its own thread ). It will be easy to put a thread-pool here so i am doing that now. – Stenson

Answer 3

The leaked object is an internal part of the C++ runtime, which is not explicitly created by Boost.Log. From what I can see, this object is created per-thread and as such should be destroyed when the thread terminates. Your usage of Boost.Log seems fine to me.

Diwan