apache / logging-log4cxx

Apache Log4cxx is a C++ port of Apache Log4j
http://logging.apache.org/log4cxx
Apache License 2.0
278 stars 122 forks source link

Reduce the overhead of unconfigured loggers #351

Closed swebb2066 closed 9 months ago

swebb2066 commented 9 months ago

AppenderAttachableImpl::appendLoopOnAppenders does not need to lock a mutex for any Logger in the path to the root Logger which has no appenders attached (This partly addressed #347).

swebb2066 commented 9 months ago

On Windows, the benchmark\tools\compare.py benchmarks old.json new.json results are:

Benchmark Time CPU Time Old Time New CPU Old CPU New
Testing disabled logging request +0.0034 +0.1569 4 4 1 1
Testing disabled logging request/threads:4 -0.2516 -0.4159 1 1 4 2
Logging 5 char string using MessageBuffer, pattern: %m%n -0.1902 -0.2120 738 597 443 349
Logging 5 char string using MessageBuffer, pattern: %m%n/threads:4 +0.0410 -0.5887 437 455 1289 530
Logging 49 char string using MessageBuffer, pattern: %m%n -0.0180 -0.1123 752 739 481 427
Logging 49 char string using MessageBuffer, pattern: %m%n/threads:4 -0.0485 -0.3203 462 439 1242 844
Logging int value using MessageBuffer, pattern: %m%n -0.0725 -0.1875 1756 1629 1099 893
Logging int value using MessageBuffer, pattern: %m%n/threads:4 -0.1219 -0.3980 740 650 1744 1050
Logging int+float using MessageBuffer, pattern: %m%n -0.1529 -0.3460 3535 2995 2288 1496
Logging int+float using MessageBuffer, pattern: %m%n/threads:4 -0.1841 -0.3902 1387 1132 3139 1914
Logging int value using MessageBuffer, pattern: [%d] %m%n -0.1133 -0.2317 1868 1656 1144 879
Logging int value using MessageBuffer, pattern: [%d] [%c] [%p] %m%n -0.0990 -0.2480 1876 1690 1308 984
Logging 49 char string using FMT, pattern: %m%n -0.0972 -0.2988 796 719 572 401
Logging 49 char string using FMT, pattern: %m%n/threads:4 -0.1717 -0.4716 489 405 1135 600
Logging int value using FMT, pattern: %m%n -0.0587 -0.0932 712 670 460 417
Logging int value using FMT, pattern: %m%n/threads:4 -0.1114 -0.3957 458 407 1062 642
Logging int+float using FMT, pattern: %m%n -0.1281 -0.1353 1132 987 663 573
Logging int+float using FMT, pattern: %m%n/threads:4 -0.1281 -0.5153 544 475 1662 806
Async, int value using MessageBuffer, pattern: %m%n -0.1272 -0.2650 1824 1592 1224 900
Async, int value using MessageBuffer, pattern: %m%n/threads:4 -0.0474 -0.3363 745 709 1883 1250
rm5248 commented 9 months ago

What's the reasoning behind the lazy initialization of m_priv? It makes the code harder to read IMO since you now have an extra check to see if it is valid, instead of just knowing that it always exists.

swebb2066 commented 9 months ago

What's the reasoning behind the lazy initialization of m_priv? It makes the code harder to read IMO since you now have an extra check to see if it is valid, instead of just knowing that it always exists.

Less memory and processor overhead (see the above benchmarks).

An application will create many loggers, but few (usually only the root logger) has attached appenders.

Lazy initialization reduces memory alloc's by avoiding allocating AppenderAttachableImpl::priv_data (and initializing a std::mutex + std::vector) for all those loggers that do not have attached appenders.

Throughput is improved because appendLoopOnAppenders does not acquire a lock for each decendent logger in the path to the root logger.

swebb2066 commented 9 months ago

On Ubuntu (gcc 11), the benchmark/tools/compare.py --no-color benchmarks /tmp/old.json /tmp/new.json results are:

Benchmark Time CPU Time Old Time New CPU Old CPU New
Testing disabled logging request -0.0358 -0.0354 0 0 0 0
Testing disabled logging request/threads:4 -0.2218 -0.2217 0 0 1 1
Logging 5 char string using MessageBuffer, pattern: %m%n -0.0704 -0.0703 311 289 311 289
Logging 5 char string using MessageBuffer, pattern: %m%n/threads:4 -0.0560 -0.0531 553 522 2172 2056
Logging 49 char string using MessageBuffer, pattern: %m%n -0.0133 -0.0133 318 314 318 314
Logging 49 char string using MessageBuffer, pattern: %m%n/threads:4 -0.2431 -0.2367 575 435 2262 1727
Logging int value using MessageBuffer, pattern: %m%n -0.0474 -0.0475 489 466 489 466
Logging int value using MessageBuffer, pattern: %m%n/threads:4 -0.2029 -0.2014 593 473 2345 1872
Logging int+float using MessageBuffer, pattern: %m%n -0.0000 -0.0000 941 941 941 941
Logging int+float using MessageBuffer, pattern: %m%n/threads:4 -0.2770 -0.2735 754 545 2997 2177
Logging int value using MessageBuffer, pattern: [%d] %m%n -0.1074 -0.1074 627 559 627 559
Logging int value using MessageBuffer, pattern: [%d] [%c] [%p] %m%n -0.1052 -0.1051 629 563 629 563
Logging 49 char string using FMT, pattern: %m%n -0.0333 -0.0333 293 283 293 283
Logging 49 char string using FMT, pattern: %m%n/threads:4 -0.1931 -0.1891 537 433 2114 1714
Logging int value using FMT, pattern: %m%n -0.0156 -0.0156 315 310 315 310
Logging int value using FMT, pattern: %m%n/threads:4 -0.1616 -0.1590 548 459 2162 1818
Logging int+float using FMT, pattern: %m%n -0.0558 -0.0559 468 442 468 442
Logging int+float using FMT, pattern: %m%n/threads:4 +0.0794 +0.0839 429 463 1700 1843
Async, int value using MessageBuffer, pattern: %m%n -0.0463 -0.0463 493 471 493 471
Async, int value using MessageBuffer, pattern: %m%n/threads:4 -0.3025 -0.2992 680 474 2683 1880