CODEWITHSUNDEEP
c++loggingboostboost-log
Dimitris Dakopoulos
Dimitris Dakopoulos

Reputation: 713

Boost Log run-time optimization

I am using Boost-Log and the global severity logger for my application's logging platform. Profiling shows that the boost::log::v2s_mt_posix::core::open_record can take up to 25% of the total execution time.

I do have many log messages BUT I would not expect them to be so costly since they are lower severity and they are filtered.

Is there a way to make those messages not so costly in run-time? (again: I expect to have a small overhead even when filtered and of course a larger when not-filrered).

Compile-time is relatively easy to "fix" this by creating some wrapper macros.

UPDATED with sample working code:

#include <cmath>
#include <iostream>
#include <string>
#include <boost/lexical_cast.hpp>
#include <boost/log/sources/global_logger_storage.hpp>
#include <boost/log/sources/severity_logger.hpp>
#include <boost/log/trivial.hpp>
#include <boost/log/sources/severity_channel_logger.hpp>
#include <boost/log/common.hpp>
#include <boost/log/expressions.hpp>
#include <boost/log/sinks.hpp>
#include <boost/log/utility/setup/common_attributes.hpp>
#include <boost/log/utility/setup/console.hpp>
#include <boost/log/support/date_time.hpp>
#include <boost/utility/empty_deleter.hpp>
#include <boost/shared_ptr.hpp>
#include <boost/make_shared.hpp>

// severity levels
enum severity_level {INFO};

// Logging macro
#define LOG(level) BOOST_LOG_SEV(global_logger::get(), level)

// Initializing global boost::log logger
typedef boost::log::sources::severity_channel_logger_mt<
    severity_level, std::string> global_logger_type;

BOOST_LOG_INLINE_GLOBAL_LOGGER_INIT(global_logger, global_logger_type)
{
    return global_logger_type(boost::log::keywords::channel = "global_logger");
}

// Initialize terminal logger
void init_logger(int verbosity)
{
    namespace bl = boost::log;
    typedef bl::sinks::synchronous_sink<bl::sinks::text_ostream_backend>
      text_sink;

    boost::shared_ptr<text_sink> sink = boost::make_shared<text_sink>();
    sink->locked_backend()->add_stream(
        boost::shared_ptr<std::ostream>(&std::cout, boost::empty_deleter()));

    sink->locked_backend()->auto_flush(true);

    sink->set_formatter(bl::expressions::stream << bl::expressions::message);

    sink->set_filter(bl::expressions::attr<severity_level>("Severity")
                     < (severity_level) verbosity);

    bl::core::get()->add_sink(sink);
    bl::add_common_attributes();
}

int main(int argc, char* argv[])
{
    init_logger(boost::lexical_cast<int>(argv[1]));
    for(int i = 0; i < 200; ++i)
    {
        std::sin(std::sin(17.2)); // dummy processing
        LOG(INFO) << "A message!";
    }
    return 0;
}

Running with argument 0 does not print any log messages but it takes twice (!) the time than commenting out the LOG message.

Upvotes: 10

Views: 2735

Answers (2)

Nim
Nim

Reputation: 33655

One workaround (this is a marmite solution btw.) is to use a macro to wrap the logging, for example:

#define LOG_INFO(x) \
  if (<test if log level is INFO>) { \
    LOG(INFO) << x;  \
  }

Then:

LOG_INFO("Foo" << "Bar" << someExpensiveFunction());

You can be sure that the someExpensiveFunction() will only be executed at a level that supports INFO.

Heck, you could even go as far as compiling it out completely, 

#ifndef _NINFO_
#define LOG_INFO(x) \
  if (<test if log level is INFO>) { \
    LOG(INFO) << x;  \
  }
#else
#define LOG_INFO(x)
#endif

Another advantage of this would be that you could change the logging implementation by modifying the macro rather than than changing all your code every where..

Upvotes: 0

Mark
Mark

Reputation: 1

Often, when logging, what is being logged has to be evaluated, and that evaluation happens before the actual decision whether to log or not is made. For example:

log.debug("The current state of the system is: " + system.expensiveFunctionToGatherState());

We had a home grown logging system that added the current time to the log, which was a call to gettimeofday(). Turned out 20% of the CPU consumption in the program was calls into gettimeofday() for log functions that never went anywhere.

Upvotes: 0

Related Questions