[log] filtering performance

It seems that the library does quite a bit of work before filtering away a record, unless the logging is turned off entirely. There's at least two mutex locks, some memory allocation, etc. Callgrind claims ~2500 instructions when the record is thrown away by the global severity filter. Shortened callgrind output is in-line below; full output and the test program attached. Compiled by gcc 4.2.3 using boost.build variant=release threading=multi. 7 BOOST_LOG_SEV(slg, normal) << "A normal severity message, will not pass to the output (global filter)"; 99,557 => bool basic_severity_logger::open_record() (1x) 7 BOOST_LOG_SEV(slg, normal) << "A normal severity message, will not pass to the output (global filter)"; 2,530 => bool basic_severity_logger::open_record() (1x) 7 BOOST_LOG_SEV(slg, normal) << "A normal severity message, will not pass to the output (global filter)"; 2,530 => bool basic_severity_logger::open_record() (1x) 7 BOOST_LOG_SEV(slg, warning) << "An warning severity message, will not pass to the output (sink filter)"; 5,212 => bool basic_severity_logger::open_record() (1x) 7 BOOST_LOG_SEV(slg, warning) << "An warning severity message, will not pass to the output (sink filter)"; 3,904 => bool basic_severity_logger::open_record() (1x) 7 BOOST_LOG_SEV(slg, warning) << "An warning severity message, will not pass to the output (sink filter)"; 3,904 => bool basic_severity_logger::open_record() (1x) . 10 BOOST_LOG_SEV(slg, error) << "An error severity message, will be printed"; 218,306 => record_pump::~record_pump() (1x) 24,144 => bool basic_severity_logger::open_record() (1x) 10 BOOST_LOG_SEV(slg, error) << "An error severity message, will be printed"; 28,963 => record_pump::~record_pump() (1x) 5,074 => bool basic_severity_logger::open_record() (1x) 11 BOOST_LOG_SEV(slg, error) << "An error severity message, will be printed"; 28,644 => record_pump::~record_pump() (1x) 5,074 => bool basic_severity_logger::open_record() (1x)

Igor Nazarenko wrote:
It seems that the library does quite a bit of work before filtering away a record, unless the logging is turned off entirely. There's at least two mutex locks, some memory allocation, etc. Callgrind claims ~2500 instructions when the record is thrown away by the global severity filter. Shortened callgrind output is in-line below; full output and the test program attached. Compiled by gcc 4.2.3 using boost.build variant=release threading=multi.
Although I didn't extensively profile the code, I believe that is quite possible.
participants (2)
-
Andrey Semashev
-
Igor Nazarenko