#c #logging #boost #boost-log
#c #ведение журнала #ускорение #boost-log
Вопрос:
Я использую 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>(amp;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
не выводит никаких сообщений журнала, но это занимает в два раза (!)
больше времени, чем комментирование сообщения ЖУРНАЛА.
Комментарии:
1. Покажите нам несколько примеров кода. Минимальная рабочая программа, если сможете.
2. Кажется, что это замедление в 2 раза (когда большинство сообщений было отфильтровано) присутствовало с тех пор, как оно было впервые принято в качестве библиотеки Boost. lists.boost.org/boost-announce/2010/03/0256.php
3. возможно, вам захочется оценить библиотеку асинхронного ведения журнала, такую как g2log или, по крайней мере, google-glog , которая записывает в буферы
Ответ №1:
Часто при регистрации необходимо оценивать то, что регистрируется, и эта оценка происходит до принятия фактического решения о том, регистрироваться или нет. Например:
log.debug("The current state of the system is: " system.expensiveFunctionToGatherState());
У нас была домашняя система ведения журнала, которая добавляла текущее время в журнал, что было вызовом gettimeofday()
. Оказалось, что 20% потребления ЦП в программе gettimeofday()
приходилось на вызовы функций журнала, которые никуда не уходили.
Комментарии:
1. Я повышаю случай, я почти уверен, что никакой оценки не происходит. Как я показываю в примере, когда регистрируется простая строка, время выполнения значительно увеличивается.
2. @DimitrisDakopoulos, я бы предположил, что это так, поскольку оператор выходного потока будет вызываться с отдельными аргументами, которые связаны цепочкой, я не знаю, как реализован boost log, но даже в игнорируемом случае он, вероятно, должен возвращать что-то, что будет поддерживать оператор потока, что, в свою очередь, будетвызывается для всех передаваемых значений…
Ответ №2:
Одним из обходных путей (кстати, это простое решение) является использование макроса для завершения ведения журнала, например:
#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
Еще одним преимуществом этого было бы то, что вы могли бы изменить реализацию ведения журнала, изменив макрос, а не изменять весь свой код везде..