From 288f0d48a15f05db7cc7ddfd9d768b97141fa622 Mon Sep 17 00:00:00 2001 From: Tom Ward Date: Fri, 18 Feb 2011 12:44:19 +0000 Subject: [PATCH] Another post, on mongo instrumentation --- public/2.html | 71 ++++---- public/2011/02.html | 111 +++++++++++++ .../experimental-mongo-instrumentation.html | 149 +++++++++++++++++ public/3.html | 89 ++++------ public/4.html | 87 ++++++---- public/5.html | 46 +++-- public/6.html | 74 ++------- public/7.html | 100 +++++++++++ public/atom.xml | 157 +++++++++++++----- public/index.html | 148 ++++++++++++----- public/sitemap.xml | 5 + public/tags/instrumentation.html | 151 +++++++++++++++++ public/tags/mongo.html | 151 +++++++++++++++++ public/tags/rails.html | 111 +++++++++++++ public/tags/rails3.html | 111 +++++++++++++ public/tags/ruby.html | 111 +++++++++++++ source/_layouts/default.html | 2 +- source/css/style.less | 10 +- ...d-columns-directly-from-the-class.markdown | 2 +- source/posts/2010-01-26-asdasdasd.markdown | 7 - ...2-11-rails-3-direct-column-reader.markdown | 2 +- ...pdated-rails-template-for-bundler.markdown | 5 + source/posts/_payload.lanyon.yml | 3 - source/scraps/_payload.lanyon.yml | 4 - 24 files changed, 1413 insertions(+), 294 deletions(-) create mode 100644 public/2011/02/experimental-mongo-instrumentation.html create mode 100644 public/7.html create mode 100644 public/tags/instrumentation.html create mode 100644 public/tags/mongo.html delete mode 100644 source/posts/2010-01-26-asdasdasd.markdown delete mode 100644 source/posts/_payload.lanyon.yml delete mode 100644 source/scraps/_payload.lanyon.yml diff --git a/public/2.html b/public/2.html index 4035043..a9d763c 100644 --- a/public/2.html +++ b/public/2.html @@ -34,6 +34,43 @@
+
+

Tip: Relative paths with File.expand_path

+

You probably know about the __FILE__ magic constant. It holds the filename of the currently executing ruby source file, relative to the execution directory. So with the following saved as /code/examples/path_example.rb:

+ +
puts __FILE__
+
+
+ + +

Running this file from the /code folder will output examples/path_example.rb

+ +

This is often used to load files on paths relative to the current file. The way I've used it before is like this:

+ +
config_path = File.expand_path(File.join(File.dirname(__FILE__), "config.yml"))
+
+
+ + +

This works, but it's a bit clunky.

+ +

What I didn't realise until reading the rails source code the other day, is that File.expand_path can take a second argument - a starting directory. Also, this argument doesn't actually have to be a path to a directory, it also accepts a path to a file. With this knowledge we can shorten the above to the following:

+ +
config_path = File.expand_path("../config.yml", __FILE__)
+
+
+ + +

Much simpler.

+ +
+
+ Tom Ward · + 23rd January 2010 + · · · · · +
+
+

Taking screenshots of web pages with macruby

Whilst playing around with the very exciting macruby last weekend, I thought I'd try building a web page screenshot grabber, based on Ben Curtis' code. The code was very easy to change translate from rubycocoa, looks cleaner and seems to work really well:

@@ -340,40 +377,6 @@

Update 28th February 2010:

-
-

Tip: cdpath - Am I the last to know?

-

This one is just so simple, I can't believe I didn't know about it earlier.

- -

First, setup the cdpath or CDPATH variable:

- -
cdpath=(~ ~/Projects/apps ~/Projects/tools ~/Projects/plugins ~/Projects/sites)
-
-
- - -

Now, changing directory in the shell becomes a whole world easier:

- -
tomw@fellini:~$ cd super-secret-app
-~/Projects/apps/super-secret-app
-tomw@fellini:~/Projects/apps/super-secret-app$ cd Documents
-~/Documents
-tomw@fellini:~/Documents$ cd tomafro.net
-~/Projects/sites/tomafro.net
-tomw@fellini:~/Projects/sites/tomafro.net $
-
-
- - -

I've already added this to my dotfiles.

- -
-
- Tom Ward · - 6th October 2009 - · · · · · -
-
-
diff --git a/public/2011/02.html b/public/2011/02.html index 3d87dda..20c8d2e 100644 --- a/public/2011/02.html +++ b/public/2011/02.html @@ -33,6 +33,117 @@
+
+

Experimental Mongo Instrumentation (for Rails 3)

+

One of our latest rails projects uses Mongo as a backend. We're just starting to get some traffic, and as we do, we're monitoring the logs for slow requests. When using ActiveRecord, rails splits out the recorded request time like so:

+ +
    Completed 200 OK in 6ms (Views 370.5ms | ActiveRecord: 2.3ms)
+
+
+ + +

We wanted to do the same for our Mongo accesses, just to give a rough idea as to what our requests were doing. Luckily Rails 3 makes this relatively straightforward, providing hooks to instrument methods, subscribe to log messages and add information to the request log. Here, then, is my first stab (mainly harvested from ActiveRecord):

+ +
module Mongo
+  module Instrumentation
+    def self.instrument(clazz, *methods)
+      clazz.module_eval do
+        methods.each do |m|
+          class_eval %{def #{m}_with_instrumentation(*args)
+            ActiveSupport::Notifications.instrumenter.instrument "mongo.mongo", :name => "#{m}" do
+              #{m}_without_instrumentation(*args)
+            end
+          end
+          }
+
+          alias_method_chain m, :instrumentation
+        end
+      end
+    end
+
+    class Railtie < Rails::Railtie
+      initializer "mongo.instrumentation" do |app|
+        Mongo::Instrumentation.instrument Mongo::Collection, :find, :save, :insert, :update
+        Mongo::Instrumentation.instrument Mongo::DB, :command
+
+        ActiveSupport.on_load(:action_controller) do
+          include Mongo::Instrumentation::ControllerRuntime
+        end
+
+        Mongo::Instrumentation::LogSubscriber.attach_to :mongo
+      end
+    end
+
+    module ControllerRuntime
+      extend ActiveSupport::Concern
+
+      protected
+
+      attr_internal :mongo_runtime
+
+      def cleanup_view_runtime
+        mongo_rt_before_render = Mongo::Instrumentation::LogSubscriber.reset_runtime
+        runtime = super
+        mongo_rt_after_render = Mongo::Instrumentation::LogSubscriber.reset_runtime
+        self.mongo_runtime = mongo_rt_before_render + mongo_rt_after_render
+        runtime - mongo_rt_after_render
+      end
+
+      def append_info_to_payload(payload)
+        super
+        payload[:mongo_runtime] = mongo_runtime
+      end
+
+      module ClassMethods
+        def log_process_action(payload)
+          messages, mongo_runtime = super, payload[:mongo_runtime]
+          messages << ("Mongo: %.1fms" % mongo_runtime.to_f) if mongo_runtime
+          messages
+        end
+      end
+    end
+
+    class LogSubscriber < ActiveSupport::LogSubscriber
+      def self.runtime=(value)
+        Thread.current["mongo_mongo_runtime"] = value
+      end
+
+      def self.runtime
+        Thread.current["mongo_mongo_runtime"] ||= 0
+      end
+
+      def self.reset_runtime
+        rt, self.runtime = runtime, 0
+        rt
+      end
+
+      def mongo(event)
+        self.class.runtime += event.duration
+      end
+    end
+  end
+end
+
+
+ + +

It looks complicated, but it's actually pretty simple. Data access methods in Mongo::DB and Mongo::Collection are hijacked and surrounded by an ActiveSupport::Notifications.instrumenter.instrument block. This triggers events which are listened to by the LogSubscriber, summing the total time spent in Mongo. The ControllerRuntime then collects this count to be displayed, and resets the sum to zero ready for the next request. The output looks like this:

+ +
    Completed 200 OK in 838ms (Views: 370.5ms | ActiveRecord: 2.3ms | Mongo: 441.5ms)
+
+
+ + +

It's just a first stab, so any comments and improvements are more then welcome. It's here on gist so please fork away.

+ +
+
+ Tom Ward · + 18th February 2011 + · · · · · +
+
+

A home for my Active Record column reader

@kraykray was nice enough to let me know that Rails 3.03 had broken my column-reader code.

