-
Notifications
You must be signed in to change notification settings - Fork 12
/
02.html
167 lines (133 loc) · 13.4 KB
/
02.html
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE html>
<html>
<head>
<title>Posts from 02/2011 · tomafro.net</title>
<meta name="verify-v1" content="ADnFYWq1MeVbf8+qNPe/GZTvcEsDgOCgWTWrUIPakz8=" />
<meta http-equiv="X-UA-Compatible" content="chrome=1" />
<script type="text/javascript" src="http://use.typekit.com/brv6igt.js"></script>
<script type="text/javascript">try{Typekit.load();}catch(e){}</script>
<link rel="stylesheet" href="/css/style.css" type="text/css" />
<link rel="alternate" type="application/atom+xml" href="http://tomafro.net/atom.xml" />
<link rel="canonical" href="http://tomafro.net/2011/02"/>
<script type="text/javascript">
var _gaq = _gaq || [];
_gaq.push(['_setAccount', 'UA-1103395-2']);
_gaq.push(['_trackPageview']);
(function() {
var ga = document.createElement('script');
ga.src = ('https:' == document.location.protocol ? 'https://ssl' :
'http://www') + '.google-analytics.com/ga.js';
ga.setAttribute('async', 'true');
document.documentElement.firstChild.appendChild(ga);
})();
</script>
</head>
<body>
<div id="container">
<header class="menubar">
<a class="name" href="/">tomafro.net</a> · <a href="/about">about</a> · <a href="http://github.com/tomafro">on github</a> · <a href="http://delicious.com/tomafro">on delicious</a> · <a href="http://twitter.com/tomafro">on twitter</a> · <a href="http://www.last.fm/user/tomafro">on last.fm</a>
</header>
<div id="main">
<article class="post">
<div class="content"><h2 class="title"><a href="/2011/02/experimental-mongo-instrumentation">Experimental Mongo Instrumentation (for Rails 3)</a></h2>
<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 "mongo.mongo", :name => "</span><span class="si">#{</span><span class="n">m</span><span class="si">}</span><span class="sx">" 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"><</span> <span class="no">Rails</span><span class="o">::</span><span class="no">Railtie</span>
<span class="n">initializer</span> <span class="s2">"mongo.instrumentation"</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"><<</span> <span class="p">(</span><span class="s2">"Mongo: %.1fms"</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"><</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">"mongo_mongo_runtime"</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">"mongo_mongo_runtime"</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>
</div>
<div class="meta">
<span class="author"><a href="http://tomafro.net">Tom Ward</a></span> ·
<span class="date"><a href="/2011/02">18th February 2011</a></span>
<span class="tags"> · <a href="/tags/ruby" rel="tag">ruby</a> · <a href="/tags/rails" rel="tag">rails</a> · <a href="/tags/rails3" rel="tag">rails3</a> · <a href="/tags/mongo" rel="tag">mongo</a> · <a href="/tags/instrumentation" rel="tag">instrumentation</a></span>
</div>
</article>
<article class="post">
<div class="content"><h2 class="title"><a href="/2011/02/rails-3-column-reader-tweak">A home for my Active Record column reader</a></h2>
<p><a href="http://twitter.com/kraykray">@kraykray</a> was nice enough to let me know that Rails 3.03 had broken my column-reader code.</p>
<p>I've always seen it as a toy rather than a serious project, but getting a bug report made me re-evaluate. If people are using it, even a tiny piece of code like this deserves a proper home.</p>
<p>So here it is, as both <a href="https://github.com/tomafro/rails-activerecord-columnreader">a github repository</a> and <a href="http://rubygems.org/gems/activerecord-column-reader">a gem</a>. Enjoy!</p>
</div>
<div class="meta">
<span class="author"><a href="http://tomafro.net">Tom Ward</a></span> ·
<span class="date"><a href="/2011/02"> 8th February 2011</a></span>
<span class="tags"> · <a href="/tags/ruby" rel="tag">ruby</a> · <a href="/tags/rails" rel="tag">rails</a> · <a href="/tags/rails3" rel="tag">rails3</a> · <a href="/tags/active-record" rel="tag">active-record</a> · <a href="/tags/column-reader" rel="tag">column-reader</a></span>
</div>
</article>
</div>
</div>
</body>
</html>