Christopher Smith wrote:
Curt Arnold wrote:
On Oct 7, 2004, at 2:51 PM, Christopher Smith wrote:
1) You pay the price of constructing std::basic_stream regardless of whether logging is turned on.
Do you have any metrics on the cost of that?
No, but I may have some in a week or so. I'll post them as soon as I do.
So, this discussion turned up my curiosity enough that I wrote a small benchmark when I got home tonight. You can grab it from: http://nagoya.apache.org/jira/secure/attachment/17856/benchmark.tar.gz. I wasn't quite sure how to setup a null appender, but I did my best. It takes one argument, which is the number of iterations to time over. I went with a million.
On my home system (2.4GHz P4 running Gentoo & gcc-3.3) these are the numbers I got (this is the average time per iteration):
CVS logstream Logging when disabled: 1600-1800ns Logging when enabled: 13000-15000ns
My LoggingStream Logging when disabled: 40-50ns Logging when enabled: 15000-18000ns
The numbers varied depending on which set of optimizations I used (best performance for all cases seemed to come from -O2 -finline), and whether I used the root logger or child. Overall this is what it broke down to:
When the level was disabled, my logging stream was 30-40x faster. When the level was enabled, mylogging stream was ~15% slower. Interestingly, with certain optimizations and using the child logger, I was only about ~2% slower. I'm guessing this is because isEnabledFor() is more expensive for child loggers as the hierarchy needs to be checked, and I only do it once.
So, I'm guessing I run faster in the disabled case because I don't construct the ostream, while I'm slower in the enabled case because I have to do a heap allocation of the ostream and dereference the pointer.
Personally, I tend to be more concerned that logging be cheap in the disabled case, particularly since the actual cost of appending tends to dwarf the other costs of firing the event.
There was one odd thing that I haven't had time to investigate yet. This line generated a compiler error if I uncommented it:
// LogStream(logger, log4cxx::Level::INFO) << "Entering application: " << aCount << LOG4CXX_ENDMSG;
--Chris
P.S.: I just noticed some performance optimizations to LocationInfo committed into CVS. I'll rerun and see if they have any impact on these results.
