Оптимизация времени выполнения журнала Boost

Я использую Boost-Log и глобальный регистратор серьезности для платформы ведения журнала моего приложения. Профилирование показывает, что boost::log::v2s_mt_posix::core::open_record может занимать до 25% общего времени выполнения.

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

Есть ли способ сделать эти сообщения не такими затратными во время выполнения? (опять же: я ожидаю, что будут небольшие накладные расходы даже при фильтрации и, конечно, большие, когда фильтрация не будет осуществляться).

Во время компиляции это относительно легко «исправить», создав несколько макросов-оболочек.

ОБНОВЛЕНО с образцом рабочего кода:

#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;
}

Запуск с аргументом 0 не печатает никаких сообщений журнала, но занимает вдвое (!) больше времени, чем закомментирование сообщения журнала.


c++ logging boost boost-log
person Dimitris Dakopoulos    schedule 17.06.2014    source источник
comment
Покажите нам пример кода. Минимальная рабочая программа, если можно.   -  person John Zwinck    schedule 17.06.2014
comment
Кажется, что это двукратное замедление (когда большинство сообщений было отфильтровано) присутствовало с тех пор, как оно было впервые принято в качестве библиотеки Boost. lists.boost.org/boost-announce/2010/03/0256. php   -  person Dimitris Dakopoulos    schedule 17.06.2014
comment
вы можете оценить библиотеку асинхронного ведения журналов, например g2log или хотя бы google-glog, который буферизует запись   -  person Dmitry Ledentsov    schedule 17.06.2014

Ответы (2)


arrow_upward
0
arrow_downward

Часто при ведении журнала нужно оценивать то, что регистрируется, и эта оценка происходит до того, как будет принято фактическое решение о том, вести журнал или нет. Например:

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

У нас была собственная система ведения журнала, которая добавляла текущее время в журнал, что было вызовом gettimeofday(). Выяснилось, что 20% потребления ЦП в программе приходилось на вызовы gettimeofday() для функций логирования, которые никуда не делись.

person Mark    schedule 02.10.2014
comment
В случае Boost я почти уверен, что никакой оценки не происходит. Как показано в примере, когда регистрируется простая строка, время выполнения значительно увеличивается. - person Dimitris Dakopoulos; 02.10.2014
comment
@DimitrisDakopoulos, я полагаю, что да, поскольку оператор выходного потока будет вызываться с отдельными аргументами, которые связаны в цепочку, я не знаю, как реализован журнал повышения, но даже в случае игнорирования он, вероятно, должен вернуть что-то, что будет поддерживать оператор потока, который, в свою очередь, будет вызываться для всех значений, передаваемых в... - person Nim; 03.08.2015

arrow_upward
0
arrow_downward

Один обходной путь (кстати, это решение marmite) — использовать макрос для переноса ведения журнала, например:

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

Затем:

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

Вы можете быть уверены, что someExpensiveFunction() будет выполняться только на уровне, поддерживающем INFO.

Черт возьми, вы могли бы даже полностью его скомпилировать,

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

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

person Nim    schedule 03.08.2015