Module: Profiler

Defined in:
lib/rpdf2txt-rockit/profiler.rb

Constant Summary collapse

@@start = 
TimesClass.times.utime
@@invocation_stack =

Method invocation stack with one entry for each invocation:

Time at entry, Total times in subfunction also being logged, MethodId

[[0, 0, "#toplevel".intern]]
@@map =

One entry for each method: NumCalls, TotalTime, OnlyMyTime, Callers

{"#toplevel".intern => [1, 0, 0]}
@@arguments =

One entry for each method: hash mapping args.inspect to count

Hash.new
@@time_limit = 
5 * 60

Class Method Summary collapse

Class Method Details

.__enter__(method, *args) ⇒ Object 



30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
 
# File 'lib/rpdf2txt-rockit/profiler.rb', line 30

def __enter__(method, *args)
  now = TimesClass.times.utime
  if @@time_limit
    if now - @@start > @@time_limit
	STDERR.puts "Profiling time limit violated. Run terminated."
	STDERR.puts profile_summary(true, true)
	exit(-1)
    end
  end
  @@invocation_stack.push [now, 0.0, method]
  begin
    @@arguments[method][args.inspect] += 1
  rescue Exception
    @@arguments[method] = Hash.new(0)
    retry
  end
end

.__leave__(method, *retargs) ⇒ Object 



49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
 
# File 'lib/rpdf2txt-rockit/profiler.rb', line 49

def __leave__(method, *retargs)
  now = TimesClass.times.utime
  tick, data = @@invocation_stack.pop, @@map[method]
  unless data
    data = [0.0, 0.0, 0.0, Hash.new(0)] 
    @@map[method] = data
  end
  data[0] += 1
  total_time_this_invocation = now - tick[0]
  data[1] += total_time_this_invocation
  data[2] += total_time_this_invocation - tick[1]
  data[3][caller[1]] += 1
  @@invocation_stack[-1][1] += total_time_this_invocation
  return *retargs
end

.profile_summary(writeCallers = false, writeArguments = false) ⇒ Object 



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
 
# File 'lib/rpdf2txt-rockit/profiler.rb', line 74

def Profiler.profile_summary(writeCallers = false, writeArguments = false)
  total_elapsed = TimesClass.times.utime - @@start
  str =  "Profiling summary\n"
  str += "*****************\n"
  str += "Total elapsed time: #{total_elapsed} seconds\n"
  unwind_invocation_stack if @@invocation_stack.length > 1
  total = @@invocation_stack.last[1]
  time_in_nonprofiled = total_elapsed - total
  str += "Time spent in non-profiled methods: #{time_in_nonprofiled} sec\n"
  str += "Time in profiled methods:\n"
  if total == 0 then total = 0.01 end
  @@map["#toplevel".intern][1] = total
  data = @@map.to_a.sort{|a,b| b[1][2] <=> a[1][2]}
  sum = 0
  str += "  %%   cumulative   self              self     total\n"
  str += " time   seconds   seconds    calls  ms/call  ms/call  name\n"
  str += " ---------------------------------------------------------\n"
  for d in data
    method = d[0]
    next if method == "#toplevel".intern 
    d = d[1]
    sum += d[2]
    str += "%6.2f %8.2f  %8.2f %8d " % [d[2]/total*100, sum, d[2], d[0]]
    str += "%8.2f %8.2f  %s\n" % [d[2]*1000/d[0], d[1]*1000/d[0], 
	method.id2name]
    if writeCallers
	str += "  Call sites:\n"
	d[3].to_a.sort {|a,b| b[1] <=> a[1]}.each do |callersite, count|
 str += "   #{count}: " + callersite.split("/").last + "\n"
	end
    end
    if writeArguments and d[0] > 1
	str += "  Arguments:\n"
	counts, num_prev_seen = Hash.new(0), 0
	@@arguments[method].to_a.sort {|a,b| b[1] <=> a[1]}.each do |args, cnt|
 # str += "   #{cnt}: " + args + "\n" if cnt > 1
 counts[cnt] += cnt
 num_prev_seen += cnt if cnt > 1
	end
	proportion_prev_seen = num_prev_seen*100.0/d[0]
	proportion_unique = 100.0 - proportion_prev_seen
	str += "   %3.2f%% (#{d[0].to_i - num_prev_seen}) of calls with unique args" % proportion_unique
	if proportion_unique != 100.0
 str += ", and\n"
 str += "   %3.2f%% (#{num_prev_seen}) of calls with args that were used several times\n" % proportion_prev_seen
 str += "    distr: #{counts.inspect}"
	end
	str += "\n"
    end
    str += "\n" if writeCallers or writeArguments
  end
  return str
end

.start(timeLimitInMinutes = nil) ⇒ Object 



20
21
22
23
24
25
26
27
 
# File 'lib/rpdf2txt-rockit/profiler.rb', line 20

def start(timeLimitInMinutes = nil)
  if timeLimitInMinutes
    @@time_limit = timeLimitInMinutes * 60
  else
    @@time_limit = nil
  end
  @@start = Float(TimesClass.times.utime)
end

.unwind_invocation_stack ⇒ Object

Go through the invocation stack and leave all methods.



67
68
69
70
71
 
# File 'lib/rpdf2txt-rockit/profiler.rb', line 67

def unwind_invocation_stack
  while @@invocation_stack.length > 1
    __leave__(@@invocation_stack.pop[2])
  end
end