Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Already on GitHub? Sign in to your account

Optimize log subscribers to check if the log level is sufficient #7708

Merged
merged 4 commits into from Oct 2, 2012

Conversation

Projects
None yet
4 participants
Contributor

bdurand commented Sep 19, 2012

This change adds checks to the beginning of logging methods in the default log subscribers to ensure that the log level is sufficient before continuing. Without this code, production applications with logging turned down will still execute a fair bit of code on every request to set up log messages that are then thrown away.

Also made a very minor optimization to time formatting to use string interpolation instead of formatters.

Finally removed Explain queries from being logged by active record since they are not interesting for debugging purposes and only pollute the log. This can clean up development logs significantly when using a variety of third-party gems that force Explain to be run on every query.

Owner

rafaelfranca commented Sep 19, 2012

Sorry but the explain queries is a feature and we can remove they in this way. If you don't want the Explain queries just set config.active_record.auto_explain_threshold_in_seconds to nil

@rafaelfranca rafaelfranca and 1 other commented on an outdated diff Sep 19, 2012

actionmailer/lib/action_mailer/log_subscriber.rb
@@ -1,13 +1,15 @@
module ActionMailer
class LogSubscriber < ActiveSupport::LogSubscriber
def deliver(event)
+ return unless logger.debug?
@rafaelfranca

rafaelfranca Sep 19, 2012

Owner

This doesn't make sense. Why check debug? if we are using info?

@bdurand

bdurand Sep 19, 2012

Contributor

My bad. I didn't look carefully enough. I just just saw the debug at the bottom of the method.

@rafaelfranca

rafaelfranca Sep 19, 2012

Owner

I think we need to check info and debug

Owner

rafaelfranca commented Sep 19, 2012

BTW I agree with the optimization, but some methods use different log levels. We need to do more work on this.

@rafaelfranca rafaelfranca commented on the diff Sep 19, 2012

actionmailer/lib/action_mailer/log_subscriber.rb
@@ -1,13 +1,15 @@
module ActionMailer
class LogSubscriber < ActiveSupport::LogSubscriber
def deliver(event)
+ return unless logger.info?
@rafaelfranca

rafaelfranca Sep 19, 2012

Owner

I think we need to check logger.info? || logger.debug?

@bdurand

bdurand Sep 20, 2012

Contributor

The log levels are a hierarchy so logger.info? should be enough.

@rafaelfranca

rafaelfranca Sep 20, 2012

Owner

I see, thanks

@rafaelfranca rafaelfranca commented on the diff Sep 19, 2012

activerecord/lib/active_record/log_subscriber.rb
@@ -1,11 +1,13 @@
module ActiveRecord
class LogSubscriber < ActiveSupport::LogSubscriber
+ IGNORE_PAYLOAD_NAMES = ["SCHEMA", "EXPLAIN"]
@rafaelfranca

rafaelfranca Sep 19, 2012

Owner

I don't know if we can ignore these payloads. cc @fxn

@bdurand

bdurand Sep 19, 2012

Contributor

SCHEMA was already being ignored.

I'd like to ignore Explain as well because when a query triggers the auto explain by passing the threshold, the original query and the query plan will be logged. It's not that interesting to see the Explain query logged as well.

By itself this isn't an issue, but there are other debugging gems that hook into ActiveRecord to force explain plans on every query which ends up logging quite a bit of useless queries.

Owner

fxn commented Sep 20, 2012

👍 on not logging EXPLAIN.

Owner

rafaelfranca commented Sep 20, 2012

Ok. @bdurand could you add a CHANGELOG entry and squash you commits?

"%.1f" % x is not quite the same as x.round(1).to_s. For instance:

"%.1f" % 0.95  # ===> "0.9"

0.95.round(1).to_s # ===> "1.0"

Not sure if it's a big deal, but is there a reason to make this change all over the place?

Owner

bdurand replied Sep 21, 2012

There's not really a pressing reason for this optimization (the main optimization was on the action pack subscribers to bypass logic if necessary). This was just a slight optimization. I do think that the round implementation would be more correct, though.

Contributor

bdurand commented Sep 30, 2012

@rafaelfranca I squashed commits and added change log. I'm not sure if I pushed it correctly since it was already pushed to a remote branch. Let me know if you need a new (clean) pull request.

rafaelfranca added a commit that referenced this pull request Oct 2, 2012

Merge pull request #7708 from bdurand/optimize_log_subscribers
Optimize log subscribers to check if the log level is sufficient

@rafaelfranca rafaelfranca merged commit cfc0ca0 into rails:master Oct 2, 2012

Owner

rafaelfranca commented Oct 2, 2012

Merged. Thanks

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment