我调试rails代码的习惯是边看代码边看日志，通过日志你可以看到每一处rails对DB的操作。这在web开发看来还是挺简单，只有在少数情况下才去使用pry或者debugger去调试代码。一来直接看日志就大致上可以看到你写的代码执行的逻辑，比如执行insert语句的时候你大概也能猜到应该是调用了 Model.create 方法。直接看日志这种方式比较便捷。但是默认rails是把所有的sql都显示在日志里面的，实际上我们关心的无非是insert/update/delete语句，至于select基本上不太关心了。但是项目逻辑一旦复杂，一个请求有上百条sql的时候，就不太容易找到insert/update/delete了。所以制作了一个gem，用来高亮insert/update/delete语句。自我感觉还不错，可以在github上找到（https://github.com/xumc/simple-debug-for-rails/tree/v1.0.0）。目前还比较简陋，以后慢慢完善。见图：
gem的事情暂且不表，下面讲讲rails中的log 相关代码。这也是为了写这个gem才看这部分代码。
涉及到log相关的rb文件如下图：
rails caicai$ tree -C -f|grep "subscribe\|notifications"
│ │ │ ├── ./actionmailer/lib/action_mailer/log_subscriber.rb
│ ├── ./actionmailer/test/log_subscriber_test.rb
│ │ │ ├── ./actionpack/lib/action_controller/log_subscriber.rb
│ │ ├── ./actionpack/test/controller/log_subscriber_test.rb
│ │ │ ├── ./actionview/lib/action_view/log_subscriber.rb
│ │ ├── ./actionview/test/template/log_subscriber_test.rb
│ │ │ ├── ./activerecord/lib/active_record/explain_subscriber.rb
│ │ │ ├── ./activerecord/lib/active_record/log_subscriber.rb
│ │ ├── ./activerecord/test/cases/explain_subscriber_test.rb
│ │ ├── ./activerecord/test/cases/log_subscriber_test.rb
│ │ ├── ./activerecord/test/fixtures/subscribers.yml
│ │ ├── ./activerecord/test/models/subscriber.rb
│ │ │ ├── ./activesupport/lib/active_support/log_subscriber
│ │ │ │ └── ./activesupport/lib/active_support/log_subscriber/test_helper.rb
│ │ │ ├── ./activesupport/lib/active_support/log_subscriber.rb
│ │ │ ├── ./activesupport/lib/active_support/notifications
│ │ │ │ ├── ./activesupport/lib/active_support/notifications/fanout.rb
│ │ │ │ └── ./activesupport/lib/active_support/notifications/instrumenter.rb
│ │ │ ├── ./activesupport/lib/active_support/notifications.rb
│ │ │ ├── ./activesupport/lib/active_support/subscriber.rb
│ ├── ./activesupport/test/log_subscriber_test.rb
│ ├── ./activesupport/test/notifications
│ │ ├── ./activesupport/test/notifications/evented_notification_test.rb
│ │ └── ./activesupport/test/notifications/instrumenter_test.rb
│ ├── ./activesupport/test/notifications_test.rb
│ ├── ./activesupport/test/subscriber_test.rb
│ │ │ └── ./railties/test/application/initializers/notifications_test.rb
很明显，rails会使用pub/sub方式记录日志。类似于消息队列的意思。 比如执行sql的时候会生成sql事件， log订阅者则能够接受到这些sql事件，并且把相关的信息记录到log中。这样就避免了在代码里面直接写logger.debug/info/error 等语句。将log和其他组件进行解耦。从上面的文件树可以看出rails的各大组件均有一个log_subscriber.rb文件。里面的代码便是捕获组件内部产生的event并且将event信息写到log文件的代码。
以/activerecord/lib/active_record/log_subscriber.rb为例：
module ActiveRecord
class LogSubscriber < ActiveSupport::LogSubscriber
IGNORE_PAYLOAD_NAMES = ["SCHEMA", "EXPLAIN"]
def self.runtime=(value)
ActiveRecord::RuntimeRegistry.sql_runtime = value
end
def self.runtime
ActiveRecord::RuntimeRegistry.sql_runtime ||= 0
end
def self.reset_runtime
rt, self.runtime = runtime, 0
rt
end
def initialize
super
@odd = false
end
def render_bind(column, value)
if column
if column.binary?
# This specifically deals with the PG adapter that casts bytea columns into a Hash.
value = value[:value] if value.is_a?(Hash)
value = value ? "<#{value.bytesize} bytes of binary data>" : "<NULL binary data>"
end
[column.name, value]
else
[nil, value]
end
end
def sql(event)
self.class.runtime += event.duration
return unless logger.debug?
payload = event.payload
return if IGNORE_PAYLOAD_NAMES.include?(payload[:name])
name = "#{payload[:name]} (#{event.duration.round(1)}ms)"
sql = payload[:sql]
binds = nil
unless (payload[:binds] || []).empty?
binds = " " + payload[:binds].map { |col,v|
render_bind(col, v)
}.inspect
end
if odd?
name = color(name, CYAN, true)
sql = color(sql, nil, true)
else
name = color(name, MAGENTA, true)
end
debug " #{name} #{sql}#{binds}"
end
def odd?
@odd = [email protected]
end
def logger
ActiveRecord::Base.logger
end
end
end
ActiveRecord::LogSubscriber.attach_to :active_record
这个类继承自ActiveSupport::LogSubscriber这个类，联系到上面的文件结构，可以猜出ActiveSupport::LogSubscriber应该是rails各大组件中的LogSubscriber的基类。active_record中的这个类主要的函数sql(event)将event中的信息转换成伟log文本调用debug方式存储到log中。 文件最后一句使用 attach_to 意为用这个类来监听active_record产生的事件。
再来看看ActiveSupport::LogSubscriber这个类：
module ActiveSupport
class LogSubscriber < Subscriber
# Embed in a String to clear all previous ANSI sequences.
CLEAR = "\e[0m"
BOLD = "\e[1m"
# Colors
BLACK = "\e[30m"
RED = "\e[31m"
GREEN = "\e[32m"
YELLOW = "\e[33m"
BLUE = "\e[34m"
MAGENTA = "\e[35m"
CYAN = "\e[36m"
WHITE = "\e[37m"
mattr_accessor :colorize_logging
self.colorize_logging = true
class << self
def logger
@logger ||= if defined?(Rails) && Rails.respond_to?(:logger)
Rails.logger
end
end
attr_writer :logger
def log_subscribers
subscribers
end
# Flush all log_subscribers' logger.
def flush_all!
logger.flush if logger.respond_to?(:flush)
end
end
def logger
LogSubscriber.logger
end
def start(name, id, payload)
super if logger
end
def finish(name, id, payload)
super if logger
rescue Exception => e
logger.error "Could not log #{name.inspect} event. #{e.class}: #{e.message} #{e.backtrace}"
end
protected
%w(info debug warn error fatal unknown).each do |level|
class_eval <<-METHOD, __FILE__, __LINE__ + 1
def #{level}(progname = nil, &block)
logger.#{level}(progname, &block) if logger
end
METHOD
end
# Set color by using a string or one of the defined constants. If a third
# option is set to +true+, it also adds bold to the string. This is based
# on the Highline implementation and will automatically append CLEAR to the
# end of the returned String.
def color(text, color, bold=false)
return text unless colorize_logging
color = self.class.const_get(color.upcase) if color.is_a?(Symbol)
bold = bold ? BOLD : ""
"#{bold}#{color}#{text}#{CLEAR}"
end
end
end
其方法还算中规中矩的辅助方法， 这是这个类又继承自subscribe类，这里很明显了，这个subscribe类应该写着一个pub/sub机制的一些方法，并非仅仅是log机制使用。打开看看：
module ActiveSupport
# ActiveSupport::Subscriber is an object set to consume
# ActiveSupport::Notifications. The subscriber dispatches notifications to
# a registered object based on its given namespace.
#
# An example would be Active Record subscriber responsible for collecting
# statistics about queries:
#
# module ActiveRecord
# class StatsSubscriber < ActiveSupport::Subscriber
# def sql(event)
# Statsd.timing("sql.#{event.payload[:name]}", event.duration)
# end
# end
# end
#
# And it's finally registered as:
#
# ActiveRecord::StatsSubscriber.attach_to :active_record
#
# Since we need to know all instance methods before attaching the log
# subscriber, the line above should be called after your subscriber definition.
#
# After configured, whenever a "sql.active_record" notification is published,
# it will properly dispatch the event (ActiveSupport::Notifications::Event) to
# the +sql+ method.
class Subscriber
class << self
# Attach the subscriber to a namespace.
def attach_to(namespace, subscriber=new, notifier=ActiveSupport::Notifications)
@namespace = namespace
@subscriber = subscriber
@notifier = notifier
subscribers << subscriber
# Add event subscribers for all existing methods on the class.
subscriber.public_methods(false).each do |event|
add_event_subscriber(event)
end
end
# Adds event subscribers for all new methods added to the class.
def method_added(event)
# Only public methods are added as subscribers, and only if a notifier
# has been set up. This means that subscribers will only be set up for
# classes that call #attach_to.
if public_method_defined?(event) && notifier
add_event_subscriber(event)
end
end
def subscribers
@@subscribers ||= []
end
protected
attr_reader :subscriber, :notifier, :namespace
def add_event_subscriber(event)
return if %w{ start finish }.include?(event.to_s)
pattern = "#{event}.#{namespace}"
# don't add multiple subscribers (eg. if methods are redefined)
return if subscriber.patterns.include?(pattern)
subscriber.patterns << pattern
notifier.subscribe(pattern, subscriber)
end
end
attr_reader :patterns # :nodoc:
def initialize
@queue_key = [self.class.name, object_id].join "-"
@patterns = []
super
end
def start(name, id, payload)
e = ActiveSupport::Notifications::Event.new(name, Time.now, nil, id, payload)
parent = event_stack.last
parent << e if parent
event_stack.push e
end
def finish(name, id, payload)
finished = Time.now
event = event_stack.pop
event.end = finished
event.payload.merge!(payload)
method = name.split('.').first
send(method, event)
end
private
def event_stack
SubscriberQueueRegistry.instance.get_queue(@queue_key)
end
end
# This is a registry for all the event stacks kept for subscribers.
#
# See the documentation of <tt>ActiveSupport::PerThreadRegistry</tt>
# for further details.
class SubscriberQueueRegistry # :nodoc:
extend PerThreadRegistry
def initialize
@registry = {}
end
def get_queue(queue_key)
@registry[queue_key] ||= []
end
end
end
也不是很难懂。 就是定义了公共的行为。