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
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
|
# rbtrace: like strace, but for ruby code
rbtrace shows you method calls happening inside another ruby process in real
time.
rbtrace works on ruby 1.8 through 2.2 (and beyond), running on linux or mac
osx.
rbtrace is designed to have minimal overhead, and should be safe to run
in production.
## usage
% gem install rbtrace
% rbtrace --help
## supported Rubies
rbtrace supports all stable versions of Ruby MRI, as of 23-01-2018 this is
Ruby version 2.2 and later.
## tracer types
rbtrace has several different tracing modes.
### firehose: show everything
% rbtrace -p <PID> --firehose
### slow: show any method calls that take longer than `<N>` milliseconds
% rbtrace -p <PID> --slow=<N>
### methods: trace calls to specific methods
% rbtrace -p <PID> --methods "Kernel#sleep" "Proc#call"
### gc: trace garbage collections
% rbtrace -p <PID> --gc
### memory: produce a basic memory report regarding process (including GC.stat and ObjectSpace stats)
% rbtrace -p <PID> --memory
### backtraces: return backtraces for all active threads in a process
% rbtrace -p <PID> --backtraces
### notes
`--firehose` is not reliable on osx.
`--slow`, `--gc` and `--methods` can be combined.
## predefined tracers
rbtrace also includes a set of [predefined tracers](https://github.com/tmm1/rbtrace/tree/master/tracers)
for popular ruby libraries and functions.
### trace calls to activerecord adapters and any i/o functions
% rbtrace -p <PID> -c activerecord io
## detailed example
### require rbtrace into a process
% cat server.rb
require 'rbtrace'
class String
def multiply_vowels(num)
@test = 123
gsub(/[aeiou]/){ |m| m*num }
end
end
while true
proc {
Dir.chdir("/tmp") do
Dir.pwd
Process.pid
'hello'.multiply_vowels(3)
sleep rand*0.5
end
}.call
end
### run the process
% ruby server.rb &
[1] 87854
### trace a function using the process's pid
% rbtrace -p 87854 -m sleep
*** attached to process 87854
Kernel#sleep <0.138615>
Kernel#sleep <0.147726>
Kernel#sleep <0.318728>
Kernel#sleep <0.338173>
Kernel#sleep <0.373004>
Kernel#sleep
*** detached from process 87854
### trace everything
% rbtrace -p 87854 --firehose
*** attached to process 87938
Kernel#proc <0.000082>
Proc#call
Dir.chdir
Dir.pwd <0.000060>
Process.pid <0.000021>
String#multiply_vowels
String#gsub
String#* <0.000023>
String#* <0.000022>
String#gsub <0.000127>
String#multiply_vowels <0.000175>
Kernel#rand <0.000018>
Float#* <0.000022>
Kernel#sleep <0.344281>
Dir.chdir <0.344858>
Proc#call <0.344908>
*** detached from process 87938
### trace specific functions
% rbtrace -p 87854 -m sleep Dir.chdir Dir.pwd Process.pid "String#gsub" "String#*"
*** attached to process 87854
Dir.chdir
Dir.pwd <0.000023>
Process.pid <0.000008>
String#gsub
String#* <0.000008>
String#* <0.000007>
String#gsub <0.000050>
Kernel#sleep <0.498809>
Dir.chdir <0.499025>
Dir.chdir
Dir.pwd <0.000024>
Process.pid <0.000008>
String#gsub
String#* <0.000008>
String#* <0.000007>
String#gsub <0.000050>
Kernel#sleep
*** detached from process 87854
### trace all functions in a class/module
% rbtrace -p 87854 -m "Kernel#"
*** attached to process 87854
Kernel#proc <0.000062>
Kernel#rand <0.000010>
Kernel#sleep <0.218677>
Kernel#proc <0.000016>
Kernel#rand <0.000010>
Kernel#sleep <0.195914>
Kernel#proc <0.000016>
Kernel#rand <0.000009>
Kernel#sleep
*** detached from process 87854
### get values of variables and other expressions
% rbtrace -p 87854 -m "String#gsub(self, @test)" "String#*(self, __source__)" "String#multiply_vowels(self, self.length, num)"
*** attached to process 87854
String#multiply_vowels(self="hello", self.length=5, num=3)
String#gsub(self="hello", @test=123)
String#*(self="e", __source__="server.rb:6") <0.000020>
String#*(self="o", __source__="server.rb:6") <0.000018>
String#gsub <0.000085>
String#multiply_vowels <0.000198>
String#multiply_vowels(self="hello", self.length=5, num=3)
String#gsub(self="hello", @test=123)
String#*(self="e", __source__="server.rb:6") <0.000020>
String#*(self="o", __source__="server.rb:6") <0.000020>
String#gsub <0.000102>
String#multiply_vowels <0.000218>
*** detached from process 87854
### watch for method calls slower than 250ms
% rbtrace -p 87854 --slow=250
*** attached to process 87854
Kernel#sleep <0.459628>
Dir.chdir <0.459828>
Proc#call <0.459849>
Kernel#sleep <0.484666>
Dir.chdir <0.484804>
Proc#call <0.484818>
*** detached from process 87854
## todo
* correct irb implementation so it establishes a dedicated channel
* add triggers to start tracing slow methods only inside another method
* add watch expressions to fire tracers only when an expression is true
* add special expressions for method args (_arg0_, _arguments_)
* optimize local variable lookup to avoid instance_eval
* investigate mach_msg on osx since msgget(2) has hard kernel limits
|
