Project

General

Profile

Bug #1152 ยป 1152-2009-03-09.patch

latest patch - jabley (James Abley), 03/16/2009 09:37 AM

View differences:

lib/profiler.rb (working copy)
1 1
module Profiler__
2 2
  # internal values
3
  @@start = @@stack = @@map = nil
3
  @@start = nil # the start time that profiling began
4
  @@stacks = nil # the map of stack arrays keyed by thread
5
  @@maps = nil # the map of map of call data keyed by thread, then by class and id. Call data arrays contains the call count, total time, 
4 6
  PROFILE_PROC = proc{|event, file, line, id, binding, klass|
5 7
    case event
6 8
    when "call", "c-call"
7 9
      now = Process.times[0]
8
      @@stack.push [now, 0.0]
10
      stack = (@@stacks[Thread.current] ||= [])
11
      stack.push [now, 0.0]
9 12
    when "return", "c-return"
10 13
      now = Process.times[0]
11 14
      key = [klass, id]
12
      if tick = @@stack.pop
13
        data = (@@map[key] ||= [0, 0.0, 0.0, key])
15
      stack = @@stacks[Thread.current]
16
      if tick = stack.pop
17
        threadMap = (@@maps[Thread.current] ||= {})
18
        data = (threadMap[key] ||= [0, 0.0, 0.0, key])
14 19
        data[0] += 1
15 20
        cost = now - tick[0]
16 21
        data[1] += cost
17 22
        data[2] += cost - tick[1]
18
        @@stack[-1][1] += cost if @@stack[-1]
23
        stack[-1][1] += cost if stack[-1]
19 24
      end
20 25
    end
21 26
  }
22 27
module_function
23 28
  def start_profile
24 29
    @@start = Process.times[0]
25
    @@stack = []
26
    @@map = {}
30
    @@stacks = {}
31
    @@maps = {}
27 32
    set_trace_func PROFILE_PROC
28 33
  end
29 34
  def stop_profile
......
33 38
    stop_profile
34 39
    total = Process.times[0] - @@start
35 40
    if total == 0 then total = 0.01 end
36
    data = @@map.values
41
    totals = {}
42
    @@maps.each { |thread, threadMap|
43
      threadMap.each {|key, data|
44
        total_data = (totals[key] ||= [0, 0.0, 0.0, key])
45
        total_data[0] += data[0]
46
        total_data[1] += data[1] #TODO summing this field doesn't make much sense? Needs discussion on ruby-core
47
        total_data[2] += data[2] 
48
      }
49
      # Print the thread output
50
      print_thread(f, thread, threadMap.values, total) if @@maps.length > 1
51
    }
52

  
53
    data = totals.values
37 54
    data = data.sort_by{|x| -x[2]}
38
    sum = 0
55

  
56
    f.printf "Summary\n" if @@maps.length > 1
57
    print_header(f)
58
    print_call_sites(f, data, total)
59
    print_footer(f, total)
60
  end
61
  def get_name(klass, id)
62
    name = klass.to_s || ""
63
    if klass.kind_of? Class
64
      name += "#"
65
    else
66
      name += "."
67
    end
68
    name + id.id2name
69
  end
70
  def print_thread(f, thread, data, total)
71
    data = data.sort_by{|x| -x[2]}
72
    f.printf " %s\n", thread
73
    print_header(f)
74
    print_call_sites(f, data, total)
75
    print_footer(f, total)
76
    f.printf "\n"
77
  end
78
  def print_header(f)
39 79
    f.printf "  %%   cumulative   self              self     total\n"
40 80
    f.printf " time   seconds   seconds    calls  ms/call  ms/call  name\n"
81
  end
82
  def print_call_sites(f, data, total)
83
    sum = 0
41 84
    for d in data
42 85
      sum += d[2]
43 86
      f.printf "%6.2f %8.2f  %8.2f %8d ", d[2]/total*100, sum, d[2], d[0]
44 87
      f.printf "%8.2f %8.2f  %s\n", d[2]*1000/d[0], d[1]*1000/d[0], get_name(*d[3])
45 88
    end
89
  end
90
  def print_footer(f, total)
46 91
    f.printf "%6.2f %8.2f  %8.2f %8d ", 0.0, total, 0.0, 1     # ???
47 92
    f.printf "%8.2f %8.2f  %s\n", 0.0, total*1000, "#toplevel" # ???
48 93
  end
49
  def get_name(klass, id)
50
    name = klass.to_s || ""
51
    if klass.kind_of? Class
52
      name += "#"
53
    else
54
      name += "."
55
    end
56
    name + id.id2name
57
  end
58 94
  private :get_name
95
  private :print_thread
96
  private :print_header
97
  private :print_call_sites
98
  private :print_footer
59 99
end