3 ms·

Ahh, logging, a subject dear to my heart. At the last project I worked on, we did a lot of work to optimize our logging, as it was being done on low spec TV se

by davedx 8y ago

Ahh, logging, a subject dear to my heart. At the last project I worked on, we did a lot of work to optimize our logging, as it was being done on low spec TV set-top-boxes, and we were burning a ton of CPU cycles just doing formatting (lots of JSON serialization). What many devs fail to realise is that, unless extra effort is made (as in the Erlang system in the OP), every log operation you call is a synchronous, blocking call that can actually be relatively expensive due to all the serialization and I/O that goes on. Async logging can help of course (necessary if you want to send logs over the network). But you can still spend a lot of CPU just formatting the log lines themselves. The solution we decided on was similar to what you'd do in a C/C++ project: for release/production, add a build step that removes all logging commands below the logging level for the target. For example in C, you'd usually use macros for this, and if your macro wasn't defined in release builds, none of the logging code would be included in your executable. This is great for performance but does have an operational trade off. Ops people might want to be able to change the logging level of a system to diagnose live issues. But if I think about all the CPU cycles and HDD storage spent on logging (and often those wasted cycles have a very real impact on UX or server latency), then I think in many cases it is worth stripping out anything lower than Error level as standard.

thibaut_barrere 8y ago
There is a lot of care in Elixir Logger (https://hexdocs.pm/logger/Logger.html https://hexdocs.pm/logger/Logger.html) with regard to this. For instance, "arguments given to info/2 will only be evaluated if a message is logged". You can also trim out (at compile time, like you did with the build step) all the logging commands below the selected level, with the ":compile_time_purge_matching" option.
- davedx 8y ago
  That’s really awesome. All modern platforms should do this
mononcqc 8y ago
yeah, Erlang-wise, most loggers have done these checks for years. There's always a big concern in terms of avoiding the most work possible as early as possible so all that filtering takes place early on. The handler and filter structure with both global and per-handler filters is fairly clever as a way to turn these things on and off easily, and the module and level checks are done the earliest since they can allow to eliminate the most amounts of logs the cheapest way possible.

by davedx 8y ago

thibaut_barrere 8y ago

There is a lot of care in Elixir Logger (https://hexdocs.pm/logger/Logger.html https://hexdocs.pm/logger/Logger.html) with regard to this. For instance, "arguments given to info/2 will only be evaluated if a message is logged". You can also trim out (at compile time, like you did with the build step) all the logging commands below the selected level, with the ":compile_time_purge_matching" option.

davedx 8y ago
That’s really awesome. All modern platforms should do this

mononcqc 8y ago

yeah, Erlang-wise, most loggers have done these checks for years. There's always a big concern in terms of avoiding the most work possible as early as possible so all that filtering takes place early on. The handler and filter structure with both global and per-handler filters is fairly clever as a way to turn these things on and off easily, and the module and level checks are done the earliest since they can allow to eliminate the most amounts of logs the cheapest way possible.