Re: [boost] Some simple logging performance tests

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
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