Checking log level at compile time instead of runtime?

[jeroenvandijk]

Did you consider checking the log level in the log* macro to be done at compile time? I'm talking about this line, here https://github.com/ptaoussanis/timbre/blob/master/src/taoensso/timbre.clj#L333

My current project is very performance sensitive and I would be more confident putting log statements everywhere if I would know that it would not affect performance at all at runtime. Even if it doesn't matter that much, I don't see the benefit of having the option to change the log level at runtime, for production at least. Am I wrong?

What do you think?

Thanks for this library!

Best, Jeroen

[ataggart]

Given what you wrote, you might consider using clojure.tools.logging in your code. You can set timbre as the backing implementation if you do end up wanting to change configuration inside the repl (something not easy to do with SLF4J, etc. as the backing implementation).

On Mon, Aug 19, 2013 at 12:48 PM, Jeroen van Dijk notifications@github.comwrote:

Did you consider checking the log level in the log* macro to be done at compile time? I'm talking about this line, here https://github.com/ptaoussanis/timbre/blob/master/src/taoensso/timbre.clj#L333

My current project is very performance sensitive and I would be more confident putting log statements everywhere if I would know that it would not affect performance at all at runtime. Even if it doesn't matter that much, I don't see the benefit of having the option to change the log level at runtime, for production at least. Am I wrong?

What do you think?

Thanks for this library!

Best, Jeroen

— Reply to this email directly or view it on GitHubhttps://github.com/ptaoussanis/timbre/issues/24 .

[ptaoussanis]

Hey Jeroen, thanks for getting in touch! This'd be an easy thing to add, and I like the idea - will open an issue for it, though no promises I'll have time to implement it this week. PR's welcome if you feel like it.

I am curious though: is there a particular reason you believe the logging level check is a performance problem in your case?

The sufficient-level? check is a little slow, but:

1. It's on the order of .5μs per call. There are indeed cases where that'd be a problem, but not very many that I see in the Clojure space generally.
2. More importantly, most of the rest of the library's perf is in proportion. There's a lot of small perf tradeoffs made, for example, to facilitate easier config and appender writing. So performance has always been a secondary goal for Timbre - if you are in a situation where you really need every last μs, probably Timbre wouldn't be a good fit overall anyway. Depends on your needs.

In any event, like I said, this'd be a useful and easy change so I'll definitely make it - just curious :-)

Thanks again for the idea, cheers!

[jeroenvandijk]

Hi Peter,

I'm writing code for a real time bidding system, for which each request needs to be finished within 200ms, including the server-server latency. So .5μs might be fast enough for a single case, but someone (including myself) might be silly enough to put a log statement in a loop of 1000 items and this .5μs turns into 5ms. I would be more convenient if during code reviews I wouldn't have to pay too much attention to logging calls. While saying this, nothing like this has happened yet, so maybe it is premature :)

For now I'll look into @ataggart suggestion (thanks, btw!). If I find time this week I'll look into a PR.

Thanks, Jeroen

[ptaoussanis]

I'm writing code for a real time bidding system

Gotcha! I'll do some extra profiling when I make the suggested change and see if there's anywhere else I might be able to trim fat. We can make the ns filter a compile-time check in most cases too, for example.

For now I'll look into @ataggart suggestion (thanks, btw!). If I find time this week I'll look into a PR.

Sorry, not really sure what Alex had in mind (I might well have misunderstood?) - but swapping to tools.logging won't improve performance here if you're still using Timbre as a backend since tools.logging would just delegate to Timbre's logging-level check anyway, so all you'd be doing is adding overhead. An alternative would be to swap for a Java-based logger, but those introduce their own set of problems that I normally try avoid.

Will come back to you about the change unless you beat me to it with a PR ;-)

Cheers!

[ptaoussanis]

Okay ended up having an appointment cancellation so took a quick stab at this on the perf branch: https://github.com/ptaoussanis/timbre/compare/perf?expand=1.

Two major changes:

1. ns filtering is always done at compile-time when possible.
2. Added support for a TIMBRE_LOG_LEVEL environment variable. When present, it acts as a compile-time logging level.

Using the env var, all logging calls with an insufficient level evaluate to nil at compile time, so there's literally zero performance hit.

Will try find some time in the week to test and clean this up a bit. Suggestions/changes welcome.

[jeroenvandijk]

Wow that's quick! A system env sounds like the right approach. I'll look into it tomorrow!

Sent from my iPad

On 20 aug. 2013, at 17:54, Peter Taoussanis notifications@github.com wrote:

Okay ended up having an appointment cancellation so took a quick stab at this on the perf branch: https://github.com/ptaoussanis/timbre/compare/perf?expand=1.

Two major changes:

1. ns filtering is always done at compile-time when possible.
2. Added support for a TIMBRE_LOG_LEVEL environment variable. When present, it acts as a compile-time logging level.

Using the env var, all logging calls with an insufficient level evaluate to nil at compile time, so there's literally zero performance hit.

Will try find some time in the week to test and clean this up a bit. Suggestions/changes welcome.

— Reply to this email directly or view it on GitHub.

[ptaoussanis]

Pushed as v2.6.0 so long, feel free to reopen if you run into any trouble or have any other suggestions/etc. Cheers!

[jeroenvandijk]

Thanks! I've tested it and it works. I had to run lein clean to fix an argument error with logging-enabled?

Regarding the implementation, one more nitpick would be that there is still the (tiny, tiny) overhead of evaluating (when nil) here https://github.com/ptaoussanis/timbre/blob/4cc5bf3b47cf636b43bd5acc3c6598a1f1456f4a/src/taoensso/timbre.clj#L352 Maybe the automatic JVM optimization already takes care of this. Otherwise, an option would be to have something like a when-logging-enabled? macro that would entirely remove any execution. I'll leave it to you to judge whether this is worth the effort.

[ptaoussanis]

Regarding the implementation, one more nitpick would be that there is still the (tiny, tiny) overhead of evaluating (when nil) here

Not a nitpick at all. My first attempt was actually (literally) when-logging-enabled? as you suggest, and for this same reason. After benching it though, the JVM does seem to optimize away the (when nil) and the resulting implementation was a little cleaner so I went with it.

Numbers:

(time (dotimes [_ 1000000000] (trace (Thread/sleep 5000))))
%> "Elapsed time: 387.159 msecs"

(time (dotimes [_ 1000000000] nil))
%> "Elapsed time: 389.231 msecs"

Note that that's actually a billion iterations...

There may still be room for other improvements though; am not using the compile-time levels myself, so very happy to get your feedback if anything comes up.

[jeroenvandijk]

Yeah I did something like your test with criterium and found similar results like that. It is probably too small to measure any difference, if any, which is good.

I'm happy to try Timbre into production now, so I'll definitely let you know when there is room for improvement somewhere.