diff --git a/public/2011/02/experimental-mongo-instrumentation.html b/public/2011/02/experimental-mongo-instrumentation.html new file mode 100644 index 0000000..4356a32 --- /dev/null +++ b/public/2011/02/experimental-mongo-instrumentation.html @@ -0,0 +1,149 @@ + + + + + Experimental Mongo Instrumentation (for Rails 3) · tomafro.net + + + + + + + + + + + + +
+
+ tomafro.net · about · on github · on delicious · on twitter · on last.fm +
+
+
+

Experimental Mongo Instrumentation (for Rails 3)

+

One of our latest rails projects uses Mongo as a backend. We're just starting to get some traffic, and as we do, we're monitoring the logs for slow requests. When using ActiveRecord, rails splits out the recorded request time like so:

+ +
    Completed 200 OK in 6ms (Views 370.5ms | ActiveRecord: 2.3ms)
+
+
+ + +

We wanted to do the same for our Mongo accesses, just to give a rough idea as to what our requests were doing. Luckily Rails 3 makes this relatively straightforward, providing hooks to instrument methods, subscribe to log messages and add information to the request log. Here, then, is my first stab (mainly harvested from ActiveRecord):

+ +
module Mongo
+  module Instrumentation
+    def self.instrument(clazz, *methods)
+      clazz.module_eval do
+        methods.each do |m|
+          class_eval %{def #{m}_with_instrumentation(*args)
+            ActiveSupport::Notifications.instrumenter.instrument "mongo.mongo", :name => "#{m}" do
+              #{m}_without_instrumentation(*args)
+            end
+          end
+          }
+
+          alias_method_chain m, :instrumentation
+        end
+      end
+    end
+
+    class Railtie < Rails::Railtie
+      initializer "mongo.instrumentation" do |app|
+        Mongo::Instrumentation.instrument Mongo::Collection, :find, :save, :insert, :update
+        Mongo::Instrumentation.instrument Mongo::DB, :command
+
+        ActiveSupport.on_load(:action_controller) do
+          include Mongo::Instrumentation::ControllerRuntime
+        end
+
+        Mongo::Instrumentation::LogSubscriber.attach_to :mongo
+      end
+    end
+
+    module ControllerRuntime
+      extend ActiveSupport::Concern
+
+      protected
+
+      attr_internal :mongo_runtime
+
+      def cleanup_view_runtime
+        mongo_rt_before_render = Mongo::Instrumentation::LogSubscriber.reset_runtime
+        runtime = super
+        mongo_rt_after_render = Mongo::Instrumentation::LogSubscriber.reset_runtime
+        self.mongo_runtime = mongo_rt_before_render + mongo_rt_after_render
+        runtime - mongo_rt_after_render
+      end
+
+      def append_info_to_payload(payload)
+        super
+        payload[:mongo_runtime] = mongo_runtime
+      end
+
+      module ClassMethods
+        def log_process_action(payload)
+          messages, mongo_runtime = super, payload[:mongo_runtime]
+          messages << ("Mongo: %.1fms" % mongo_runtime.to_f) if mongo_runtime
+          messages
+        end
+      end
+    end
+
+    class LogSubscriber < ActiveSupport::LogSubscriber
+      def self.runtime=(value)
+        Thread.current["mongo_mongo_runtime"] = value
+      end
+
+      def self.runtime
+        Thread.current["mongo_mongo_runtime"] ||= 0
+      end
+
+      def self.reset_runtime
+        rt, self.runtime = runtime, 0
+        rt
+      end
+
+      def mongo(event)
+        self.class.runtime += event.duration
+      end
+    end
+  end
+end
+
+
+ + +

It looks complicated, but it's actually pretty simple. Data access methods in Mongo::DB and Mongo::Collection are hijacked and surrounded by an ActiveSupport::Notifications.instrumenter.instrument block. This triggers events which are listened to by the LogSubscriber, summing the total time spent in Mongo. The ControllerRuntime then collects this count to be displayed, and resets the sum to zero ready for the next request. The output looks like this:

+ +
    Completed 200 OK in 838ms (Views: 370.5ms | ActiveRecord: 2.3ms | Mongo: 441.5ms)
+
+
+ + +

It's just a first stab, so any comments and improvements are more then welcome. It's here on gist so please fork away.

+ +
+
+ Tom Ward · + 18th February 2011 + · · · · · +
+
+ +
+
+ + \ No newline at end of file diff --git a/public/3.html b/public/3.html index bf30a7b..f0c3b4c 100644 --- a/public/3.html +++ b/public/3.html @@ -34,6 +34,40 @@
+
+

Tip: cdpath - Am I the last to know?

+

This one is just so simple, I can't believe I didn't know about it earlier.

+ +

First, setup the cdpath or CDPATH variable:

+ +
cdpath=(~ ~/Projects/apps ~/Projects/tools ~/Projects/plugins ~/Projects/sites)
+
+
+ + +

Now, changing directory in the shell becomes a whole world easier:

+ +
tomw@fellini:~$ cd super-secret-app
+~/Projects/apps/super-secret-app
+tomw@fellini:~/Projects/apps/super-secret-app$ cd Documents
+~/Documents
+tomw@fellini:~/Documents$ cd tomafro.net
+~/Projects/sites/tomafro.net
+tomw@fellini:~/Projects/sites/tomafro.net $
+
+
+ + +

I've already added this to my dotfiles.

+ +
+
+ Tom Ward · + 6th October 2009 + · · · · · +
+
+

Tip: The case for from_param

There's one small method I add to every new rails project I work on:

@@ -372,61 +406,6 @@

A technique for choosing index column order

-
-

ZSH Completion for gem and gem open

-

I've been trying to get my head around the ZSH completion system. It's not easy, but I'm slowly making progress.

- -

Here's my first semi-successful attempt. It provides command completion for gem (including installed commands) and gem name completion for specific gem commands (update, and open from Adam Sanderson).

- -

So typing gem <tab> gives a list of possible commands, whilst gem open <tab> will complete with the names of the currently installed gems.

- -
#compdef gem
-
-_gem_commands () {
-  if [[ -z $gem_commands ]] ; then
-    gem_commands=$(gem help commands | grep '^    [a-z]' | cut -d " " -f 5)
-  fi
-  
-  # This seems unnecessary, but if I try to set gem_commands to an array, it falls over.
- 
-  typeset -a gem_command_array
-  gem_command_array=($(echo $gem_commands))
-  compadd $gem_command_array
-}
- 
-_installed_gems () {
-  if [[ -z $installed_gems ]] ; then
-    installed_gems=($(gem list | grep '^[A-Za-z]' | cut -d " " -f 1))
-  fi
-  
-  typeset -a installed_gem_array
-  installed_gem_array=($(echo $installed_gems))
-  compadd $installed_gem_array
-}
- 
-if (( CURRENT == 2 )); then
-  _gem_commands
-else
-  if [[ $words[2] == open || $words[2] == update ]] ; then
-    _installed_gems
-  fi
-fi
-
-
- - -

As it's a first attempt, it's a long way from perfect. I've put it on gist, for other people to play with, and I'd appreciate any advice or improvements. Specifically I'd like to know how to avoid the use of both gem_command_array and gem_commands. I'd also like to know a better way to check if the given command is in the list [open, update].

- -

Please fork the gist, or tweet me with your suggestions.

- -
-
- Tom Ward · - 14th August 2009 - · · · · -
-
-
diff --git a/public/4.html b/public/4.html index e58e838..7576c3c 100644 --- a/public/4.html +++ b/public/4.html @@ -34,6 +34,61 @@
+
+

ZSH Completion for gem and gem open

+

I've been trying to get my head around the ZSH completion system. It's not easy, but I'm slowly making progress.

+ +

Here's my first semi-successful attempt. It provides command completion for gem (including installed commands) and gem name completion for specific gem commands (update, and open from Adam Sanderson).

+ +

So typing gem <tab> gives a list of possible commands, whilst gem open <tab> will complete with the names of the currently installed gems.

