Skip to content

Commit

Permalink
Cleaning up DotPrinter a little bit.
Browse files Browse the repository at this point in the history
  • Loading branch information
@adamsanderson
adamsanderson committed Jul 29, 2010
1 parent 53bd4b0 commit a3bc5f0
Show file tree
Hide file tree
Showing 2 changed files with 102 additions and 150 deletions.
120 changes: 60 additions & 60 deletions examples/graph.dot
View file
Original file line number Diff line number Diff line change
@@ -1,96 +1,96 @@
digraph "Profile" {
label="WALL_TIME >=0%\nTotal: 1.391186"
label="WALL_TIME >=0%\nTotal: 1.401074"
subgraph "Thread 2148237740" {
2159423900 [label="[]=\n(0%)"];
2159423980 [label="find_primes\n(99%)"];
2159423980 -> 2159424740 [label="2/2"];
2159424040 [label="setup\n(100%)"];
2159424040 -> 2159424660 [label="1/2"];
2159424040 -> 2159424420 [label="1/1"];
2159424120 [label="%\n(15%)"];
2159424200 [label="new\n(0%)"];
2159424200 -> 2159424500 [label="2/2"];
2159424200 -> 2159424980 [label="2/2"];
2159424280 [label="rand\n(0%)"];
2159424360 [label="-\n(0%)"];
2159424420 [label="go\n(49%)"];
2159424420 -> 2159424660 [label="1/2"];
2159424500 [label="initialize\n(0%)"];
2159424580 [label="each_index\n(1%)"];
2159424580 -> 2159424280 [label="20000/20000"];
2159424580 -> 2159423900 [label="20000/20000"];
2159424660 [label="run_primes\n(100%)"];
2159424660 -> 2159423980 [label="2/2"];
2159424660 -> 2159424820 [label="2/2"];
2159424740 [label="select\n(99%)"];
2159424740 -> 2159425060 [label="20000/20000"];
2159424820 [label="make_random_array\n(1%)"];
2159424820 -> 2159424580 [label="2/2"];
2159424820 -> 2159424200 [label="2/2"];
2159424900 [label="upto\n(97%)"];
2159424900 -> 2159424120 [label="1574781/1574781"];
2159424900 -> 2159425220 [label="1574781/1574781"];
2159424980 [label="allocate\n(0%)"];
2159425060 [label="is_prime\n(98%)"];
2159425060 -> 2159424900 [label="20000/20000"];
2159425060 -> 2159424360 [label="20000/20000"];
2159425220 [label="==\n(12%)"];
2159428720 [label="run_primes\n(100%)"];
2159428720 -> 2159429580 [label="2/2"];
2159428720 -> 2159428880 [label="2/2"];
2159428800 [label="[]=\n(0%)"];
2159428880 [label="make_random_array\n(1%)"];
2159428880 -> 2159429420 [label="2/2"];
2159428880 -> 2159429040 [label="2/2"];
2159428960 [label="%\n(15%)"];
2159429040 [label="new\n(0%)"];
2159429040 -> 2159429340 [label="2/2"];
2159429040 -> 2159429820 [label="2/2"];
2159429120 [label="rand\n(0%)"];
2159429200 [label="-\n(0%)"];
2159429260 [label="setup\n(100%)"];
2159429260 -> 2159430040 [label="1/1"];
2159429260 -> 2159428720 [label="1/2"];
2159429340 [label="initialize\n(0%)"];
2159429420 [label="each_index\n(1%)"];
2159429420 -> 2159429120 [label="20000/20000"];
2159429420 -> 2159428800 [label="20000/20000"];
2159429500 [label="is_prime\n(98%)"];
2159429500 -> 2159429740 [label="20000/20000"];
2159429500 -> 2159429200 [label="20000/20000"];
2159429580 [label="find_primes\n(99%)"];
2159429580 -> 2159429660 [label="2/2"];
2159429660 [label="select\n(99%)"];
2159429660 -> 2159429500 [label="20000/20000"];
2159429740 [label="upto\n(97%)"];
2159429740 -> 2159428960 [label="1593581/1593581"];
2159429740 -> 2159429920 [label="1593581/1593581"];
2159429820 [label="allocate\n(0%)"];
2159429920 [label="==\n(12%)"];
2159430040 [label="go\n(50%)"];
2159430040 -> 2159428720 [label="1/2"];
}
subgraph cluster_2159099520 {
subgraph cluster_2159104080 {
label = "Object";
fontcolor = "#666666";
color = "#666666";
2159425060;
2159424820;
2159424660;
2159423980;
2159429580;
2159429500;
2159428880;
2159428720;
}
subgraph cluster_2159099380 {
subgraph cluster_2159104200 {
label = "Integer";
fontcolor = "#666666";
color = "#666666";
2159424900;
2159429740;
}
subgraph cluster_2159099220 {
subgraph cluster_2159104380 {
label = "PrintersTest";
fontcolor = "#666666";
color = "#666666";
2159424420;
2159424040;
2159430040;
2159429260;
}
subgraph cluster_2159099300 {
subgraph cluster_2159104140 {
label = "Array";
fontcolor = "#666666";
color = "#666666";
2159424740;
2159424580;
2159424500;
2159423900;
2159429660;
2159429420;
2159429340;
2159428800;
}
subgraph cluster_2159099460 {
subgraph cluster_2159104280 {
label = "<Class::Array>";
fontcolor = "#666666";
color = "#666666";
2159424980;
2159429820;
}
subgraph cluster_2159099040 {
subgraph cluster_2159103860 {
label = "Class";
fontcolor = "#666666";
color = "#666666";
2159424200;
2159429040;
}
subgraph cluster_2159099100 {
subgraph cluster_2159104000 {
label = "Kernel";
fontcolor = "#666666";
color = "#666666";
2159424280;
2159429120;
}
subgraph cluster_2159099580 {
subgraph cluster_2159104340 {
label = "Fixnum";
fontcolor = "#666666";
color = "#666666";
2159425220;
2159424360;
2159424120;
2159429920;
2159429200;
2159428960;
}
}
132 changes: 42 additions & 90 deletions lib/ruby-prof/dot_printer.rb
View file
Original file line number Diff line number Diff line change
Expand Up @@ -12,13 +12,17 @@ module RubyProf
# printer = RubyProf::DotPrinter.new(result)
# printer.print(STDOUT)
#
# You can use either dot viewer such as GraphViz, or the dot command line tool
# to reformat the output into a wide variety of outputs:
#
# dot -Tpng graph.dot > graph.png
#
class DotPrinter < RubyProf::AbstractPrinter
CLASS_COLOR = '"#666666"'
# Creates the DotPrinter using a RubyProf::Result.
def initialize(result)
super(result)
@thread_times = {}
@seen_methods = Set.new
compute_times
end

# Print a graph report to the provided output.
Expand All @@ -38,54 +42,60 @@ def print(output = STDOUT, options = {})
@output = output
setup_options(options)
mode = RubyProf.constants.find{|c| RubyProf.const_get(c) == RubyProf.measure_mode}
total_time = @thread_times.values.inject{|a,b| a+b}
total_time = thread_times.values.inject{|a,b| a+b}

@output.puts 'digraph "Profile" {'
@output.puts "label=\"#{mode} >=#{min_percent}%\\nTotal: #{total_time}\""
puts 'digraph "Profile" {'
puts "label=\"#{mode} >=#{min_percent}%\\nTotal: #{total_time}\""
print_threads
@output.puts '}'
puts '}'
end

private

def compute_times
# Sort methods from longest to shortest total time
@result.threads.each do |thread_id, methods|
methods = methods.sort

toplevel = methods.last
total_time = toplevel.total_time
total_time = 0.01 if total_time == 0
@thread_times[thread_id] = total_time
# Computes the total time per thread:
def thread_times
@thread_times ||= begin
times = {}
@result.threads.each do |thread_id, methods|
toplevel = methods.sort.last

total_time = toplevel.total_time
# This looks like a hack for very small times... from GraphPrinter
total_time = 0.01 if total_time == 0
times[thread_id] = total_time
end

times
end
end

def print_threads
# sort assumes that spawned threads have higher object_ids
@result.threads.sort.each do |thread_id, methods|
@output.puts "subgraph \"Thread #{thread_id}\" {"
puts "subgraph \"Thread #{thread_id}\" {"

print_methods(thread_id, methods)
@output.puts "}"
puts "}"

print_classes(thread_id, methods)
end
end

def dot_id(method)
method.object_id
# Determines an ID to use to represent the subject in the Dot file.
def dot_id(subject)
subject.object_id
end

def print_methods(thread_id, methods)
total_time = @thread_times[thread_id]
total_time = thread_times[thread_id]
# Print each method in total time order
methods.reverse_each do |method|
total_percentage = (method.total_time/total_time) * 100
self_percentage = (method.self_time/total_time) * 100

next if total_percentage < min_percent
name = method_name(method).split("#").last
@output.puts "#{dot_id(method)} [label=\"#{name}\\n(#{total_percentage.round}%)\"];"
puts "#{dot_id(method)} [label=\"#{name}\\n(#{total_percentage.round}%)\"];"
@seen_methods << method
print_children(total_time, method)
end
Expand All @@ -97,20 +107,15 @@ def print_classes(thread_id, methods)
big_methods, small_methods = methods.partition{|m| @seen_methods.include? m}

if !big_methods.empty?
@output.puts "subgraph cluster_#{cls.object_id} {"
@output.puts "label = \"#{cls}\";"
@output.puts "fontcolor = \"#666666\";"
@output.puts "color = \"#666666\";"
puts "subgraph cluster_#{cls.object_id} {"
puts "label = \"#{cls}\";"
puts "fontcolor = #{CLASS_COLOR};"
puts "color = #{CLASS_COLOR};"
big_methods.each do |m|
@output.puts "#{m.object_id};"
puts "#{m.object_id};"
end
@output.puts "}"
end

#small_methods.each do |m|
# @output.puts "#{m.object_id} [label=\" \" shape=point];"
#end

puts "}"
end
end
end

Expand All @@ -121,67 +126,14 @@ def print_children(total_time, method)
next if target_percentage < min_percent

# Get children method
@output.puts "#{dot_id(method)} -> #{dot_id(child.target)} [label=\"#{child.called}/#{child.target.called}\"];"

# @output << sprintf("%#{TIME_WIDTH}.2f", child.total_time)
# @output << sprintf("%#{TIME_WIDTH}.2f", child.self_time)
# @output << sprintf("%#{TIME_WIDTH}.2f", child.wait_time)
# @output << sprintf("%#{TIME_WIDTH}.2f", child.children_time)
#
# call_called = "#{child.called}/#{child.target.called}"
# @output << sprintf("%#{CALL_WIDTH}s", call_called)
# @output << sprintf(" %s", child.target.full_name)
# @output << "\n"
end
end
end
end

if __FILE__ == $0
require File.dirname(__FILE__) + '/../ruby-prof.rb'
puts "Running sample:"
class DogHouse
def initialize(count)
@count = count
@dogs = []
add_dogs(count)
end

def add_dogs(count)
count.times do
@dogs << Dog.new
puts "#{dot_id(method)} -> #{dot_id(child.target)} [label=\"#{child.called}/#{child.target.called}\"];"
end
end

def feed
@dogs.each{|d| d.feed }
end

def let_out
@dogs.each{|d| @dogs.delete(d); d.play }
end
end

class Dog
def feed
puts "Woof munch munch"
# Silly little helper for printing to the @output
def puts(str)
@output.puts(str)
end

def play
puts "Woof Waggle"
sleep 0.01 # hard work!
end
end

RubyProf.start
5.times do |i|
dh = DogHouse.new(i)
dh.feed
dh.let_out
end
result = RubyProf.stop

open("example.dot","w") do |io|
RubyProf::DotPrinter.new(result).print(io)
end
end

0 comments on commit a3bc5f0

Please sign in to comment.