Logging should be lazy (because programmers are)
Logging is one of the most important thing in programming. I like to call it an “art”. This is because if you are good at logging things, you can save a lot of (your or your teammates) time when:
- something goes wrong in production
- you are working on a new piece of code
- you are refactoring some old program that is somehow complicated
That said, there are some best practices in the art of logging. We would like to show some performance-related issues that you can easily implement in your everyday code.
We are going to use Python for this purpose.
Python logging
Here is the hello world for logging in python
>>>import logging>>>logging.warning("Hello logging")WARNING:root:Hello logging
Here, we use warning as log level because this is the default level set in python when you use the logging module (which use an instance of the logger class called root). In fact, if you try to run
>>>import logging>>>logging.info(“Hello logging”)
Nothing is displayed, because the info level is below the warning level and no message is displayed.
This is the definition of the warning function in the logging module
def warning(msg, *args, **kwargs):The same structure is applied for the other log levels definitions. So basically, we have to pass the message as the first argument, but we can pass more arguments after this one.
This is the key in the lazy logging pattern. We’ll see later why is that so important.
Talk is cheap
Let’s show some code.
>>>import logging>>>class RaiseWhenPrinted:
... def __str__(self):
... raise Exception(“I was printed”)>>>raise_when_printed = RaiseWhenPrinted()
So the RaiseWhenPrinted class is raising an exception whenever you try to call its __str__ method. This happens for example when you want to log the instance of this object raise_when_printed. Let’s do it
>>>logging.info(“Logging {}”.format(raise_when_printed))Traceback (most recent call last):File “<input>”, line 1, in <module>File “<input>”, line 3, in __str__Exception: I was printed
So even if the logging level is below info, the exception is raised. This means that the __str__ method of the RaiseWhenPrinted instance was called even if the log level is not set to info.
Here is where lazy logging comes in. Let’s modify our code
>>>logging.info(“Logging %s”, raise_when_printed)In this case, no exception is raised. This means that the __str__ method was not called. So we made our log lazy, because it is not been evaluated unless we actually need it.
In fact, if we run
>>>logging.warning(“Logging %s”, raise_when_printed)we receive the full stack trace of the exception, which means that the __str__ method was called as expected.
Why is that?
The explanation is quite simple (and very elegant in my opinion).
Let’s recall the definition of the info log level function (which is the same as the warning definition)
def info(msg, *args, **kwargs):So if we write our log command in the code using the format method to concatenate strings (same apply for f-strings)
logging.info(“Logging {}”.format(raise_when_printed))we are basically telling the interpreter that the msg argument is the string "Logging {}.format(raise_when_printed)"that is evaluated immediately at runtime.
Instead, writing the command in the lazy way
logging.info(“Logging %s”, raise_when_printed)tells the interpreter that the msg argument is "Logging %s”which is a common string and the other argument is the raise_when_printed instance. Here, the __str__ method has not been called yet.
When the program reaches this line, the info function is called and internally it checks if the log level is the one set. If not, nothing happens. Otherwise the string is formed.
This is basically the definition of laziness in programming.
Time it!
Let’s talk about performances. Here we use the timeit library. This library can help us calculating how much time a command takes to execute.
>>>import timeit>>>lazy = “logging.info(‘lazy %s’, ‘logging’)”>>>not_lazy = “logging.info(‘not lazy {}’.format(‘logging’))”>>>setup = “import logging”
So basically we create our two logging commands lazy and not_lazy because timeit wants a string as first argument (it calls exec on that string). The setup variable is important because it tells timeit which commands should be run to set up the environment. If we run the two commands we get
>>>timeit.timeit(not_lazy, setup=setup)0.9043805910005176>>>timeit.timeit(lazy, setup=setup)0.7162870119991567
So the difference is not so big, but we must notice that the string to log is super easy. With this in mind, the difference is quite big.
Summing up
Lazy logging is not a common practice in python, even if this is the example provided in the official documentation.
I cannot say that in Flowe we log everything in this way, but we are aware of this and are gradually refactoring our code by transforming our logs in lazy logs.
But if you are starting a brand new project, you should definitely consider using this approach.