+ +
#compdef gem
+
+_gem_commands () {
+  if [[ -z $gem_commands ]] ; then
+    gem_commands=$(gem help commands | grep '^    [a-z]' | cut -d " " -f 5)
+  fi
+
+  # This seems unnecessary, but if I try to set gem_commands to an array, it falls over.
+
+  typeset -a gem_command_array
+  gem_command_array=($(echo $gem_commands))
+  compadd $gem_command_array
+}
+
+_installed_gems () {
+  if [[ -z $installed_gems ]] ; then
+    installed_gems=($(gem list | grep '^[A-Za-z]' | cut -d " " -f 1))
+  fi
+  
+  typeset -a installed_gem_array
+  installed_gem_array=($(echo $installed_gems))
+  compadd $installed_gem_array
+}
+
+if (( CURRENT == 2 )); then
+  _gem_commands
+else
+  if [[ $words[2] == open || $words[2] == update ]] ; then
+    _installed_gems
+  fi
+fi
+
+
+ + +

As it's a first attempt, it's a long way from perfect. I've put it on gist, for other people to play with, and I'd appreciate any advice or improvements. Specifically I'd like to know how to avoid the use of both gem_command_array and gem_commands. I'd also like to know a better way to check if the given command is in the list [open, update].

+ +

Please fork the gist, or tweet me with your suggestions.

+ +
+
+ Tom Ward · + 14th August 2009 + · · · · +
+
+ -
-

Kernel specific ZSH dotfiles

-

I work on a number of different machines, OS X based for development and Linux based for hosting. I've added various aliases and other commands to my shell, and use a github repository to share this configuration between these machines.

- -

This works well, but while most commands work commonly across Linux and OS X, there are some nasty differences. One example is ls which takes different arguments on both systems; the default ls alias I use on OS X doesn't work on Linux. So how can we accommodate these differences, without removing all the shared configuration?

- -

The answer is really simple. Create kernel specific configuration files, and use a case statement to load the correct one. The main obstacle was finding a way to distinguish between each kernel. In the end I found the $system_name environment variable, which is set on both OS X and the servers I use.

- -

Here's the code:

- -
case $system_name in
-  Darwin*)
-    source ~/.houseshare/zsh/kernel/darwin.zsh
-    ;;
-  *)
-    source ~/.houseshare/zsh/kernel/linux.zsh
-    ;;;
-esac
-
-
- - -

As I said, simple.

- -
-
- Tom Ward · - 3rd August 2009 - · · · · -
-
-
diff --git a/public/5.html b/public/5.html index 76c6629..677f2a0 100644 --- a/public/5.html +++ b/public/5.html @@ -34,6 +34,38 @@
+
+

Kernel specific ZSH dotfiles

+

I work on a number of different machines, OS X based for development and Linux based for hosting. I've added various aliases and other commands to my shell, and use a github repository to share this configuration between these machines.

+ +

This works well, but while most commands work commonly across Linux and OS X, there are some nasty differences. One example is ls which takes different arguments on both systems; the default ls alias I use on OS X doesn't work on Linux. So how can we accommodate these differences, without removing all the shared configuration?

+ +

The answer is really simple. Create kernel specific configuration files, and use a case statement to load the correct one. The main obstacle was finding a way to distinguish between each kernel. In the end I found the $system_name environment variable, which is set on both OS X and the servers I use.

+ +

Here's the code:

+ +
case $system_name in
+  Darwin*)
+    source ~/.houseshare/zsh/kernel/darwin.zsh
+    ;;
+  *)
+    source ~/.houseshare/zsh/kernel/linux.zsh
+    ;;;
+esac
+
+
+ + +

As I said, simple.

+ +
+
+ Tom Ward · + 3rd August 2009 + · · · · +
+
+ - -
diff --git a/public/6.html b/public/6.html index 41d5244..76f9ab7 100644 --- a/public/6.html +++ b/public/6.html @@ -34,6 +34,20 @@
+ + -
-

Adam Sanderson's open_gem

-

The latest version of rubygems (1.3.2) now has an interface to add commands. Making great use of this feature, Adam Sanderson has written open_gem, a simple but amazingly useful tool.

- -

You use it like this:

- -
$ gem open activerecord
-
-
- - -

This opens the activerecord gem in your favourite editor (taken from either $GEM_OPEN_EDITOR or $EDITOR environment variables). If there are multiple versions of the gem installed, it will show a menu, letting you choose which version you require.

- -
$ gem open activerecord
-Open which gem?
- 1. activerecord 2.1.0
- 2. activerecord 2.3.2
-> 
-
-
- - -

open_gem itself is a gem, and can be installed with:

- -
$ gem install open_gem
-
-
- - -

To get it working, you need to have $EDITOR set to something sensible:

- -
$ export EDITOR=mate
-
-
- - -

If you're running on OS X and use TextMate, you may have already set $EDITOR to mate -w, which let's you use TextMate as the editor for git commit messages and much more. However, the -w flag doesn't work with open_gem, so set the $GEM_OPEN_EDITOR variable, and open_gem will use that instead:

- -
$ export GEM_OPEN_EDITOR=mate
-
-
- - -

You should now be good to go. If you want to see how it works, just use it on itself!

- -
$ gem open open_gem
-
-
- - - - -
-
- Tom Ward · - 6th May 2009 - · · · · -
-
-
diff --git a/public/7.html b/public/7.html new file mode 100644 index 0000000..0b5beb5 --- /dev/null +++ b/public/7.html @@ -0,0 +1,100 @@ + + + + + Tom Ward's blog · tomafro.net + + + + + + + + + + + + + +
+
+ tomafro.net · about · on github · on delicious · on twitter · on last.fm +
+
+ +
+

Adam Sanderson's open_gem

+

The latest version of rubygems (1.3.2) now has an interface to add commands. Making great use of this feature, Adam Sanderson has written open_gem, a simple but amazingly useful tool.

+ +

You use it like this:

+ +
$ gem open activerecord
+
+
+ + +

This opens the activerecord gem in your favourite editor (taken from either $GEM_OPEN_EDITOR or $EDITOR environment variables). If there are multiple versions of the gem installed, it will show a menu, letting you choose which version you require.

+ +
$ gem open activerecord
+Open which gem?
+ 1. activerecord 2.1.0
+ 2. activerecord 2.3.2
+> 
+
+
+ + +

open_gem itself is a gem, and can be installed with:

+ +
$ gem install open_gem
+
+
+ + +

To get it working, you need to have $EDITOR set to something sensible:

+ +
$ export EDITOR=mate
+
+
+ + +

If you're running on OS X and use TextMate, you may have already set $EDITOR to mate -w, which let's you use TextMate as the editor for git commit messages and much more. However, the -w flag doesn't work with open_gem, so set the $GEM_OPEN_EDITOR variable, and open_gem will use that instead:

+ +
$ export GEM_OPEN_EDITOR=mate
+
+
+ + +

You should now be good to go. If you want to see how it works, just use it on itself!

