Boost logo

Boost :

From: Caleb Epstein (caleb.epstein_at_[hidden])
Date: 2005-11-15 11:14:21

[ 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_at_[hidden]> 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

I've also profiled this code, and found some not-too-suprising results (also

   - 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

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

Boost list run by bdawes at, gregod at, cpdaniel at, john at