File: rbtracer.rb

package info (click to toggle)
ruby-rbtrace 0.5.3-1
  • links: PTS, VCS
  • area: main
  • in suites: forky, sid
  • size: 756 kB
  • sloc: ruby: 1,128; ansic: 925; sh: 42; makefile: 4
file content (595 lines) | stat: -rw-r--r-- 13,564 bytes parent folder | download | duplicates (2)
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