Logging overhead due to unnecessary pessimism

[swebb2066]

AppenderAttachableImpl::appendLoopOnAppenders locks a mutex for every Logger in the path to the root Logger.

Logging overhead would be reduced significantly if AppenderAttachableImpl was immutable.

[swebb2066]

On Windows, the benchmark comparisons using a lock (old) and without locking (new) in AppenderAttachableImpl::appendLoopOnAppenders are:

Benchmark	Time	CPU	Time Old	Time New	CPU Old	CPU New
Testing disabled logging request	+0.0524	+0.0084	4	4	1	1
Testing disabled logging request/threads:4	+0.0369	-0.0044	1	1	4	4
Logging 5 char string using MessageBuffer, pattern: %m%n	-0.2688	-0.3065	738	539	443	307
Logging 5 char string using MessageBuffer, pattern: %m%n/threads:4	-0.3380	-0.4413	437	290	1289	720
Logging 49 char string using MessageBuffer, pattern: %m%n	-0.0783	-0.1196	752	693	481	424
Logging 49 char string using MessageBuffer, pattern: %m%n/threads:4	-0.2386	-0.2128	462	352	1242	977
Logging int value using MessageBuffer, pattern: %m%n	+0.0696	-0.0857	1756	1879	1099	1004
Logging int value using MessageBuffer, pattern: %m%n/threads:4	-0.1047	-0.0368	740	662	1744	1680
Logging int+float using MessageBuffer, pattern: %m%n	-0.0856	-0.2073	3535	3233	2288	1814
Logging int+float using MessageBuffer, pattern: %m%n/threads:4	-0.0242	-0.0556	1387	1354	3139	2965
Logging int value using MessageBuffer, pattern: [%d] %m%n	-0.0155	-0.2530	1868	1839	1144	854
Logging int value using MessageBuffer, pattern: [%d] [%c] [%p] %m%n	-0.1486	-0.1360	1876	1597	1308	1130
Logging 49 char string using FMT, pattern: %m%n	-0.2258	-0.3268	796	617	572	385
Logging 49 char string using FMT, pattern: %m%n/threads:4	-0.2812	-0.2012	489	352	1135	907
Logging int value using FMT, pattern: %m%n	-0.1590	-0.3030	712	599	460	321
Logging int value using FMT, pattern: %m%n/threads:4	-0.2876	-0.1461	458	326	1062	907
Logging int+float using FMT, pattern: %m%n	-0.1087	+0.0263	1132	1009	663	680
Logging int+float using FMT, pattern: %m%n/threads:4	-0.1788	-0.2244	544	447	1662	1289
Async, int value using MessageBuffer, pattern: %m%n	+0.0425	-0.0427	1824	1902	1224	1172
Async, int value using MessageBuffer, pattern: %m%n/threads:4	-0.0787	-0.2361	745	686	1883	1439

[swebb2066]

On Ubuntu gcc 11, the benchmark comparisons using a lock (old) and without locking (new) in AppenderAttachableImpl::appendLoopOnAppenders are:

