Add new Rails/EagerEvaluationLogMessage cop

[Aesthetikx]

Hello,

The Debugging Rails Applications guide recommends that blocks are passed to Rails.logger.info et. al. instead of method arguments, as there is some performance impact on generating potentially expensive log messages that do not even end up being logged depending on config.log_level. Since Rails changed the default log_level to :info, this may now be more beneficial. For example,

`Rails.logger.debug { "Expensive computation: #{computation}" }`

instead of

`Rails.logger.debug "Expensive computation: #{computation}"`

This PR adds a new cop "Rails/LoggerBlock" that detects values passed to the various log methods, such as Rails.logger.debug, and then supports autocorrecting to the block form.

This is my first time working on Rubocop, so I am looking for feedback to see if this is something that will be useful to the community, if it should be enabled by default, or if this is something that should use two enforced styles (which I did not implement,) what the cop should be called, etc. I am also unsure if this should also attempt to detect situations where users access logger without the Rails prefix, as it is often in scope. Indeed, using logger this way could possibly be a cop in itself. Finally, there is also the Logger#add method which I did not deal with, but I could. Lastly as I am writing this I am realizing that ActiveSupport::Logger actually just inherits Logger from the Ruby standard library, so possibly this could be just a plain rubocop cop?

[koic]

If you like, can you open another PR for this typo fixing.

[andyw8]

so possibly this could be just a plain rubocop cop?

Yes, I think this would be better suited to https://github.com/rubocop/rubocop as a Performance cop.

[koic]

https://github.com/rubocop/rubocop as a Performance cop.

Performance cop is managed by https://github.com/rubocop/rubocop-performance :-)

This is a technical note. Ruby's Logger#debug is an instance method. In other words, it cannot be detected safely for receiver object. On the other hand, the proposed implementation detects Rails.logger.debug, so it can be safe detection for receiver object (Rails.logger).

[Aesthetikx]

Thank you for your helpful feedback, I will make changes in the next couple days as we continue to discuss some of the details. I am wondering if it could make sense to have three enforced styles, one being (the default) "always use blocks for interpolated strings, never use blocks otherwise", one being "never use blocks", and one being "always use blocks".

@koic you are correct about the difficulty of detecting any call to any subclass of Logger, indeed this was something that I was thinking could be an issue, but if we only attempt to explicitly detect Rails.logger.x usage, that is not a problem.

On a side note, using the parser gem, is there an easier / conventional way to detect the range of source code that is the method arguments, including parenthesis, if they are present?

[koic]

I am wondering if it could make sense to have three enforced styles, one being (the default) "always use blocks for interpolated strings, never use blocks otherwise", one being "never use blocks", and one being "always use blocks".

Is it faster with blocks even for non-interpolation strings? I haven't benchmarked it, but I'm concerned it won't be faster for plain (non-interpolation) strings. So I think it will be limited if blocks are required, and EnforcedStyle may not be needed.

On a side note, using the parser gem, is there an easier / conventional way to detect the range of source code that is the method arguments, including parenthesis, if they are present?

I think (maybe) something existed, but I cannot remember without investigating :-)

[bquorning]

I'm having trouble reading the tests (in general, looping in tests make them less clear) – do you intend to warn people when calling logger.warn, logger.error etc. with a String argument? I don't think that should be the case. The default logger level for Rails is info, which means only debug calls are conditional and will benefit from using the block style.

[Aesthetikx]

@koic Today or tomorrow I am going to do some benchmarks on your idea of interpolated vs non interpolated strings, and then perhaps we can make a more informed decision. Is it worth also considering that users could be passing other things to Rails.logger..., such as some_method which returns some object (in a possibly slow way) to be printed out, which would have otherwise been avoided by wrapping some_method in a block?

Also, do you have any opinion on taking the default rails logger level (was :debug, now :info) into account?

[Aesthetikx]

Ok, here are my findings. I have attached two files, a performance script and the results from running it on my laptop.

The script sets Rails.logger.level to :info, to match the default Rails production level. Then, it runs a series of comparisons between the 'standard method call' and 'block version' for a few different log output scenarios:

• The number 8
• The string 'A string log message'
• The interpolated string "An interpolated string log message: #{Time.zone.now}"
• The method call Time.zone.now (a somewhat expensive yet realistic method call)
• The method call rand (a cheaper method call)

It does this for both the :debug level and for the :info level, so that we can see the effect of using a block when the statements will be logged, and when they will not.

To summarize the results:

• When logging to a level that will end up being logged, such as Rails.logger.debug with the :debug log level, using a block does not seem to have any noticeable performance impact, at least as compared to the actual logging.
• When logging to a level that will not end up being logged, such as Rails.logger.debug with the :info log level, using a block improves performance for somewhat-expensive method calls (~3.5x for methods like Time.zone.now) and improves performance even more-so for interpolation (~20x for interpolation with a method like Time.zone.now), but does not have an impact on other things like plain strings or optimized method calls.

So, I suppose there could be three takeaways from this depending on your worldview:

1. In a strict sense, "always" using blocks is "never worse" for performance, albeit with the cost of having to remember to use them and subsequently understand why you are supposed to be using blocks.
2. In a less strict sense, only use blocks for interpolated strings, and possibly only for the debug log level, because that is the highest performance benefit with the lowest cognitive overhead, although it is selectively applied.
3. Forget that this ever happened and move on with our lives ;)

performance_test.rb.txt (A .txt to satisfy GH)

results.txt

I am happy to make changes to the PR based on the wisdom of the people involved here.

[koic]

Great! Thank you for your taking time and investigation.

In a less strict sense, only use blocks for interpolated strings, and possibly only for the debug log level, because that is the highest performance benefit with the lowest cognitive overhead, although it is selectively applied.

I'd like to take this one. It also matches the context mentioned in the reference.
There is a possibility that it will be extended from pragmatic user feedback in future, but I think that the cop can start from this point.

[Aesthetikx]

Ok @koic, I think I am finished with the changes, and ready for another review. @bquorning, as per your suggestion the cop only considers Rails.logger.debug now, so there are no loops in the tests anymore.

[koic]

Thanks!

[bbugh]

I am wondering if it could make sense to have three enforced styles, one being (the default) "always use blocks for interpolated strings, never use blocks otherwise", one being "never use blocks", and one being "always use blocks".

We really want this because nobody remembers to do it, and there's a lot of Rails.logger.debug that has to be checked at code review. Performance analysis showed it was costing us quite a lot of processing.

I can PR this (unless you're enthusiastic about doing it @koic sorry, @Aesthetikx) to add another style for all blocks. Can we do that?