-
Notifications
You must be signed in to change notification settings - Fork 63
/
rbtracer.rb
595 lines (497 loc) · 13.2 KB
/
rbtracer.rb
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
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
546
547
548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
574
575
576
577
578
579
580
581
582
583
584
585
586
587
588
589
590
591
592
593
594
595
require 'socket'
require 'fileutils'
require 'msgpack'
require 'ffi'
require 'rbtrace/core_ext'
require 'rbtrace/msgq'
class RBTracer
# Public: The Fixnum pid of the traced process.
attr_reader :pid
# Public: The IO where tracing output is written (default: STDOUT).
attr_accessor :out
# Public: The timeout before giving up on attaching/detaching to a process.
attr_accessor :timeout
# The String prefix used on nested method calls (default: ' ').
attr_accessor :prefix
# The Boolean flag for showing how long method calls take (default: true).
attr_accessor :show_duration
# The Boolean flag for showing the timestamp when method calls start (default: false).
attr_accessor :show_time
# Create a new tracer
#
# pid - The String of Fixnum process id
#
# Returns a tracer.
def initialize(pid)
begin
raise ArgumentError unless pid
@pid = pid.to_i
raise ArgumentError unless @pid > 0
Process.kill(0, @pid)
rescue TypeError, ArgumentError
raise ArgumentError, 'pid required'
rescue Errno::ESRCH
raise ArgumentError, 'invalid pid'
rescue Errno::EPERM
raise ArgumentError, 'could not signal process, are you running as root?'
end
@sock = Socket.new Socket::AF_UNIX, Socket::SOCK_DGRAM, 0
@sockaddr = Socket.pack_sockaddr_un(socket_path)
@sock.bind(@sockaddr)
FileUtils.chmod 0666, socket_path
at_exit { clean_socket_path }
5.times do
signal
sleep 0.15 # wait for process to create msgqs
@qo = MsgQ.msgget(-@pid, 0666)
break if @qo > -1
end
if @qo == -1
raise ArgumentError, 'pid is not listening for messages, did you `require "rbtrace"`'
end
@klasses = {}
@methods = {}
@tracers = Hash.new{ |h,k|
h[k] = {
:query => nil,
:times => [],
:names => [],
:exprs => {},
:last => false,
:arglist => false
}
}
@max_nesting = @last_nesting = @nesting = 0
@last_tracer = nil
@timeout = 5
@out = STDOUT
@out.sync = true
@prefix = ' '
@printed_newline = true
@show_time = false
@show_duration = true
@watch_slow = false
attach
end
def socket_path
"/tmp/rbtrace-#{@pid}.sock"
end
def clean_socket_path
FileUtils.rm(socket_path) if File.exist?(socket_path)
end
# Watch for method calls slower than a threshold.
#
# msec - The Fixnum threshold in milliseconds
#
# Returns nothing.
def watch(msec, cpu_only=false)
@watch_slow = true
send_cmd(cpu_only ? :watchcpu : :watch, msec)
end
# Turn on the firehose (show all method calls).
#
# Returns nothing.
def firehose
send_cmd(:firehose)
end
# Turn on dev mode.
#
# Returns nothing.
def devmode
send_cmd(:devmode)
end
# Fork the process and return the copy's pid.
#
# Returns a Fixnum pid.
def fork
send_cmd(:fork)
if wait('for fork', 30){ !!@forked_pid }
@forked_pid
else
STDERR.puts '*** timed out waiting for fork'
end
end
# Evaluate some ruby code.
#
# Returns the String result.
def eval(code)
if (err = valid_syntax?(code)) != true
raise ArgumentError, "#{err.class} for expression #{code.inspect}"
end
send_cmd(:eval, code)
if wait('for eval response', timeout){ !!@eval_result }
res = @eval_result
@eval_result = nil
res
else
STDERR.puts '*** timed out waiting for eval response'
end
end
# Turn on GC tracing.
#
# Returns nothing.
def gc
send_cmd(:gc)
end
# Restrict slow tracing to a specific list of methods.
#
# methods - The String or Array of method selectors.
#
# Returns nothing.
def add_slow(methods)
add(methods, true)
end
# Add tracers for the given list of methods.
#
# methods - The String or Array of method selectors to trace.
#
# Returns nothing.
def add(methods, slow=false)
Array(methods).each do |func|
func = func.strip
next if func.empty?
if func =~ /^(.+?)\((.+)\)$/
name, args = $1, $2
args = args.split(',').map{ |a| a.strip }
end
send_cmd(:add, name || func, slow)
if args and args.any?
args.each do |arg|
if (err = valid_syntax?(arg)) != true
raise ArgumentError, "#{err.class} for expression #{arg.inspect} in method #{func.inspect}"
end
if arg =~ /^@/ and arg !~ /^@[_a-z][_a-z0-9]+$/i
# arg[0]=='@' means ivar, but if this is an expr
# we can hack a space in front so it gets eval'd instead
arg = " #{arg}"
end
send_cmd(:addexpr, arg)
end
end
end
end
# Attach to the process.
#
# Returns nothing.
def attach
send_cmd(:attach, Process.pid)
if wait('to attach'){ @attached == true }
STDERR.puts "*** attached to process #{pid}"
else
raise ArgumentError, 'process already being traced?'
end
end
# Detach from the traced process.
#
# Returns nothing.
def detach
begin
send_cmd(:detach)
rescue Errno::ESRCH
end
newline
if wait('to detach cleanly'){ @attached == false }
newline
STDERR.puts "*** detached from process #{pid}"
else
newline
STDERR.puts "*** could not detach cleanly from process #{pid}"
end
rescue Errno::EINVAL, Errno::EIDRM
newline
STDERR.puts "*** process #{pid} is gone"
# STDERR.puts "*** #{$!.inspect}"
# STDERR.puts $!.backtrace.join("\n ")
rescue Interrupt, SignalException
retry
ensure
clean_socket_path
end
# Process events from the traced process.
#
# Returns nothing
def recv_loop
while true
ready = IO.select([@sock], nil, nil, 1)
if ready
# block until a message arrives
process_line(recv_cmd)
# process any remaining messages
recv_lines
else
Process.kill(0, @pid)
end
end
rescue Errno::EINVAL, Errno::EIDRM, Errno::ESRCH
# process went away
end
# Process events from the traced process, without blocking if
# there is nothing to do. This is a useful way to drain the buffer
# so messages do not accumulate in kernel land.
#
# Returns nothing.
def recv_lines
50.times do
break unless line = recv_cmd(false)
process_line(line)
end
end
def puts(arg=nil)
@printed_newline = true
arg ? @out.puts(arg) : @out.puts
end
private
def signal
Process.kill 'URG', @pid
end
# Process incoming events until either a timeout or a condition becomes true.
#
# time - The Fixnum timeout in seconds.
# block - The Block that is checked every 50ms until it returns true.
#
# Returns true when the condition was met, or false on a timeout.
def wait(reason, time=@timeout)
wait = 0.05 # polling interval
(time/wait).to_i.times do
begin
recv_lines
sleep(wait)
begin
signal
rescue Errno::ESRCH
break
end
time -= wait
return true if yield
rescue Interrupt
STDERR.puts "*** waiting #{reason} (#{time.to_i}s left)"
retry
end
end
false
end
def send_cmd(*cmd)
begin
msg = cmd.to_msgpack
# A message is null-terminated, but bytesize gives the unterminated
# length.
if msg.bytesize >= RBTrace::BUF_SIZE
raise ArgumentError, "command is too long (#{msg.bytesize}B >= #{MsgQ::EventMsg::BUF_SIZE}B)"
end
MsgQ::EventMsg.send_cmd(@qo, msg)
rescue Errno::EINTR
retry
end
signal
recv_lines
end
def recv_cmd(block=true)
if block
@sock.recv(65536)
else
@sock.recv_nonblock(65536)
end
rescue Errno::EAGAIN
nil
end
def valid_syntax?(code)
begin
Kernel.eval("#{code}\nBEGIN {return true}", nil, 'rbtrace_expression', 0)
rescue Exception => e
e
end
end
def print(arg)
@printed_newline = false
@out.print(arg)
end
def newline
puts unless @printed_newline
@printed_newline = true
end
def parse_cmd(line)
unpacker = MessagePack::Unpacker.new
unpacker.feed(line)
obj = nil
unpacker.each{|o| obj = o; break }
obj
end
def process_line(line)
return unless cmd = parse_cmd(line)
event = cmd.shift
case event
when 'during_gc'
sleep 0.01
signal
return
when 'attached'
tracer_pid, = *cmd
if tracer_pid != Process.pid
STDERR.puts "*** process #{pid} is already being traced (#{tracer_pid} != #{Process.pid})"
exit!(-1)
end
@attached = true
return
when 'detached'
tracer_pid, = *cmd
if tracer_pid != Process.pid
STDERR.puts "*** process #{pid} detached #{tracer_pid}, but we are #{Process.pid}"
else
@attached = false
end
return
end
unless @attached
STDERR.puts "*** got #{event} before attaching"
return
end
case event
when 'forked'
pid, = *cmd
@forked_pid = pid
when 'evaled'
res, = *cmd
@eval_result = res
when 'mid'
mid, name = *cmd
@methods[mid] = name
when 'klass'
kid, name = *cmd
@klasses[kid] = name
when 'add'
tracer_id, query = *cmd
if tracer_id == -1
STDERR.puts "*** unable to add tracer for #{query}"
else
@tracers.delete(tracer_id)
@tracers[tracer_id][:query] = query
end
when 'newexpr'
tracer_id, expr_id, expr = *cmd
tracer = @tracers[tracer_id]
if expr_id > -1
tracer[:exprs][expr_id] = expr.strip
end
when 'exprval'
tracer_id, expr_id, val = *cmd
tracer = @tracers[tracer_id]
expr = tracer[:exprs][expr_id]
if tracer[:arglist]
print ', '
else
print '('
end
print "#{expr}="
print val
tracer[:arglist] = true
when 'call','ccall'
time, tracer_id, mid, is_singleton, klass = *cmd
tracer = @tracers[tracer_id]
klass = @klasses[klass]
name = klass ? "#{klass}#{ is_singleton ? '.' : '#' }" : ''
name += @methods[mid] || '(unknown)'
tracer[:times] << time
tracer[:names] << name
if @last_tracer and @last_tracer[:arglist]
print ')'
@last_tracer[:arglist] = false
end
newline
if @show_time
t = Time.at(time/1_000_000)
print t.strftime("%H:%M:%S.")
print "%06d " % (time - t.to_f*1_000_000).round
end
print @prefix*@nesting if @nesting > 0
print name
@nesting += 1
@max_nesting = @nesting if @nesting > @max_nesting
@last_nesting = @nesting
@last_tracer = tracer
tracer[:last] = "#{name}:#{@nesting-1}"
when 'return','creturn'
time, tracer_id = *cmd
tracer = @tracers[tracer_id]
@nesting -= 1 if @nesting > 0
if start = tracer[:times].pop
name = tracer[:names].pop
diff = time - start
@last_tracer[:arglist] = false if @last_tracer and @last_tracer[:last] != "#{name}:#{@nesting}"
print ')' if @last_tracer and @last_tracer[:arglist]
unless tracer == @last_tracer and @last_tracer[:last] == "#{name}:#{@nesting}"
newline
print ' '*16 if @show_time
print @prefix*@nesting if @nesting > 0
print name
end
print ' <%f>' % (diff/1_000_000.0) if @show_duration
newline
if @nesting == 0 and @max_nesting > 1
# unless tracer == @last_tracer and @last_tracer[:last] == name
puts
# end
end
end
tracer[:arglist] = false
@last_nesting = @nesting
when 'slow', 'cslow'
time, diff, nesting, mid, is_singleton, klass = *cmd
klass = @klasses[klass]
name = klass ? "#{klass}#{ is_singleton ? '.' : '#' }" : ''
name += @methods[mid] || '(unknown)'
newline
nesting = @nesting if @nesting > 0
if @show_time
t = Time.at(time/1_000_000)
print t.strftime("%H:%M:%S.")
print "%06d " % (time - t.to_f*1_000_000).round
end
print @prefix*nesting if nesting > 0
print name
if @show_duration
print ' '
print "<%f>" % (diff/1_000_000.0)
end
puts
puts if nesting == 0 and @max_nesting > 1
@max_nesting = nesting if nesting > @max_nesting
@last_nesting = nesting
when 'gc_start'
time, = *cmd
@gc_start = time
print 'garbage_collect'
when 'gc_end'
time, = *cmd
diff = time - @gc_start
# if @gc_mark
# mark = ((@gc_mark - @gc_start) * 100.0 / diff).to_i
# print '(mark: %d%%, sweep: %d%%)' % [mark, 100-mark]
# end
print ' <%f>' % (diff/1_000_000.0) if @show_duration
@gc_start = nil
newline
when 'gc'
time, = *cmd
@gc_mark = time
unless @gc_start
newline
if @show_time
t = Time.at(time/1_000_000)
print t.strftime("%H:%M:%S.")
print "%06d " % (time - t.to_f*1_000_000).round
end
print @prefix*@last_nesting if @last_nesting > 0
print "garbage_collect"
puts if @watch_slow
end
when 'write'
data, = *cmd
STDOUT.write(data)
else
puts "unknown event #{event}: #{cmd.inspect}"
end
rescue => e
STDERR.puts "error on #{event}: #{cmd.inspect}"
raise e
end
end