Benchmark	Time	CPU	Time Old	Time New	CPU Old	CPU New
Testing disabled logging request	-0.0370	-0.0365	0	0	0	0
Testing disabled logging request/threads:4	-0.2354	-0.2353	0	0	1	1
Logging 5 char string using MessageBuffer, pattern: %m%n	-0.2278	-0.2279	311	240	311	240
Logging 5 char string using MessageBuffer, pattern: %m%n/threads:4	-0.3315	-0.3237	553	370	2172	1469
Logging 49 char string using MessageBuffer, pattern: %m%n	-0.1668	-0.1668	318	265	318	265
Logging 49 char string using MessageBuffer, pattern: %m%n/threads:4	-0.3456	-0.3381	575	376	2262	1497
Logging int value using MessageBuffer, pattern: %m%n	-0.1342	-0.1342	489	423	489	423
Logging int value using MessageBuffer, pattern: %m%n/threads:4	-0.4666	-0.4631	593	316	2345	1259
Logging int+float using MessageBuffer, pattern: %m%n	-0.0736	-0.0736	941	872	941	872
Logging int+float using MessageBuffer, pattern: %m%n/threads:4	-0.3367	-0.3335	754	500	2997	1997
Logging int value using MessageBuffer, pattern: [%d] %m%n	-0.2144	-0.2143	627	492	627	492
Logging int value using MessageBuffer, pattern: [%d] [%c] [%p] %m%n	-0.2166	-0.2165	629	493	629	493
Logging 49 char string using FMT, pattern: %m%n	-0.2071	-0.2071	293	232	293	232
Logging 49 char string using FMT, pattern: %m%n/threads:4	-0.4621	-0.4589	537	289	2114	1144
Logging int value using FMT, pattern: %m%n	-0.1490	-0.1489	315	268	315	268
Logging int value using FMT, pattern: %m%n/threads:4	-0.3587	-0.3562	548	351	2162	1392
Logging int+float using FMT, pattern: %m%n	-0.1278	-0.1278	468	408	468	408
Logging int+float using FMT, pattern: %m%n/threads:4	-0.1714	-0.1653	429	356	1700	1419
Async, int value using MessageBuffer, pattern: %m%n	-0.1403	-0.1403	493	424	493	424
Async, int value using MessageBuffer, pattern: %m%n/threads:4	-0.4647	-0.4598	680	364	2683	1449

[swebb2066]

After #351, the benchmark comparing the current implementation (lock and copy appender pointers) versas no copying or lock on gcc 11 indicates a 30-40 ns overhead from the copy and no disernable lock contention:

Benchmark	Time	CPU	Time Old	Time New	CPU Old	CPU New
Testing disabled logging request	+0.0000	+0.0000	0	0	0	0
Testing disabled logging request/threads:6	+0.0346	+0.0346	0	0	1	1
Appending 5 char string using MessageBuffer, pattern: %m%n	-0.1557	-0.1557	332	280	332	280
Appending 5 char string using MessageBuffer, pattern: %m%n/threads:6	-0.0916	-0.1142	397	361	2252	1995
Appending 49 char string using MessageBuffer, pattern: %m%n	-0.1265	-0.1265	366	320	366	320
Appending 49 char string using MessageBuffer, pattern: %m%n/threads:6	-0.0478	-0.0749	442	421	2475	2290
Appending int value using MessageBuffer, pattern: %m%n	+0.0204	+0.0204	500	510	500	510
Appending int value using MessageBuffer, pattern: %m%n/threads:6	+0.0200	-0.0074	442	451	2502	2484
Appending int+float using MessageBuffer, pattern: %m%n	+0.0091	+0.0090	990	999	990	999
Appending int+float using MessageBuffer, pattern: %m%n/threads:6	-0.0406	-0.0499	549	527	3226	3065
Appending int value using MessageBuffer, pattern: [%d] %m%n	+0.0038	+0.0038	546	548	546	548
Appending int value using MessageBuffer, pattern: [%d] [%c] [%p] %m%n	-0.0056	-0.0055	605	602	605	602
Appending 49 char string using FMT, pattern: %m%n	-0.1537	-0.1537	341	289	341	289
Appending 49 char string using FMT, pattern: %m%n/threads:6	-0.0290	-0.0623	445	432	2480	2326
Appending int value using FMT, pattern: %m%n	-0.1406	-0.1406	369	317	369	317
Appending int value using FMT, pattern: %m%n/threads:6	-0.0171	-0.0526	445	437	2488	2357
Appending int+float using FMT, pattern: %m%n	-0.0714	-0.0714	507	471	507	470
Appending int+float using FMT, pattern: %m%n/threads:6	-0.0422	-0.0589	485	465	2776	2612
Async, Sending int+float using MessageBuffer	+0.0188	+0.0188	1204	1226	1204	1226
Async, Sending int+float using MessageBuffer/threads:6	-0.1140	-0.1127	557	494	3327	2952
Logging int+float using MessageBuffer, pattern: %d %m%n	+0.0148	+0.0193	1137	1153	1132	1153
Logging int+float using MessageBuffer, pattern: %d %m%n/threads:6	-0.0278	-0.0226	1155	1123	5068	4954
OVERALL_GEOMEAN	-0.0448	-0.0521	0	0	0	0