+ +
$ gem open open_gem
+
+
+ + + + +
+
+ Tom Ward · + 6th May 2009 + · · · · +
+
+ +
+
+ + \ No newline at end of file diff --git a/public/atom.xml b/public/atom.xml index c276a5a..42e277f 100644 --- a/public/atom.xml +++ b/public/atom.xml @@ -9,6 +9,123 @@ tom@popdog.net + + http://tomafro.net + + Experimental Mongo Instrumentation (for Rails 3) + + Tom Ward + tom@popdog.net + + <p>One of our latest rails projects uses <a href="http://mongodb.org">Mongo</a> as a backend. We're just starting to get some traffic, and as we do, we're monitoring the logs for slow requests. When using ActiveRecord, rails splits out the recorded request time like so:</p> + +<div class="highlight"><pre> Completed 200 OK in 6ms (Views 370.5ms | ActiveRecord: 2.3ms) +</pre> +</div> + + +<p>We wanted to do the same for our Mongo accesses, just to give a rough idea as to what our requests were doing. Luckily Rails 3 makes this relatively straightforward, providing hooks to instrument methods, subscribe to log messages and add information to the request log. Here, then, is my first stab (mainly harvested from ActiveRecord):</p> + +<div class="highlight"><pre><span class="k">module</span> <span class="nn">Mongo</span> + <span class="k">module</span> <span class="nn">Instrumentation</span> + <span class="k">def</span> <span class="nc">self</span><span class="o">.</span><span class="nf">instrument</span><span class="p">(</span><span class="n">clazz</span><span class="p">,</span> <span class="o">*</span><span class="nb">methods</span><span class="p">)</span> + <span class="n">clazz</span><span class="o">.</span><span class="n">module_eval</span> <span class="k">do</span> + <span class="nb">methods</span><span class="o">.</span><span class="n">each</span> <span class="k">do</span> <span class="o">|</span><span class="n">m</span><span class="o">|</span> + <span class="nb">class_eval</span> <span class="sx">%{def </span><span class="si">#{</span><span class="n">m</span><span class="si">}</span><span class="sx">_with_instrumentation(*args)</span> +<span class="sx"> ActiveSupport::Notifications.instrumenter.instrument &quot;mongo.mongo&quot;, :name =&gt; &quot;</span><span class="si">#{</span><span class="n">m</span><span class="si">}</span><span class="sx">&quot; do</span> +<span class="sx"> </span><span class="si">#{</span><span class="n">m</span><span class="si">}</span><span class="sx">_without_instrumentation(*args)</span> +<span class="sx"> end</span> +<span class="sx"> end</span> +<span class="sx"> }</span> + + <span class="n">alias_method_chain</span> <span class="n">m</span><span class="p">,</span> <span class="ss">:instrumentation</span> + <span class="k">end</span> + <span class="k">end</span> + <span class="k">end</span> + + <span class="k">class</span> <span class="nc">Railtie</span> <span class="o">&lt;</span> <span class="no">Rails</span><span class="o">::</span><span class="no">Railtie</span> + <span class="n">initializer</span> <span class="s2">&quot;mongo.instrumentation&quot;</span> <span class="k">do</span> <span class="o">|</span><span class="n">app</span><span class="o">|</span> + <span class="no">Mongo</span><span class="o">::</span><span class="no">Instrumentation</span><span class="o">.</span><span class="n">instrument</span> <span class="no">Mongo</span><span class="o">::</span><span class="no">Collection</span><span class="p">,</span> <span class="ss">:find</span><span class="p">,</span> <span class="ss">:save</span><span class="p">,</span> <span class="ss">:insert</span><span class="p">,</span> <span class="ss">:update</span> + <span class="no">Mongo</span><span class="o">::</span><span class="no">Instrumentation</span><span class="o">.</span><span class="n">instrument</span> <span class="no">Mongo</span><span class="o">::</span><span class="no">DB</span><span class="p">,</span> <span class="ss">:command</span> + + <span class="no">ActiveSupport</span><span class="o">.</span><span class="n">on_load</span><span class="p">(</span><span class="ss">:action_controller</span><span class="p">)</span> <span class="k">do</span> + <span class="kp">include</span> <span class="no">Mongo</span><span class="o">::</span><span class="no">Instrumentation</span><span class="o">::</span><span class="no">ControllerRuntime</span> + <span class="k">end</span> + + <span class="no">Mongo</span><span class="o">::</span><span class="no">Instrumentation</span><span class="o">::</span><span class="no">LogSubscriber</span><span class="o">.</span><span class="n">attach_to</span> <span class="ss">:mongo</span> + <span class="k">end</span> + <span class="k">end</span> + + <span class="k">module</span> <span class="nn">ControllerRuntime</span> + <span class="kp">extend</span> <span class="no">ActiveSupport</span><span class="o">::</span><span class="no">Concern</span> + + <span class="kp">protected</span> + + <span class="n">attr_internal</span> <span class="ss">:mongo_runtime</span> + + <span class="k">def</span> <span class="nf">cleanup_view_runtime</span> + <span class="n">mongo_rt_before_render</span> <span class="o">=</span> <span class="no">Mongo</span><span class="o">::</span><span class="no">Instrumentation</span><span class="o">::</span><span class="no">LogSubscriber</span><span class="o">.</span><span class="n">reset_runtime</span> + <span class="n">runtime</span> <span class="o">=</span> <span class="k">super</span> + <span class="n">mongo_rt_after_render</span> <span class="o">=</span> <span class="no">Mongo</span><span class="o">::</span><span class="no">Instrumentation</span><span class="o">::</span><span class="no">LogSubscriber</span><span class="o">.</span><span class="n">reset_runtime</span> + <span class="nb">self</span><span class="o">.</span><span class="n">mongo_runtime</span> <span class="o">=</span> <span class="n">mongo_rt_before_render</span> <span class="o">+</span> <span class="n">mongo_rt_after_render</span> + <span class="n">runtime</span> <span class="o">-</span> <span class="n">mongo_rt_after_render</span> + <span class="k">end</span> + + <span class="k">def</span> <span class="nf">append_info_to_payload</span><span class="p">(</span><span class="n">payload</span><span class="p">)</span> + <span class="k">super</span> + <span class="n">payload</span><span class="o">[</span><span class="ss">:mongo_runtime</span><span class="o">]</span> <span class="o">=</span> <span class="n">mongo_runtime</span> + <span class="k">end</span> + + <span class="k">module</span> <span class="nn">ClassMethods</span> + <span class="k">def</span> <span class="nf">log_process_action</span><span class="p">(</span><span class="n">payload</span><span class="p">)</span> + <span class="n">messages</span><span class="p">,</span> <span class="n">mongo_runtime</span> <span class="o">=</span> <span class="k">super</span><span class="p">,</span> <span class="n">payload</span><span class="o">[</span><span class="ss">:mongo_runtime</span><span class="o">]</span> + <span class="n">messages</span> <span class="o">&lt;&lt;</span> <span class="p">(</span><span class="s2">&quot;Mongo: %.1fms&quot;</span> <span class="o">%</span> <span class="n">mongo_runtime</span><span class="o">.</span><span class="n">to_f</span><span class="p">)</span> <span class="k">if</span> <span class="n">mongo_runtime</span> + <span class="n">messages</span> + <span class="k">end</span> + <span class="k">end</span> + <span class="k">end</span> + + <span class="k">class</span> <span class="nc">LogSubscriber</span> <span class="o">&lt;</span> <span class="no">ActiveSupport</span><span class="o">::</span><span class="no">LogSubscriber</span> + <span class="k">def</span> <span class="nc">self</span><span class="o">.</span><span class="nf">runtime</span><span class="o">=</span><span class="p">(</span><span class="n">value</span><span class="p">)</span> + <span class="no">Thread</span><span class="o">.</span><span class="n">current</span><span class="o">[</span><span class="s2">&quot;mongo_mongo_runtime&quot;</span><span class="o">]</span> <span class="o">=</span> <span class="n">value</span> + <span class="k">end</span> + + <span class="k">def</span> <span class="nc">self</span><span class="o">.</span><span class="nf">runtime</span> + <span class="no">Thread</span><span class="o">.</span><span class="n">current</span><span class="o">[</span><span class="s2">&quot;mongo_mongo_runtime&quot;</span><span class="o">]</span> <span class="o">||=</span> <span class="mi">0</span> + <span class="k">end</span> + + <span class="k">def</span> <span class="nc">self</span><span class="o">.</span><span class="nf">reset_runtime</span> + <span class="n">rt</span><span class="p">,</span> <span class="nb">self</span><span class="o">.</span><span class="n">runtime</span> <span class="o">=</span> <span class="n">runtime</span><span class="p">,</span> <span class="mi">0</span> + <span class="n">rt</span> + <span class="k">end</span> + + <span class="k">def</span> <span class="nf">mongo</span><span class="p">(</span><span class="n">event</span><span class="p">)</span> + <span class="nb">self</span><span class="o">.</span><span class="n">class</span><span class="o">.</span><span class="n">runtime</span> <span class="o">+=</span> <span class="n">event</span><span class="o">.</span><span class="n">duration</span> + <span class="k">end</span> + <span class="k">end</span> + <span class="k">end</span> +<span class="k">end</span> +</pre> +</div> + + +<p>It looks complicated, but it's actually pretty simple. Data access methods in <code>Mongo::DB</code> and <code>Mongo::Collection</code> are hijacked and surrounded by an <code>ActiveSupport::Notifications.instrumenter.instrument</code> block. This triggers events which are listened to by the <code>LogSubscriber</code>, summing the total time spent in Mongo. The <code>ControllerRuntime</code> then collects this count to be displayed, and resets the sum to zero ready for the next request. The output looks like this:</p> + +<div class="highlight"><pre> Completed 200 OK in 838ms (Views: 370.5ms | ActiveRecord: 2.3ms | Mongo: 441.5ms) +</pre> +</div> + + +<p>It's just a first stab, so any comments and improvements are more then welcome. It's <a href="https://gist.github.com/833444">here on gist</a> so please fork away.</p> + + 2011-02-18T00:00:00+00:00 + + + + + + + http://tomafro.net @@ -652,44 +769,4 @@ Bundler has changed a lot since I first wrote this template, so I've <a href= - - http://tomafro.net - - Tip: cdpath - Am I the last to know? - - Tom Ward - tom@popdog.net - - <p>This one is just so simple, I can't believe I didn't know about it earlier.</p> - -<p>First, setup the cdpath or CDPATH variable:</p> - -<div class="highlight"><pre><span class="nv">cdpath</span><span class="o">=(</span>~ ~/Projects/apps ~/Projects/tools ~/Projects/plugins ~/Projects/sites<span class="o">)</span> -</pre> -</div> - - -<p>Now, changing directory in the shell becomes a whole world easier:</p> - -<div class='highlight'><pre><span class="s1">tomw@fellini:~<span class='nv'>$ </span></span><span class='nb'>cd </span>super-secret-app -~/Projects/apps/super-secret-app -<span class="s1">tomw@fellini:~/Projects/apps/super-secret-app<span class='nv'>$ </span></span><span class='nb'>cd </span>Documents -~/Documents -<span class="s1">tomw@fellini:~/Documents<span class='nv'>$ </span></span><span class='nb'>cd </span>tomafro.net -~/Projects/sites/tomafro.net -<span class="s1">tomw@fellini:~/Projects/sites/tomafro.net <span class='err'>$</span></span> -</pre> -</div> - - -<p>I've already added this to <a href="http://github.com/tomafro/dotfiles">my dotfiles</a>.</p> - - 2009-10-06T00:00:00+01:00 - - - - - - - \ No newline at end of file diff --git a/public/index.html b/public/index.html index 92258b2..26536a3 100644 --- a/public/index.html +++ b/public/index.html @@ -34,6 +34,117 @@
+
+

