Flogger implementation should not read the configuration twice

[forax]

I think there is an issue in your implementation when the configuration is changed dynamically. Your implementation read the configuration twice, once in at(Level) and once later in log() so the logger can check the level of one configuration and log using another newly updated configuration.

To fix this issue, you can read the configuration once in at() and propagate the configuration as a parameter of the Context.

[hagbard]

Hi, thanks for your comments (and sorry for not replying sooner). I assume you mean that there are multiple calls to "isLoggable()" for the same log statement when you talk about "reading the configuration".

This was a deliberate choice in the design and related to forcing of log statements. In those cases the backend will say that a log statement is not loggable, but we ignore that in the frontend and push the log record through anyway. The decision not to store the result was likely related to a desire to keep the LogContext objects as small as possible (since they get allocated a lot).

See the rather complex in AbstractBackend.java for more.

I think that the worst that happens is a harmless race condition between the time that a log statement begins and when it's output. Is this behaviour causing you a problem?

[forax]

Hi David, yes, multiple calls is the issue because the backend can changed in-between those calls, it's not a race because it's not an access on the same data, it's more an API violation.

The behavior of a backend can be compromised because you can have this scenario: isLoggable is called on backend1, at that point the backend is changed to backend2, then the logging is done on backend2 without calling isLoggable of backend2.

And you're right that storing the backend in LogContext will fix this issue.

[hagbard]

The log context logs to the backend of the logger it was created with. And that field is final, so cannot change. If a composite logger backend wishes to allow switching between implementations dynamically it is required to implement any additional checks required to behave "properly".

In short, the backend is already effectively "stored" in the log context (but I actually go via the logger to avoid extra fields). See code in AbstractLogger.

[forax]

By additional checks, you mean that the logger first checks if it should log by asking the backend, if the answer is true the when .log() is called, the backend has to check again if it should log so performing the logging check twice.

If it's implemented like this, i agree that there is no issue but it means that you have two volatile reads when logging and usually Hotspot tend to not merge those volatile reads (i'm happy if i'm wrong about that).

[hagbard]

Yes, but when logging, the cost of doing the second check is utterly insignificant to the rest of the work done. Optimizing for "no work" only matters in the case when you aren't logging. When you are logging, there are allocations, some string formatting, I/O etc...

[forax]

I agree that doing a second volatile read on the same address is cheap compared to the first volatile read, but it's still slower that not doing it.

The elephant in the room is a volatile read, by itself is already awful, it's slow from the CPU POV and worst it disables hamper JIT optimizations like loop hoisting (the VM is forced to re-read all fields from the RAM).

Optimizing for "no work" only matters in the case when you aren't logging

yes, but it enable a powerful way of writing/deploying a software. It means that you can have a fine grain logging in production because the cost at runtime is really zero until you enable a particular logger to diagnose an issue.

When you are logging, there are allocations, some string formatting, I/O etc..

yes, i agree, string formatting can be done in one allocation BTW using the StringConcatFactory.