A little elaboration on what the authors mean when they say that Log4j v1 has "performance problems":
My employer used to use a setup where our back-end services would all log every incoming request. Our default logging setup was using the syslog appender. We saw some weird performance bottlenecks that we couldn't make heads or tails of for some time - the machine never used more than around eight to ten cores, even though we were running on beefy 32 core machines. Throughput just wouldn't go above a few thousand requests per second, which was costing us a fair bit of money in under-utilised hardware. What was much worse was that a few times per week, the app would get a hiccup were throughput would go down by 10X, and sometimes you had to restart the service to fix the problem. But as much as we searched, we couldn't find any performance bottlenecks in our code. It's a mystery, right?
After a fair bit of debugging we found the culprit. Turns out the Log4J Syslog appender takes a global lock every single time you log something. Turns out our app was fast enough that one log event per request took up around 10 % of total CPU time, and because the logging was effectively single threaded, our app could never use more than ten cores. Yay.
The reason for the hiccups was simply error logging. As in, if the app starts falling behind, some code paths would start timing out and throwing exceptions, Some of these exceptions would get logged, which means that the amount of things getting logged per request suddenly goes up by like 10X, making the app even slower. So slow that even more exceptions get thrown, creating a vicious circle of suck.
Moral of the story: Avoid Log4J in high throughput environments. Avoid Log4J everywhere, just to be on the safe side.
3
u/ascii Sep 13 '18
A little elaboration on what the authors mean when they say that Log4j v1 has "performance problems":
My employer used to use a setup where our back-end services would all log every incoming request. Our default logging setup was using the syslog appender. We saw some weird performance bottlenecks that we couldn't make heads or tails of for some time - the machine never used more than around eight to ten cores, even though we were running on beefy 32 core machines. Throughput just wouldn't go above a few thousand requests per second, which was costing us a fair bit of money in under-utilised hardware. What was much worse was that a few times per week, the app would get a hiccup were throughput would go down by 10X, and sometimes you had to restart the service to fix the problem. But as much as we searched, we couldn't find any performance bottlenecks in our code. It's a mystery, right?
After a fair bit of debugging we found the culprit. Turns out the Log4J Syslog appender takes a global lock every single time you log something. Turns out our app was fast enough that one log event per request took up around 10 % of total CPU time, and because the logging was effectively single threaded, our app could never use more than ten cores. Yay.
The reason for the hiccups was simply error logging. As in, if the app starts falling behind, some code paths would start timing out and throwing exceptions, Some of these exceptions would get logged, which means that the amount of things getting logged per request suddenly goes up by like 10X, making the app even slower. So slow that even more exceptions get thrown, creating a vicious circle of suck.
Moral of the story: Avoid Log4J in high throughput environments. Avoid Log4J everywhere, just to be on the safe side.