Experimental Mongo Instrumentation (for Rails 3)

+

One of our latest rails projects uses Mongo as a backend. We're just starting to get some traffic, and as we do, we're monitoring the logs for slow requests. When using ActiveRecord, rails splits out the recorded request time like so:

+ +
    Completed 200 OK in 6ms (Views 370.5ms | ActiveRecord: 2.3ms)
+
+
+ + +

We wanted to do the same for our Mongo accesses, just to give a rough idea as to what our requests were doing. Luckily Rails 3 makes this relatively straightforward, providing hooks to instrument methods, subscribe to log messages and add information to the request log. Here, then, is my first stab (mainly harvested from ActiveRecord):

+ +
module Mongo
+  module Instrumentation
+    def self.instrument(clazz, *methods)
+      clazz.module_eval do
+        methods.each do |m|
+          class_eval %{def #{m}_with_instrumentation(*args)
+            ActiveSupport::Notifications.instrumenter.instrument "mongo.mongo", :name => "#{m}" do
+              #{m}_without_instrumentation(*args)
+            end
+          end
+          }
+
+          alias_method_chain m, :instrumentation
+        end
+      end
+    end
+
+    class Railtie < Rails::Railtie
+      initializer "mongo.instrumentation" do |app|
+        Mongo::Instrumentation.instrument Mongo::Collection, :find, :save, :insert, :update
+        Mongo::Instrumentation.instrument Mongo::DB, :command
+
+        ActiveSupport.on_load(:action_controller) do
+          include Mongo::Instrumentation::ControllerRuntime
+        end
+
+        Mongo::Instrumentation::LogSubscriber.attach_to :mongo
+      end
+    end
+
+    module ControllerRuntime
+      extend ActiveSupport::Concern
+
+      protected
+
+      attr_internal :mongo_runtime
+
+      def cleanup_view_runtime
+        mongo_rt_before_render = Mongo::Instrumentation::LogSubscriber.reset_runtime
+        runtime = super
+        mongo_rt_after_render = Mongo::Instrumentation::LogSubscriber.reset_runtime
+        self.mongo_runtime = mongo_rt_before_render + mongo_rt_after_render
+        runtime - mongo_rt_after_render
+      end
+
+      def append_info_to_payload(payload)
+        super
+        payload[:mongo_runtime] = mongo_runtime
+      end
+
+      module ClassMethods
+        def log_process_action(payload)
+          messages, mongo_runtime = super, payload[:mongo_runtime]
+          messages << ("Mongo: %.1fms" % mongo_runtime.to_f) if mongo_runtime
+          messages
+        end
+      end
+    end
+
+    class LogSubscriber < ActiveSupport::LogSubscriber
+      def self.runtime=(value)
+        Thread.current["mongo_mongo_runtime"] = value
+      end
+
+      def self.runtime
+        Thread.current["mongo_mongo_runtime"] ||= 0
+      end
+
+      def self.reset_runtime
+        rt, self.runtime = runtime, 0
+        rt
+      end
+
+      def mongo(event)
+        self.class.runtime += event.duration
+      end
+    end
+  end
+end
+
+
+ + +

It looks complicated, but it's actually pretty simple. Data access methods in Mongo::DB and Mongo::Collection are hijacked and surrounded by an ActiveSupport::Notifications.instrumenter.instrument block. This triggers events which are listened to by the LogSubscriber, summing the total time spent in Mongo. The ControllerRuntime then collects this count to be displayed, and resets the sum to zero ready for the next request. The output looks like this:

+ +
    Completed 200 OK in 838ms (Views: 370.5ms | ActiveRecord: 2.3ms | Mongo: 441.5ms)
+
+
+ + +

It's just a first stab, so any comments and improvements are more then welcome. It's here on gist so please fork away.

+ +
+
+ Tom Ward · + 18th February 2011 + · · · · · +
+
+ -
-

Tip: Relative paths with File.expand_path

-

You probably know about the __FILE__ magic constant. It holds the filename of the currently executing ruby source file, relative to the execution directory. So with the following saved as /code/examples/path_example.rb:

- -
puts __FILE__
-
-
- - -

Running this file from the /code folder will output examples/path_example.rb

- -

This is often used to load files on paths relative to the current file. The way I've used it before is like this:

- -
config_path = File.expand_path(File.join(File.dirname(__FILE__), "config.yml"))
-
-
- - -

This works, but it's a bit clunky.

- -

What I didn't realise until reading the rails source code the other day, is that File.expand_path can take a second argument - a starting directory. Also, this argument doesn't actually have to be a path to a directory, it also accepts a path to a file. With this knowledge we can shorten the above to the following:

- -
config_path = File.expand_path("../config.yml", __FILE__)
-
-
- - -

Much simpler.

- -
-
- Tom Ward · - 23rd January 2010 - · · · · · -
-
-
diff --git a/public/sitemap.xml b/public/sitemap.xml index de1901a..dd23ac9 100644 --- a/public/sitemap.xml +++ b/public/sitemap.xml @@ -159,4 +159,9 @@ 2011-02-08 monthly + + http://tomafro.net/2011/02/experimental-mongo-instrumentation + 2011-02-18 + monthly + \ No newline at end of file diff --git a/public/tags/instrumentation.html b/public/tags/instrumentation.html new file mode 100644 index 0000000..c7183a8 --- /dev/null +++ b/public/tags/instrumentation.html @@ -0,0 +1,151 @@ + + + + + Posts tagged with instrumentation · tomafro.net + + + + + + + + + + + + +
+
+ tomafro.net · about · on github · on delicious · on twitter · on last.fm +
+
+ +
+

Experimental Mongo Instrumentation (for Rails 3)

+

One of our latest rails projects uses Mongo as a backend. We're just starting to get some traffic, and as we do, we're monitoring the logs for slow requests. When using ActiveRecord, rails splits out the recorded request time like so:

+ +
    Completed 200 OK in 6ms (Views 370.5ms | ActiveRecord: 2.3ms)
+
+
+ + +

We wanted to do the same for our Mongo accesses, just to give a rough idea as to what our requests were doing. Luckily Rails 3 makes this relatively straightforward, providing hooks to instrument methods, subscribe to log messages and add information to the request log. Here, then, is my first stab (mainly harvested from ActiveRecord):

