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 logging overhead more #336

Closed swebb2066 closed 10 months ago

swebb2066 commented 10 months ago

This PR improves benchmarks more than #333.

On Windows, the new results are: Benchmark Time CPU Iterations
Testing disabled logging request 3.18 ns 1.19 ns 497777778
Testing disabled logging request/threads:4 1.35 ns 3.85 ns 199111112
Logging 5 char string using MessageBuffer, pattern: %m%n 614 ns 327 ns 3200000
Logging 5 char string using MessageBuffer, pattern: %m%n/threads:4 359 ns 837 ns 1120000
Logging 49 char string using MessageBuffer, pattern: %m%n 707 ns 488 ns 1120000
Logging 49 char string using MessageBuffer, pattern: %m%n/threads:4 442 ns 949 ns 1054116
Logging int value using MessageBuffer, pattern: %m%n 1564 ns 889 ns 896000
Logging int value using MessageBuffer, pattern: %m%n/threads:4 608 ns 1289 ns 400000
Logging int+float using MessageBuffer, pattern: %m%n 2941 ns 1880 ns 407273
Logging int+float using MessageBuffer, pattern: %m%n/threads:4 1163 ns 3047 ns 400000
Logging int value using MessageBuffer, pattern: [%d] %m%n 1804 ns 1130 ns 746667
Logging int value using MessageBuffer, pattern: [%d] [%c] [%p] %m%n 1572 ns 907 ns 1120000
Logging 49 char string using FMT, pattern: %m%n 703 ns 391 ns 1600000
Logging 49 char string using FMT, pattern: %m%n/threads:4 414 ns 767 ns 1120000
Logging int value using FMT, pattern: %m%n 643 ns 348 ns 1659259
Logging int value using FMT, pattern: %m%n/threads:4 384 ns 907 ns 896000
Logging int+float using FMT, pattern: %m%n 1088 ns 641 ns 1000000
Logging int+float using FMT, pattern: %m%n/threads:4 532 ns 1270 ns 689232
Async, int value using MessageBuffer, pattern: %m%n 1876 ns 1367 ns 560000
Async, int value using MessageBuffer, pattern: %m%n/threads:4 675 ns 1694 ns 617932
swebb2066 commented 10 months ago
On Ubuntu gcc 9, benchmarks improve to: Benchmark Time CPU Iterations
Testing disabled logging request 0.475 ns 0.475 ns 1000000000
Testing disabled logging request/threads:16 0.092 ns 1.01 ns 674392480
Logging 5 char string using MessageBuffer, pattern: %m%n 295 ns 295 ns 2369056
Logging 5 char string using MessageBuffer, pattern: %m%n/threads:16 456 ns 3678 ns 203328
Logging 49 char string using MessageBuffer, pattern: %m%n 329 ns 329 ns 2124660
Logging 49 char string using MessageBuffer, pattern: %m%n/threads:16 428 ns 3500 ns 172976
Logging int value using MessageBuffer, pattern: %m%n 513 ns 513 ns 1365225
Logging int value using MessageBuffer, pattern: %m%n/threads:16 457 ns 3705 ns 188320
Logging int+float using MessageBuffer, pattern: %m%n 906 ns 906 ns 769372
Logging int+float using MessageBuffer, pattern: %m%n/threads:16 440 ns 3644 ns 171664
Logging int value using MessageBuffer, pattern: [%d] %m%n 516 ns 516 ns 1368021
Logging int value using MessageBuffer, pattern: [%d] [%c] [%p] %m%n 515 ns 515 ns 1371139
Logging 49 char string using FMT, pattern: %m%n 288 ns 288 ns 2433169
Logging 49 char string using FMT, pattern: %m%n/threads:16 367 ns 2972 ns 204304
Logging int value using FMT, pattern: %m%n 316 ns 316 ns 2175223
Logging int value using FMT, pattern: %m%n/threads:16 430 ns 3481 ns 199248
Logging int+float using FMT, pattern: %m%n 451 ns 451 ns 1553304
Logging int+float using FMT, pattern: %m%n/threads:16 450 ns 3659 ns 187680
Async, int value using MessageBuffer, pattern: %m%n 512 ns 512 ns 1367661
Async, int value using MessageBuffer, pattern: %m%n/threads:16 516 ns 4199 ns 196688
rm5248 commented 10 months ago

I thought I had seen in one of the other PRs that you had done something like:

callAppenders(event, this->pool);

Was that not the case? I would imagine that just passing the same pool around would be better since it would not continuously allocate new pools.

swebb2066 commented 10 months ago

done something like: callAppenders(event, this->pool);

Yes. That was my initial commit to #333. However, I later realized that was an error as the additions to the APR pool in callAppendersneed to be freed after callAppendersreturn. So the separate APR sub-pool is needed to prevent unbounded memory growth in the long lived pool held by the Hierarchyobject.

Most appenders no longer alloc memory from an APR pool (exceptions are ODBCAppender, SMTPAppender, etc). This is the reason this PR achieves much better performance than #333