[ Sent previously and canceled because I forgot to compress the text files - Pardon me if you get two copies ] On 11/15/05, Darryl Green <darryl.green@unitab.com.au> wrote:
Compiler/version? Optimization settings? How long does a single or a very small number of iterations of the disabled cout and disable log take?
Here is a small program I just wrote that might be useful to profile and benchmark the logging library. The program accepts the following command line arguments: -b | --bypass Bypass all logging; used as a control -d | --disable Disable the log -f | --file <filename> Send output to the named file -i | --iostreams Use a std::ofstream for output instead of Boost.Log. Can be combined with -d and -f to help benchmark raw iostreams vs. Boost.Log. The program uses SIGALRM to interrupt the benchmarking loop, so I'm not sure if it will work properly on Windows. I had tried a more portable implementation that checked for the boost::timer.elapsed time to reach 1.0, but the overhead of checking the clock overwhelmed the rest of the test so I scrapped that. In the code, I'm also not making use of the Boost.Log supplied "write_to_file" appender, which IMHO is fundamentally broken. It opens the file for append, writes a message, and then closes the file for every message it logs. I've provided an implementation called "my_write_to_file" which leaves the file open for the appenders lifetime. It does no explicit flushing on the stream. Here's the output when compiled with g++ 3.3.4 -O2 on a GNU/Linux with dual P4 Xeon 3.2 GHz and run with various flags: % ./boost-log-test Using enabled Boost.Log, output to (nowhere) 542303 logging operations in 0.99 sec =3D 547781 ops/sec or 1.82555e-06 sec/op % ./boost-log-test -d Using disabled Boost.Log 49492447 logging operations in 1 sec =3D 4.94924e+07 ops/sec or 2.02051e-08 sec/op % ./boost-log-test -f /dev/null Using enabled Boost.Log, output to /dev/null 484558 logging operations in 1 sec =3D 484558 ops/sec or 2.06374e-06 sec/op % ./boost-log-test -f /tmp/test.log Using enabled Boost.Log, output to /tmp/test.log 465831 logging operations in 1 sec =3D 465831 ops/sec or 2.1467e-06 sec/op % ./boost-log-test -d -i Using disabled iostreams 789447209 logging operations in 1.02 sec =3D 7.73968e+08 ops/sec or 1.29204e-09 sec/op % ./boost-log-test -i -f /dev/null Using enabled iostreams, output to /dev/null 5969546 logging operations in 1 sec =3D 5.96955e+06 ops/sec or 1.67517e-07 sec/op % ./boost-log-test -i -f /tmp/test.log Using enabled iostreams, output to /tmp/test.log 4223268 logging operations in 0.99 sec =3D 4.26593e+06 ops/sec or 2.34416e-07sec/op I've also profiled this code, and found some not-too-suprising results (also attached): - When the logger is enabled, the bulk of this program's time is spent in boost:logging::enabled_logger::~enabled_logger, which is calling write_msg with the result of std::ostringstream::str. - When the logger is disabled, much of the time is spent in ~enabled_logger as well as the is_enabled check Overall, the performance of the Boost.Log library when output is enabled is almost an order of magnitude slower than just writing the same data to a standard iostream. I believe the overhead of the enabled_logger design (object creation, heap allocation of an ostringstream every time a message is logged) might bear some re-examination. Is the enabled_logger object really necessary? Can the ostringstream be created on the caller's stack instead of the heap (e.g. by re-writing the BOOST_LOG macro) or perhaps re-used? I believe that the syntax of the logging macros (e.g. BOOST_LOG (x) << ...), while clever, contributes to the relatively poor performance of the library when compared to bare iostreams. I would suggest that by enclosing the entire logging statement in the macro invocation (e.g. BOOST_LOG(x, ...) ), a more optimal, feature-rich implementation is be possible. It becomes exceedingly simple to implement compile-time removal of logging calls with the "enclosed" macro-based interface, obviating the need for the is_compile_time complexities in the current code. Additionally, messages might be logged with __FILE__ and __LINE__ information automatically (if so desired). I'm sure there are other benefits (and weaknesses) that I'm overlooking as well. Hope this helps, -- Caleb Epstein caleb dot epstein at gmail dot com