+ +
module Mongo
+  module Instrumentation
+    def self.instrument(clazz, *methods)
+      clazz.module_eval do
+        methods.each do |m|
+          class_eval %{def #{m}_with_instrumentation(*args)
+            ActiveSupport::Notifications.instrumenter.instrument "mongo.mongo", :name => "#{m}" do
+              #{m}_without_instrumentation(*args)
+            end
+          end
+          }
+
+          alias_method_chain m, :instrumentation
+        end
+      end
+    end
+
+    class Railtie < Rails::Railtie
+      initializer "mongo.instrumentation" do |app|
+        Mongo::Instrumentation.instrument Mongo::Collection, :find, :save, :insert, :update
+        Mongo::Instrumentation.instrument Mongo::DB, :command
+
+        ActiveSupport.on_load(:action_controller) do
+          include Mongo::Instrumentation::ControllerRuntime
+        end
+
+        Mongo::Instrumentation::LogSubscriber.attach_to :mongo
+      end
+    end
+
+    module ControllerRuntime
+      extend ActiveSupport::Concern
+
+      protected
+
+      attr_internal :mongo_runtime
+
+      def cleanup_view_runtime
+        mongo_rt_before_render = Mongo::Instrumentation::LogSubscriber.reset_runtime
+        runtime = super
+        mongo_rt_after_render = Mongo::Instrumentation::LogSubscriber.reset_runtime
+        self.mongo_runtime = mongo_rt_before_render + mongo_rt_after_render
+        runtime - mongo_rt_after_render
+      end
+
+      def append_info_to_payload(payload)
+        super
+        payload[:mongo_runtime] = mongo_runtime
+      end
+
+      module ClassMethods
+        def log_process_action(payload)
+          messages, mongo_runtime = super, payload[:mongo_runtime]
+          messages << ("Mongo: %.1fms" % mongo_runtime.to_f) if mongo_runtime
+          messages
+        end
+      end
+    end
+
+    class LogSubscriber < ActiveSupport::LogSubscriber
+      def self.runtime=(value)
+        Thread.current["mongo_mongo_runtime"] = value
+      end
+
+      def self.runtime
+        Thread.current["mongo_mongo_runtime"] ||= 0
+      end
+
+      def self.reset_runtime
+        rt, self.runtime = runtime, 0
+        rt
+      end
+
+      def mongo(event)
+        self.class.runtime += event.duration
+      end
+    end
+  end
+end
+
+
+ + +

It looks complicated, but it's actually pretty simple. Data access methods in Mongo::DB and Mongo::Collection are hijacked and surrounded by an ActiveSupport::Notifications.instrumenter.instrument block. This triggers events which are listened to by the LogSubscriber, summing the total time spent in Mongo. The ControllerRuntime then collects this count to be displayed, and resets the sum to zero ready for the next request. The output looks like this:

+ +
    Completed 200 OK in 838ms (Views: 370.5ms | ActiveRecord: 2.3ms | Mongo: 441.5ms)
+
+
+ + +

It's just a first stab, so any comments and improvements are more then welcome. It's here on gist so please fork away.

+ +
+
+ Tom Ward · + 18th February 2011 + · · · · · +
+
+ + +
+
+ + \ No newline at end of file diff --git a/public/tags/mongo.html b/public/tags/mongo.html new file mode 100644 index 0000000..9012a80 --- /dev/null +++ b/public/tags/mongo.html @@ -0,0 +1,151 @@ + + + + + Posts tagged with mongo · tomafro.net + + + + + + + + + + + + +
+
+ tomafro.net · about · on github · on delicious · on twitter · on last.fm +
+
+ +
+

Experimental Mongo Instrumentation (for Rails 3)

+

One of our latest rails projects uses Mongo as a backend. We're just starting to get some traffic, and as we do, we're monitoring the logs for slow requests. When using ActiveRecord, rails splits out the recorded request time like so:

+ +
    Completed 200 OK in 6ms (Views 370.5ms | ActiveRecord: 2.3ms)
+
+
+ + +

We wanted to do the same for our Mongo accesses, just to give a rough idea as to what our requests were doing. Luckily Rails 3 makes this relatively straightforward, providing hooks to instrument methods, subscribe to log messages and add information to the request log. Here, then, is my first stab (mainly harvested from ActiveRecord):

+ +
module Mongo
+  module Instrumentation
+    def self.instrument(clazz, *methods)
+      clazz.module_eval do
+        methods.each do |m|
+          class_eval %{def #{m}_with_instrumentation(*args)
+            ActiveSupport::Notifications.instrumenter.instrument "mongo.mongo", :name => "#{m}" do
+              #{m}_without_instrumentation(*args)
+            end
+          end
+          }
+
+          alias_method_chain m, :instrumentation
+        end
+      end
+    end
+
+    class Railtie < Rails::Railtie
+      initializer "mongo.instrumentation" do |app|
+        Mongo::Instrumentation.instrument Mongo::Collection, :find, :save, :insert, :update
+        Mongo::Instrumentation.instrument Mongo::DB, :command
+
+        ActiveSupport.on_load(:action_controller) do
+          include Mongo::Instrumentation::ControllerRuntime
+        end
+
+        Mongo::Instrumentation::LogSubscriber.attach_to :mongo
+      end
+    end
+
+    module ControllerRuntime
+      extend ActiveSupport::Concern
+
+      protected
+
+      attr_internal :mongo_runtime
+
+      def cleanup_view_runtime
+        mongo_rt_before_render = Mongo::Instrumentation::LogSubscriber.reset_runtime
+        runtime = super
+        mongo_rt_after_render = Mongo::Instrumentation::LogSubscriber.reset_runtime
+        self.mongo_runtime = mongo_rt_before_render + mongo_rt_after_render
+        runtime - mongo_rt_after_render
+      end
+
+      def append_info_to_payload(payload)
+        super
+        payload[:mongo_runtime] = mongo_runtime
+      end
+
+      module ClassMethods
+        def log_process_action(payload)
+          messages, mongo_runtime = super, payload[:mongo_runtime]
+          messages << ("Mongo: %.1fms" % mongo_runtime.to_f) if mongo_runtime
+          messages
+        end
+      end
+    end
+
+    class LogSubscriber < ActiveSupport::LogSubscriber
+      def self.runtime=(value)
+        Thread.current["mongo_mongo_runtime"] = value
+      end
+
+      def self.runtime
+        Thread.current["mongo_mongo_runtime"] ||= 0
+      end
+
+      def self.reset_runtime
+        rt, self.runtime = runtime, 0
+        rt
+      end
+
+      def mongo(event)
+        self.class.runtime += event.duration
+      end
+    end
+  end
+end
+
+
+ + +

It looks complicated, but it's actually pretty simple. Data access methods in Mongo::DB and Mongo::Collection are hijacked and surrounded by an ActiveSupport::Notifications.instrumenter.instrument block. This triggers events which are listened to by the LogSubscriber, summing the total time spent in Mongo. The ControllerRuntime then collects this count to be displayed, and resets the sum to zero ready for the next request. The output looks like this:

+ +
    Completed 200 OK in 838ms (Views: 370.5ms | ActiveRecord: 2.3ms | Mongo: 441.5ms)
+
+
+ + +

It's just a first stab, so any comments and improvements are more then welcome. It's here on gist so please fork away.

+ +
+
+ Tom Ward · + 18th February 2011 + · · · · · +
+
+ + +
+
+ + \ No newline at end of file diff --git a/public/tags/rails.html b/public/tags/rails.html index f407169..7dc3256 100644 --- a/public/tags/rails.html +++ b/public/tags/rails.html @@ -33,6 +33,117 @@
+
+

Experimental Mongo Instrumentation (for Rails 3)

+

One of our latest rails projects uses Mongo as a backend. We're just starting to get some traffic, and as we do, we're monitoring the logs for slow requests. When using ActiveRecord, rails splits out the recorded request time like so:

+ +
    Completed 200 OK in 6ms (Views 370.5ms | ActiveRecord: 2.3ms)
+
+
+ + +

We wanted to do the same for our Mongo accesses, just to give a rough idea as to what our requests were doing. Luckily Rails 3 makes this relatively straightforward, providing hooks to instrument methods, subscribe to log messages and add information to the request log. Here, then, is my first stab (mainly harvested from ActiveRecord):

