It works if I’m looking at it!
Today my team tracked down, hunted and summarily executed a bug. It was a nasty one, because under certain (pretty rare) error conditions, we would get into pretty nasty state and not recover from it.
The problem was that the code to handle this and handle the state properly was there, and on when we tested it locally, worked just fine. But on production, it didn’t work. Unless we tried to figure out why it wasn’t working, in which case it did work.
As you can imagine, this can be a pretty frustrating state of affair. Eventually we tracked it down to the following problem. Here is the relevant code. And the problem is that the exception aren’t thrown (and therefor not handled). Can you see the issue?
Comments
Such misuse of IsInfoEnabled is not even funny. It's plain dumb optimization that you should forbid somehow IMO.
Some may say that IsInfoEnabled is misused but from another perspective it seems that handling of invalid responses shouldn't belong to that switch statement at all which is about logging response with Info level. Another switch or few ifs will do the job better
The exception for a failure reply isn't thrown unless info loggin is enabled.
This seems like you're mixing two things here. Logging and handling the reply
wqw, What probably happened is that we had the logic there just for logging. Then the actual handling was added without realizing that this isn't always going to run
I like how you share these kinds of things. We've all done it at some stage - it's experience.
We had an issue once a few years back where we'd log an exception if something went wrong processing a PDF. We were (and still are) using Serilog and its great ability to log out details of an object. The issue is that we blindly passed the PdfField object to be logged - that unfortunately had a reference to the PdfDocument, which itself had references to other PdfField instances, etc. Crazy shenanigans and a huge amount of RAM consumed. Lesson learnt - logging is helpful but definitely don't just pass some third party's object to the logging framework as it could change at any time and alter the behaviour of your program.
Logging affects your program. Often not as obviously as shown in this code snippet of course :)
Even without the error handling bug this code looks a bit ugly. Why not let
_log
determine if it has to do something or just ignore theInfo()
call by checking its own state (IsInfoEnabled
) internally? I feel this code is breaking _log encapsulation.Jose, That is by design, I wrote about this here: https://ayende.com/blog/174530/designing-ravendbs-debug-log-system
Put simply, logging can be _expensive_, so we make sure to only generate the log statements if logging is enabled. It means more code, but it has measurable impact on perf.
What I am saying is pretty basic and it is impossible that a seasoned developer like you do this kind of things without a very good reason so I guess I am missing something... I am going to insist just to discover what I am missing, not because I think I am right. I hope not bother you.
You can make sure of that and avoid leaking
_log
behaviour at the same time with this kind of implementation:About corner cases; if you need to call several
_log.Info
for onereplicationBatchReply
you will have an impact on perf because you are callingif (this.IsInfoEnabled)
several times but this can be solved by aggregating the log messages first and using a overload version:Logger.Info(string[] messages)
.So, the only impact on perf I can see is betwen noop and just one
_log.Info
call that does not do nothing. How is the difference in expensiveness betwen calling a function that does not do nothing or just not calling at all? Is this the reason that leads you to the implementation I see in the post?@Jose: it is about the arguments of the log statement. if you just provide a single hard coded message, you might be right. I would also expect every major logging framework to have a fast noop-path already.
But if you want to log some ID in the string, or you have to compute a count of items or some average to log, this will always be done before calling into _log.info and can only be avoided with the given if.
I think you could solve this with c++ template macros or with deep inlining and compiler optimization. both are not available in c# and one could argue, it is a good thing?!
Ok. Now it is clear as water to me. It is about also avoiding the work of creating the logging data that need to be passed to
_log.Info
.Some of design pattern comes to my mind to also avoid that work but due the performance requrements for speed and memory footprint the proyect has I can completely understand the reasons of that implementation.
Many thanks Fabian.
Fun fact, thats why at the moment (a current project of mine requires it ) i love kotlin so dearly .... inline functions to the rescue, e.g:
inline fun ILog.info(messageProducer : () -> String ) { if(isInfoEnabled()) { this.logInfo(messageProducer()); } }
Usage:
log.info { "Hello world" }
This will be inlined completly at the call site, and gives us the best of both worlds, zero allocations in the case of info not enabled, (the passed function is inlined transitively ) and the computation of the log message is also only performed when needed.
Jose, Yes, that is the key part. And preparing the log message can be really expensive. Good log messages can require gather a lot of data.
Bernhard, If this allows you to prevent closures / capturing / allocations, that is really nice.
Yes this prevents any and all allocations in the above case, but comes with a few limitations as well:
Since messageProducer is inlined, you can only invoke it, but not store it in a variable. However inline functions in Kotlin work around several issues in the JVM as well as they allow a limited form of reified generics to work as well.
I have tried many programming languages in my life time, and Kotlin is one of the best designed out there... I am not going into things like extension lambda functions, that will blow your mind though :-)
Comment preview