Re: [boost] Some simple logging performance tests

From: Darryl Green (darryl.green_at_[hidden])
Date: 2005-11-15 05:42:14

Andrew Schweitzer <a.schweitzer.grps <at> gmail.com> writes:
> 
> Using GetTickCount and GetThreadTimes on Windows XP Pro, recorded time 
> to execute some simple pieces of logging code in a loop. Divided by loop 
> iterations to get time per iteration. This is a 3Ghz Pentium. Not sure 
> how good these tests are, but here's the results:
> 
> results:
> 		elapsed ms 	thread time ms		ns / call 		
                (GetTickCount) 
> (GetThreadTimes)	(in thread)		
> cout		1329		421 			42100
> enabled log	1469		453			45300
> cout "disabled"	15		15			15
> disabled log	531		531			531

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's a little detail on tests
> cout, 10,000 times, l_dw increments each loop:	
> 	cout << l_dw << endl;
> 
> enabled log, 10,000 times:
> 	//outside loop:
> 	enable_logs("lgTest");
> 	//in loop:
> 	BOOST_SCOPEDLOG(l_lgTest) << l_dw << endl;
> 
> cout "disabled", 1,000,000 times:
> 	//outside loop:
> 	bool l_bEnabled = false;	
> 	//in loop:
> 	if(l_bEnabled)
> 	{
> 		cout << l_dw << endl;
> 	}

The disabled cout test, if it really is as simple a bit of code as that should 
take something close to 0 time to execute - which it does. If you put the if
(l_bEnabled) test in a separate compilation unit to the loop body is 
performance the same?

> 
> disabled log, 1,000,000 times:
> 	//outside loop:
> 	disable_logs("lgTest"); 	//this not in loop
> 	//in loop:
> 	BOOST_SCOPEDLOG(l_lgTest) << l_dw << endl;

This involves at least the creation and destruction of a small temporary 
object, a function call to a separate compilation unit and an inderection 
through a shared ptr (not expensive) 500 odd ns seems broadly ok for that I 
guess - so something like 2 million disabled log messages/second.... Don't 
accidentally enable all logs/that log.... If you have a system with 100 logs, 
and only 1 enabled, the other 99 logs (being called at the same rate) are using 
the same amount of CPU as your 1 enabled log - not too bad - not as good as it 
could be either I'd guess.

Some performance test should be added to the code before it is released - what 
enabled/disabled performance ratio do you think is needed for a "pass"? What 
sort of "nop function" do you think the disabled log needs to be equivalent to 
to pass?