...

Scenario	Process	Threads	Output	Logging Proxy	Central Logger	Oneway	Total	Average	Min	Max
1	Client	1	Log (stdout)				18380 us	1.8 us	1.6 us	308 us
1	Client	1	Log (stdout)				601893 us	60.1 us	5.9 us	525.8 us
2	Client	1	Log (stdout)				681522 us	68.1 us	52.8 us	531.7 us
3	Client	1	Log (stdout)				337458 us	33.7	19.2 us	353.4 us
4	Client	1	Log (file)				18639 us	1.8 us	1.6 us	295 us
4	Client	1	Log (file)				548046 us	54.8 us	6.3 us	783.2 us
5	Client	1	Log (file)				619841 us	61.9 us	52.5 us	946.9 us
6	Client	1	Log (file)				320333 us	32.0	16.8 us	393.5 us
7	Client	1	stdout				18841 us	1.8 us	0.8 us	447.9 us
8	Client	1	file				21358 us	2.1 us	1.4 us	332.8 us
9	Client	1	no-op				834 us	0.1 us	0.02 us	95.2 us
10	Client	10	Log (stdout)				64520.4 us	6.4 us	1.7 us	610.9 us
10	Client	10	Log (stdout)				1415860 us	141.5 us	4.9 us	12617.4 us
11	Client	10	Log (stdout)				2950060 us	294.902 us	66.257 us	5005.26 us
12	Client	10	Log (stdout)				958351 us	95.75 us	16.7 us	65872.4 us
13	Client	10	Log (file)				63096.3 us	6.2 us	1.7 us	1007.8 us
13	Client	10	Log (file)				930486 us	93.0 us	6.8 us	15150.4 us
14	Client	10	Log (file)				2319040 us	231.8 us	54.7 us	5164.8 us
15	Client	10	Log (file)				660748 us	66.0 us	15.3 us	67563.6 us
16	Client	10	stdout				301182 us	30.1 us	0.8 us	1655.3 us
17	Client	10	file				210906 us	21.06 us	1.5 us	285.3 us
18	Client	10	no-op				2409 us	0.2 us	0.02 us	257.84 us
19	Component	1	Log (stdout)
20	Component	1	Log (stdout)
21	Component	1	Log (stdout)
22	Component	1	Log (file)
23	Component	1	Log (file)
24	Component	1	Log (file)
25	Component	1	stdout
26	Component	1	file
27	Component	1	no-op
28	Component	10	Log (stdout)
29	Component	10	Log (stdout)
30	Component	10	Log (stdout)
31	Component	10	Log (file)
32	Component	10	Log (file)
33	Component	10	Log (file)
34	Component	10	stdout
35	Component	10	file
36	Component	10	no-op

Analysis

LoggingProxy

From the statistics results, we can infer that (in a local environment) the biggest performance hit comes from the LoggingProxy itself and not the communication with the Central Logger. Going a bit further , we found out that a mutex is guilty of thistwo slow downs down the path:

                xmlElement = XMLParser::parseString(iter->c_str(), true);

And

            ts.tv_sec=0;bool LoggingProxy::sendRecord(const Logging::XmlLogRecordSeq &reclist)
{
    ACE_GUARD_RETURN (ACE_Recursive_Thread_Mutex, ace_mon, m_mutex, false);

        ts.tv_nsec=100;
            //FIXME: This nanosleep provide stability to the logging system. It shouldn't exist :(
            nanosleep(&ts,NULL);

Which combined with several mutexes, end up generating thread contention on the logging system.

The impact is of about 60/70 μs on average for each log call, which is not a big number, but we would like to be closer to the 1/10 μs range.

There are different strategies that could be used to fix this problem, such as refactoring the code, replacing the XML parsing library or the mechanism used within the library, re-structuring the use of mutexes to multiple instances or changing them to be RW mutexes.

Central Logger