Caching of Context objects

[scottsue]

Hi all,

I have been performing some performance testing within our application that utilises Flogger (log4j2 backend) as our logging framework.

I have found that when performing logging (arguably excessive number of log statements), Flogger starts showing up withing our profiler (we are using async-profiler).

Digging further into the Flogger implementation, it seems that the Context object is created upon every call to Flogger. Which called enough will become a drag on garbage collection.

Is there any possibility for this Context object to be cached and reused across multiple logging calls?

Thanks in advance!

[hagbard]

We've thought about this a lot over the years, but the general consensus was that if the context allocations are an issue, then the cost of logging (formatting strings, processing arguments) would be a much much bigger issue.

If the logging is disabled by the log level, then no logging context will be creating (it reuses a static no-op instance) so context allocations should normally only happen when dealing with logging which is expected to log to some formatted/structured output, when the cost of exfiltrating the log message would far exceed the cost of the context.

Are you perhaps testing this out in an unrealistic situation (e.g. micro benchmarks)?

It would be potentially possible to cache the context, but also potentially slower (since it would have to be a thread local instance retrieved each time rather than a fast "small" allocation). You would also need to make contexts more mutable than they are and pay the cost of nulling out fields after use to prevent accidental retention of referenced arguments/metadata. It's doable and we'd consider it if you can show a realistic situation in which it's an issue, but so far in Google (which uses Flogger extensively) it's not shown up at all.

[scottsue]

Hi @hagbard, appreciate your insight on this. Makes complete sense as my default would be to favour immutability over caching of objects as well.

Flogger does a great job of reducing the cost of logging to almost zero. The rationale behind my thinking was from the point of view was to align with one of the flogger best practices to "don't be afraid to add fine-grained logging". I believe that this is also a great thing to have and follow as well. For our system, we are in the low-latency space and we've found in our performance benchmarks that with enough 'fine-grained' logging, it starts to become a non-zero cost. With that in mind, we've had to be a little more judicious and have had to remove certain logging as it starts to cost more to log than to do the actual work for the areas that get hit hard.