+ +
module Mongo
+  module Instrumentation
+    def self.instrument(clazz, *methods)
+      clazz.module_eval do
+        methods.each do |m|
+          class_eval %{def #{m}_with_instrumentation(*args)
+            ActiveSupport::Notifications.instrumenter.instrument "mongo.mongo", :name => "#{m}" do
+              #{m}_without_instrumentation(*args)
+            end
+          end
+          }
+
+          alias_method_chain m, :instrumentation
+        end
+      end
+    end
+
+    class Railtie < Rails::Railtie
+      initializer "mongo.instrumentation" do |app|
+        Mongo::Instrumentation.instrument Mongo::Collection, :find, :save, :insert, :update
+        Mongo::Instrumentation.instrument Mongo::DB, :command
+
+        ActiveSupport.on_load(:action_controller) do
+          include Mongo::Instrumentation::ControllerRuntime
+        end
+
+        Mongo::Instrumentation::LogSubscriber.attach_to :mongo
+      end
+    end
+
+    module ControllerRuntime
+      extend ActiveSupport::Concern
+
+      protected
+
+      attr_internal :mongo_runtime
+
+      def cleanup_view_runtime
+        mongo_rt_before_render = Mongo::Instrumentation::LogSubscriber.reset_runtime
+        runtime = super
+        mongo_rt_after_render = Mongo::Instrumentation::LogSubscriber.reset_runtime
+        self.mongo_runtime = mongo_rt_before_render + mongo_rt_after_render
+        runtime - mongo_rt_after_render
+      end
+
+      def append_info_to_payload(payload)
+        super
+        payload[:mongo_runtime] = mongo_runtime
+      end
+
+      module ClassMethods
+        def log_process_action(payload)
+          messages, mongo_runtime = super, payload[:mongo_runtime]
+          messages << ("Mongo: %.1fms" % mongo_runtime.to_f) if mongo_runtime
+          messages
+        end
+      end
+    end
+
+    class LogSubscriber < ActiveSupport::LogSubscriber
+      def self.runtime=(value)
+        Thread.current["mongo_mongo_runtime"] = value
+      end
+
+      def self.runtime
+        Thread.current["mongo_mongo_runtime"] ||= 0
+      end
+
+      def self.reset_runtime
+        rt, self.runtime = runtime, 0
+        rt
+      end
+
+      def mongo(event)
+        self.class.runtime += event.duration
+      end
+    end
+  end
+end
+
+
+ + +

It looks complicated, but it's actually pretty simple. Data access methods in Mongo::DB and Mongo::Collection are hijacked and surrounded by an ActiveSupport::Notifications.instrumenter.instrument block. This triggers events which are listened to by the LogSubscriber, summing the total time spent in Mongo. The ControllerRuntime then collects this count to be displayed, and resets the sum to zero ready for the next request. The output looks like this:

+ +
    Completed 200 OK in 838ms (Views: 370.5ms | ActiveRecord: 2.3ms | Mongo: 441.5ms)
+
+
+ + +

It's just a first stab, so any comments and improvements are more then welcome. It's here on gist so please fork away.

+ +
+
+ Tom Ward · + 18th February 2011 + · · · · · +
+
+

A home for my Active Record column reader

@kraykray was nice enough to let me know that Rails 3.03 had broken my column-reader code.

diff --git a/public/tags/rails3.html b/public/tags/rails3.html index e3d12fd..fd7eb74 100644 --- a/public/tags/rails3.html +++ b/public/tags/rails3.html @@ -33,6 +33,117 @@
+
+

Experimental Mongo Instrumentation (for Rails 3)

+

One of our latest rails projects uses Mongo as a backend. We're just starting to get some traffic, and as we do, we're monitoring the logs for slow requests. When using ActiveRecord, rails splits out the recorded request time like so:

+ +
    Completed 200 OK in 6ms (Views 370.5ms | ActiveRecord: 2.3ms)
+
+
+ + +

We wanted to do the same for our Mongo accesses, just to give a rough idea as to what our requests were doing. Luckily Rails 3 makes this relatively straightforward, providing hooks to instrument methods, subscribe to log messages and add information to the request log. Here, then, is my first stab (mainly harvested from ActiveRecord):

+ +
module Mongo
+  module Instrumentation
+    def self.instrument(clazz, *methods)
+      clazz.module_eval do
+        methods.each do |m|
+          class_eval %{def #{m}_with_instrumentation(*args)
+            ActiveSupport::Notifications.instrumenter.instrument "mongo.mongo", :name => "#{m}" do
+              #{m}_without_instrumentation(*args)
+            end
+          end
+          }
+
+          alias_method_chain m, :instrumentation
+        end
+      end
+    end
+
+    class Railtie < Rails::Railtie
+      initializer "mongo.instrumentation" do |app|
+        Mongo::Instrumentation.instrument Mongo::Collection, :find, :save, :insert, :update
+        Mongo::Instrumentation.instrument Mongo::DB, :command
+
+        ActiveSupport.on_load(:action_controller) do
+          include Mongo::Instrumentation::ControllerRuntime
+        end
+
+        Mongo::Instrumentation::LogSubscriber.attach_to :mongo
+      end
+    end
+
+    module ControllerRuntime
+      extend ActiveSupport::Concern
+
+      protected
+
+      attr_internal :mongo_runtime
+
+      def cleanup_view_runtime
+        mongo_rt_before_render = Mongo::Instrumentation::LogSubscriber.reset_runtime
+        runtime = super
+        mongo_rt_after_render = Mongo::Instrumentation::LogSubscriber.reset_runtime
+        self.mongo_runtime = mongo_rt_before_render + mongo_rt_after_render
+        runtime - mongo_rt_after_render
+      end
+
+      def append_info_to_payload(payload)
+        super
+        payload[:mongo_runtime] = mongo_runtime
+      end
+
+      module ClassMethods
+        def log_process_action(payload)
+          messages, mongo_runtime = super, payload[:mongo_runtime]
+          messages << ("Mongo: %.1fms" % mongo_runtime.to_f) if mongo_runtime
+          messages
+        end
+      end
+    end
+
+    class LogSubscriber < ActiveSupport::LogSubscriber
+      def self.runtime=(value)
+        Thread.current["mongo_mongo_runtime"] = value
+      end
+
+      def self.runtime
+        Thread.current["mongo_mongo_runtime"] ||= 0
+      end
+
+      def self.reset_runtime
+        rt, self.runtime = runtime, 0
+        rt
+      end
+
+      def mongo(event)
+        self.class.runtime += event.duration
+      end
+    end
+  end
+end
+
+
+ + +

It looks complicated, but it's actually pretty simple. Data access methods in Mongo::DB and Mongo::Collection are hijacked and surrounded by an ActiveSupport::Notifications.instrumenter.instrument block. This triggers events which are listened to by the LogSubscriber, summing the total time spent in Mongo. The ControllerRuntime then collects this count to be displayed, and resets the sum to zero ready for the next request. The output looks like this:

+ +
    Completed 200 OK in 838ms (Views: 370.5ms | ActiveRecord: 2.3ms | Mongo: 441.5ms)
+
+
+ + +

It's just a first stab, so any comments and improvements are more then welcome. It's here on gist so please fork away.

+ +
+
+ Tom Ward · + 18th February 2011 + · · · · · +
+
+

A home for my Active Record column reader

@kraykray was nice enough to let me know that Rails 3.03 had broken my column-reader code.

diff --git a/public/tags/ruby.html b/public/tags/ruby.html index e7f6a60..19aeb69 100644 --- a/public/tags/ruby.html +++ b/public/tags/ruby.html @@ -33,6 +33,117 @@
+
+

Experimental Mongo Instrumentation (for Rails 3)

+

One of our latest rails projects uses Mongo as a backend. We're just starting to get some traffic, and as we do, we're monitoring the logs for slow requests. When using ActiveRecord, rails splits out the recorded request time like so:

+ +
    Completed 200 OK in 6ms (Views 370.5ms | ActiveRecord: 2.3ms)
+
+
+ + +

We wanted to do the same for our Mongo accesses, just to give a rough idea as to what our requests were doing. Luckily Rails 3 makes this relatively straightforward, providing hooks to instrument methods, subscribe to log messages and add information to the request log. Here, then, is my first stab (mainly harvested from ActiveRecord):

