Mongo 1.6.2 logging

24 Dec 2012

I will separate it into an independent gem later, but here is how I log all the database queries and log the summary usage per request.

Rails has a built-in mechanism for instrumenting the things that we want. The Rails' instrument mechanism enables us to log the total time spent on operations we are interested.

In my case, it is Mongo's operation. In the log message, I will see something like:

Completed 200 OK in 2240ms (Views: 2169.4ms | Solr: 0.0ms | Mongo : 65.6ms | Mongo queries: 10 times)

First of all, we need to surround the thing we want to measure with `ActiveSupport::Notifications.instrumenter.instrument "op.mongo" { }`.

In this case, we want to instrument all operations of Mongo. So, I name it `op.mongo. We have to name our instrument's point with this convention: ``<action>,<namespace>```.

I've found that Mongo has its own instrument mechanism, which is used for logging. So, I just hook Rails' instrument into it. The code is shown below:

module Mongo [Collection, Connection, Cursor].each do |clazz| clazz.class_eval do def instrument(name, payload = {}, &blk) start_time = res = ActiveSupport::Notifications.instrumenter.instrument "op.mongo" do yield end log_operation(name, payload, start_time) res end def log_operation(name, payload, start_time)"Log something here with duration") end end end end

The code above log individual operations and also log the duration for the summary.

We solve the problem of logging individual query already.

Now in order to log the summary properly, we have to define 2 more classes:

class LogSubscriber < ActiveSupport::LogSubscriber RUNTIME_KEY = name + "#runtime" COUNT_KEY = name + "#count" def self.runtime=(value) Thread.current[RUNTIME_KEY] = value end def self.runtime Thread.current[RUNTIME_KEY] ||= 0 end def self.count=(value) Thread.current[COUNT_KEY] = value end def self.count Thread.current[COUNT_KEY] ||= 0 end def self.reset_runtime rt = runtime this_count = count self.runtime, self.count = 0, 0 [rt, this_count] end def op(event) self.class.runtime += event.duration self.class.count += 1 end end LogSubscriber.attach_to :mongo

Please ignore other details except `def op. Since we name our instrument as ``op.mongo`, we need to callattach_to`` in order to attach `LogSubscriberto the namespace ``mongo`. And whenever the instrument ofop.mongo`` is called, the `def op` will be called with the event's information.

Now we already log the summary of operations. Next, we need a way to reset the `runtimeand ``count```, and we need a way to print the information along with the standard Rails' summarized log.

I'm too lazy to explain it…. Here is the code:

module ControllerRuntime extend ActiveSupport::Concern protected attr_internal :mongo_runtime, :mongo_count def process_action(action, *args) LogSubscriber.reset_runtime super end def cleanup_view_runtime mongo_rt_before_render, count_before_render = LogSubscriber.reset_runtime runtime = super mongo_rt_after_render, count_after_render = LogSubscriber.reset_runtime self.mongo_runtime = mongo_rt_before_render + mongo_rt_after_render self.mongo_count = count_before_render + count_after_render runtime - mongo_rt_after_render end def append_info_to_payload(payload) super payload[:mongo_runtime] = mongo_runtime payload[:mongo_count] = mongo_count end module ClassMethods def log_process_action(payload) messages, mongo_runtime, mongo_count = super, payload[:mongo_runtime], payload[:mongo_count] messages << ("Mongo : %.1fms" % mongo_runtime.to_f) if mongo_runtime messages << ("Mongo queries: #{mongo_count} times") if mongo_count messages end end end ActiveSupport.on_load(:action_controller) do include ControllerRuntime end