[log] Cache logger object in a private var

[alexander-yakushev]

This PR modifies toucan2.log macros so that when expanded, they intern a special Var into the current namespace where the logging is performed, and that var is bound to the value of the logger. Next invocations of the log macros in that namespace will reuse the logger.

Also don't use (delay doc), instead hide the doc computation behind boolean checks.

[codecov]

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 83.61%. Comparing base (3729d20) to head (fa84004).

Additional details and impacted files

@@            Coverage Diff             @@
##           master     #184      +/-   ##
==========================================
+ Coverage   83.58%   83.61%   +0.02%     
==========================================
  Files          37       37              
  Lines        2498     2502       +4     
  Branches      212      212              
==========================================
+ Hits         2088     2092       +4     
  Misses        198      198              
  Partials      212      212              

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[camsaul]

Would it make more sense to move the call to intern inside -get-logger, that way the macroexpansion is a little more concise? If that call needs to happen ever time might as well move it into a helper function so the code exists once total instead of once per macro usage

[camsaul]

So, changing the shape of the code so doc doesn't use a delay makes 100% sense to me as an optimization, I'm happy to merge that stuff in.

I am worried about caching the logger however. In Metabase we support changing log levels at runtime (mostly in tests but we have discussed being able to do this on a live instance for debugging purposes) which in some cases means we need to create new loggers on the fly.

For example maybe we have our Log4j2 config set up like

<Logger name="metabase" level="INFO"/>

which means that the metabase logger is used for "child" namespaces, e.g. the logger for metabase.db is the metabase logger.

Now if we wanted to change the log level of metabase.db to DEBUG but leave other metabase.* at INFO we would have to create a new logger for metabase.db. So I'm worried that caching the logger would break our ability to do things like that on the fly.

Even clojure.tools.logging itself doesn't try to optimize out the call to get-logger -- this happens in every call to clojure.tools.logging/log which underlies everything else:

https://github.com/clojure/tools.logging/blob/6748dcb66bd058d49caa8c01442fad37a5b5378d/src/main/clojure/clojure/tools/logging.clj#L78

So I'm not sure how I feel about optimizing Toucan 2 logging above and beyond what the logging library we use everywhere else does.

Can you share some metrics about performance improvements when implementing this change? If we are wasting a lot of time on a few specific log/trace calls or whatever in tight loops it might be best just to comment them out for now or something rather than do something crazy with our logging implementation

[alexander-yakushev]

Regarding the impact: this is a benchmark I did for #185. get_logger method is highlighted, accounts for 34% of the total runtime 😱.

[alexander-yakushev]

Regarding your other comments:

I understand the requirement for being able to change logging levels in production. I suspect that this should still be possible even with cached logging object – after all, caching a logger object in class's static field is a common pattern in Java applications, and I'm sure people use the dynamic logger toggles there. Anyway, this would have to be tested – I'd need to know the exact way how you are going to change the logging levels (is it programmatically or declaratively somehow?).

I also understand why you wouldn't want to complicate the logging implementation here. Maybe, removing the expensive trace calls is a better way to go. You can see on the flamegraph above that there are 8 places where logging calls are impactful. If you are fine just commenting out those, I'll do it instead.

[alexander-yakushev]

UPD: even with this optimization, but after all other pending PRs are applied, the logging overhead still amounts to ~20%. So, removing the offending traces is probably a way to go anyway.