+ +
module Mongo
+  module Instrumentation
+    def self.instrument(clazz, *methods)
+      clazz.module_eval do
+        methods.each do |m|
+          class_eval %{def #{m}_with_instrumentation(*args)
+            ActiveSupport::Notifications.instrumenter.instrument "mongo.mongo", :name => "#{m}" do
+              #{m}_without_instrumentation(*args)
+            end
+          end
+          }
+
+          alias_method_chain m, :instrumentation
+        end
+      end
+    end
+
+    class Railtie < Rails::Railtie
+      initializer "mongo.instrumentation" do |app|
+        Mongo::Instrumentation.instrument Mongo::Collection, :find, :save, :insert, :update
+        Mongo::Instrumentation.instrument Mongo::DB, :command
+
+        ActiveSupport.on_load(:action_controller) do
+          include Mongo::Instrumentation::ControllerRuntime
+        end
+
+        Mongo::Instrumentation::LogSubscriber.attach_to :mongo
+      end
+    end
+
+    module ControllerRuntime
+      extend ActiveSupport::Concern
+
+      protected
+
+      attr_internal :mongo_runtime
+
+      def cleanup_view_runtime
+        mongo_rt_before_render = Mongo::Instrumentation::LogSubscriber.reset_runtime
+        runtime = super
+        mongo_rt_after_render = Mongo::Instrumentation::LogSubscriber.reset_runtime
+        self.mongo_runtime = mongo_rt_before_render + mongo_rt_after_render
+        runtime - mongo_rt_after_render
+      end
+
+      def append_info_to_payload(payload)
+        super
+        payload[:mongo_runtime] = mongo_runtime
+      end
+
+      module ClassMethods
+        def log_process_action(payload)
+          messages, mongo_runtime = super, payload[:mongo_runtime]
+          messages << ("Mongo: %.1fms" % mongo_runtime.to_f) if mongo_runtime
+          messages
+        end
+      end
+    end
+
+    class LogSubscriber < ActiveSupport::LogSubscriber
+      def self.runtime=(value)
+        Thread.current["mongo_mongo_runtime"] = value
+      end
+
+      def self.runtime
+        Thread.current["mongo_mongo_runtime"] ||= 0
+      end
+
+      def self.reset_runtime
+        rt, self.runtime = runtime, 0
+        rt
+      end
+
+      def mongo(event)
+        self.class.runtime += event.duration
+      end
+    end
+  end
+end
+
+
+ + +

It looks complicated, but it's actually pretty simple. Data access methods in Mongo::DB and Mongo::Collection are hijacked and surrounded by an ActiveSupport::Notifications.instrumenter.instrument block. This triggers events which are listened to by the LogSubscriber, summing the total time spent in Mongo. The ControllerRuntime then collects this count to be displayed, and resets the sum to zero ready for the next request. The output looks like this:

+ +
    Completed 200 OK in 838ms (Views: 370.5ms | ActiveRecord: 2.3ms | Mongo: 441.5ms)
+
+
+ + +

It's just a first stab, so any comments and improvements are more then welcome. It's here on gist so please fork away.

+ +
+
+ Tom Ward · + 18th February 2011 + · · · · · +
+
+

A home for my Active Record column reader

@kraykray was nice enough to let me know that Rails 3.03 had broken my column-reader code.

diff --git a/source/_layouts/default.html b/source/_layouts/default.html index bf0a8c0..a354721 100644 --- a/source/_layouts/default.html +++ b/source/_layouts/default.html @@ -34,7 +34,7 @@ {% include 'menubar' %}
- {{ content }} + {{ page.body }}
diff --git a/source/css/style.less b/source/css/style.less index 66ec031..c004ec7 100644 --- a/source/css/style.less +++ b/source/css/style.less @@ -1,4 +1,4 @@ -@serif: "ff-tisa-web-pro-1","ff-tisa-web-pro-2"; +@serif: "adelle-1","adelle-2"; @sans-serif: "ff-dagny-web-pro-1","ff-dagny-web-pro-2"; .rounded-corners (@radius: 0.3em) { @@ -75,9 +75,9 @@ h2 { font-size: 1.8em; line-height: 1.2em; border-bottom: 1px solid #ddd; - padding-bottom: 0.2em; - margin-bottom: -0.3em; - margin-top: 0; + padding-bottom: 0.1em; + margin-bottom: -0.2em; + margin-top: 0.1em; } h3 { @@ -88,7 +88,7 @@ h1 { font-size: 2em; font-weight: normal; border-bottom: 1px solid #ddd; - padding-bottom: 8px; + padding-bottom: 4px; } article { diff --git a/source/posts/2009-05-29-read-active-record-columns-directly-from-the-class.markdown b/source/posts/2009-05-29-read-active-record-columns-directly-from-the-class.markdown index 6d33019..a7e5400 100644 --- a/source/posts/2009-05-29-read-active-record-columns-directly-from-the-class.markdown +++ b/source/posts/2009-05-29-read-active-record-columns-directly-from-the-class.markdown @@ -1,7 +1,7 @@ --- layout: post title: Read ActiveRecord columns directly from the class -tags: [ruby, rails, active-record] +tags: [ruby, rails, active-record, column-reader] --- Sometimes you want to read just a single column from a collection of records, without the overhead of instantiating each and every one. You could just execute raw SQL, but it's a shame to do away with the nice type conversion `ActiveRecord` provides. It'd also be a pity to get rid of find scoping, amongst other goodness. diff --git a/source/posts/2010-01-26-asdasdasd.markdown b/source/posts/2010-01-26-asdasdasd.markdown deleted file mode 100644 index 6e0c3f6..0000000 --- a/source/posts/2010-01-26-asdasdasd.markdown +++ /dev/null @@ -1,7 +0,0 @@ ---- -layout: post -title: "Don't requires in ruby" -tags: [ruby, tip, tiny, file, expand-path] -draft: true ---- -A few days ago I wrote a post showing [how to use `File.expand_path` to generate paths relative to the current file](http://tomafro.net/2010/01/tip-relative-paths-with-file-expand-path). Thanks to tweets from [Luke Redpath](https://twitter.com/lukeredpath/status/8216962316), [Ryan Bates](https://twitter.com/rbates/status/8225544463) and others, this post garnered a lot of attention. \ No newline at end of file diff --git a/source/posts/2010-02-11-rails-3-direct-column-reader.markdown b/source/posts/2010-02-11-rails-3-direct-column-reader.markdown index fa88b0c..e1e5e4e 100644 --- a/source/posts/2010-02-11-rails-3-direct-column-reader.markdown +++ b/source/posts/2010-02-11-rails-3-direct-column-reader.markdown @@ -1,7 +1,7 @@ --- layout: post title: Rails 3 direct column reader -tags: [ruby, rails, rails3, active-record] +tags: [ruby, rails, rails3, active-record, column-reader] --- Whilst trying to get my head around [arel](http://github.com/brynary/arel) and it's relationship to ActiveRecord in rails 3, I've updated the simple ColumnReader class I [introduced last year](http://tomafro.net/2009/05/read-active-record-columns-directly-from-the-class). It lets you read the (correctly cast) column values for an ActiveRecord class, without the overhead of instantiating each object. diff --git a/source/posts/2010-02-28-updated-rails-template-for-bundler.markdown b/source/posts/2010-02-28-updated-rails-template-for-bundler.markdown index abea926..8da2410 100644 --- a/source/posts/2010-02-28-updated-rails-template-for-bundler.markdown +++ b/source/posts/2010-02-28-updated-rails-template-for-bundler.markdown @@ -3,6 +3,11 @@ layout: post title: An updated rails template for gem bundler tags: [ruby, rails, gem, bundler] --- +
+

Update 8th February 2011:

+Bundler has changed a lot since I wrote these instructions. Use them at your own risk! +
+ A few months ago I wrote [a rails template for gem bundler](http://tomafro.net/2009/11/a-rails-template-for-gem-bundler). Since then, bundler has changed a lot, and my template no longer works. [Here then is an updated version](http://github.com/tomafro/dotfiles/raw/master/resources/rails/bundler.rb), based on [this gist](http://gist.github.com/302406) from [Andre Arko](http://arko.net/). Using it, you should be able to get a rails 2.3.5 project working with bundler in less than 5 minutes. The first step is to install the latest bundler. At the time of writing, this was 0.9.9. diff --git a/source/posts/_payload.lanyon.yml b/source/posts/_payload.lanyon.yml deleted file mode 100644 index 4794be5..0000000 --- a/source/posts/_payload.lanyon.yml +++ /dev/null @@ -1,3 +0,0 @@ ---- -url: "/:year/:month/:permalink" -path: ":url.html" \ No newline at end of file diff --git a/source/scraps/_payload.lanyon.yml b/source/scraps/_payload.lanyon.yml deleted file mode 100644 index 71a7c8c..0000000 --- a/source/scraps/_payload.lanyon.yml +++ /dev/null @@ -1,4 +0,0 @@ ---- -path: ":url.html" -url: "/scrapbook/:year/:month/:permalink" -draft: true \ No newline at end of file