Skip to content

Instantly share code, notes, and snippets.

@DavidEGrayson

DavidEGrayson/profile_rbx1.2.4.txt

Created November 12, 2011 19:32
Show Gist options
  • Save DavidEGrayson/1360989 to your computer and use it in GitHub Desktop.
Save DavidEGrayson/1360989 to your computer and use it in GitHub Desktop.
Download ZIP
Rubinius 1.2.4 hash collision profiling
Raw
profile_rbx1.2.4.txt
Thread 0: total running time: 10.186666s
% cumulative self self total
time seconds seconds calls ms/call ms/call name
------------------------------------------------------------
23.05 7.49 2.35 526336 0.00 0.01 Thread.detect_recursion
14.79 2.94 1.51 552960 0.00 0.01 Struct::eql?<243> {}
10.32 8.72 1.05 522240 0.00 0.02 Struct#eql?
6.94 9.55 0.71 522245 0.00 0.02 Hash::Entry#match?
5.42 3.67 0.55 530441 0.00 0.01 Array#each
4.38 4.32 0.45 522240 0.00 0.01 Struct::eql?<243> {}
3.96 0.54 0.40 552960 0.00 0.00 Numeric#eql?
3.88 0.38 0.40 1130511 0.00 0.00 Symbol#to_s
3.19 10.04 0.33 4096 0.08 2.45 Hash#[]=
2.97 0.28 0.30 1130505 0.00 0.00 String#to_sym
2.67 0.25 0.27 2131968 0.00 0.00 Kernel#__class__
2.65 0.33 0.27 530432 0.00 0.00 Struct#_attrs
2.17 0.27 0.22 526336 0.00 0.00 Kernel#===
1.98 0.19 0.20 1118208 0.00 0.00 Kernel#instance_variable_get
1.35 0.12 0.14 1052672 0.00 0.00 Kernel#object_id
1.19 0.10 0.12 1048592 0.00 0.00 Kernel#equal?
1.04 0.10 0.11 530434 0.00 0.00 Rubinius::LookupTable#[]=
0.87 0.08 0.09 530432 0.00 0.00 Rubinius::LookupTable#delete
0.71 0.06 0.07 530432 0.00 0.00 Thread.current
0.69 0.07 0.07 589834 0.00 0.00 Rubinius::Tuple#at
0.68 0.06 0.07 530434 0.00 0.00 Rubinius::LookupTable#[]
0.67 0.06 0.07 522248 0.00 0.00 Symbol.===
0.62 0.05 0.06 534806 0.00 0.00 Fixnum.===
0.61 0.06 0.06 552960 0.00 0.00 Kernel#instance_of?
0.61 0.06 0.06 522241 0.00 0.00 Kernel#==
0.43 0.04 0.04 183 0.24 0.24 GC.collect_young
0.36 0.04 0.04 1 36.23 36.23 Rubinius::Tooling.disable
0.25 0.06 0.03 12288 0.00 0.00 Struct::initialize<114> {}
0.24 0.10 0.02 4096 0.01 0.02 Thread.detect_outermost_recursion
0.23 0.04 0.02 12288 0.00 0.00 Struct::hash<275> {}
0.17 0.02 0.02 12288 0.00 0.00 Array#[]
0.11 0.02 0.01 9 1.21 1.75 Hash#redistribute
0.08 0.09 0.01 4096 0.00 0.02 Struct#initialize
0.07 0.01 0.01 4096 0.00 0.00 Hash#new_entry
0.07 0.09 0.01 4374 0.00 0.02 Class#new
0.06 10.14 0.01 4096 0.00 2.48 Object::__script__<9> {}
0.06 10.15 0.01 273 0.02 37.17 Range#each
0.06 0.11 0.01 4096 0.00 0.03 Struct#hash
0.06 0.06 0.01 12288 0.00 0.01 Enumerable::each_with_index<448> {}
0.04 0.10 0.00 4096 0.00 0.02 P.new
0.04 0.06 0.00 4096 0.00 0.01 Struct::hash<275> {}
0.03 0.08 0.00 4096 0.00 0.02 Enumerable#each_with_index
0.03 0.00 0.00 6141 0.00 0.00 Hash#key_index
0.02 0.00 0.00 18413 0.00 0.00 Rubinius::Tuple#[]
0.02 0.00 0.00 12288 0.00 0.00 Kernel#instance_variable_set
14 methods omitted
59 methods called a total of 17,428,628 times
Raw
profile_rbx1.2.4_graph.txt
===== Thread 0 =====
Total running time: 9.488942s
index % time self children called name
----------------------------------------------------------
[1] 99.5 0.00 9.44 1 Range#each [1]
0.00 9.44 16 Object::__script__<7> {} [2]
-------------------------------------------------------
0.00 9.44 1 Range#each [1]
[2] 99.5 0.00 9.44 16 Object::__script__<7> {} [2]
0.00 9.44 16 Range#each [3]
-------------------------------------------------------
0.00 9.44 16 Object::__script__<7> {} [2]
[3] 99.5 0.00 9.44 16 Range#each [3]
0.00 9.44 256 Object::__script__<8> {} [4]
-------------------------------------------------------
0.00 9.44 16 Range#each [3]
[4] 99.5 0.00 9.44 256 Object::__script__<8> {} [4]
0.01 9.43 256 Range#each [5]
0.00 0.00 256 Class#new
-------------------------------------------------------
0.00 9.44 256 Object::__script__<8> {} [4]
[5] 99.5 0.01 9.43 256 Range#each [5]
0.01 9.43 4096 Object::__script__<9> {} [6]
-------------------------------------------------------
0.01 9.43 256 Range#each [5]
[6] 99.4 0.01 9.43 4096 Object::__script__<9> {} [6]
0.32 9.01 4096 Hash#[]= [7]
0.00 0.09 4096 P.new [23]
-------------------------------------------------------
0.01 9.43 4096 Object::__script__<9> {} [6]
[7] 98.4 0.32 9.01 4096 Hash#[]= [7]
0.72 8.15 522245 Hash::Entry#match? [8]
0.01 0.10 4096 Struct#hash [21]
0.01 0.01 9 Hash#redistribute
0.02 0.00 41 GC.collect_young
0.01 0.00 4096 Hash#new_entry
-------------------------------------------------------
0.32 9.01 4096 Hash#[]= [7]
[8] 93.4 0.72 8.15 522245 Hash::Entry#match? [8]
1.04 6.98 522240 Struct#eql? [9]
0.07 0.00 522245 Symbol.=== [33]
0.06 0.00 522245 Fixnum.=== [37]
-------------------------------------------------------
0.72 8.15 522245 Hash::Entry#match? [8]
[9] 84.5 1.04 6.98 522240 Struct#eql? [9]
2.30 4.43 522240 Thread.detect_recursion [10]
0.12 0.00 1044480 Kernel#__class__ [20]
0.06 0.00 522240 Kernel#== [36]
0.06 0.00 522240 Kernel#equal? [39]
0.00 0.00 27 GC.collect_young
-------------------------------------------------------
1.04 6.98 522240 Struct#eql? [9]
[10] 70.9 2.30 4.43 522240 Thread.detect_recursion [10]
0.53 3.14 522240 Struct::eql?<243> {} [11]
0.24 0.06 522240 Kernel#=== [16]
0.14 0.00 1044480 Kernel#object_id [19]
0.09 0.00 522240 Rubinius::LookupTable#[]= [22]
0.09 0.00 522240 Rubinius::LookupTable#delete [26]
0.07 0.00 522240 Thread.current [30]
0.07 0.00 522240 Rubinius::LookupTable#[] [32]
-------------------------------------------------------
2.30 4.43 522240 Thread.detect_recursion [10]
[11] 38.7 0.53 3.14 522240 Struct::eql?<243> {} [11]
1.49 1.32 552960 Struct::eql?<243> {} [12]
0.26 0.06 522240 Struct#_attrs [14]
0.01 0.00 23 GC.collect_young
-------------------------------------------------------
0.53 3.14 522240 Struct::eql?<243> {} [11]
[12] 29.6 1.49 1.32 552960 Struct::eql?<243> {} [12]
0.41 0.15 552960 Numeric#eql? [13]
0.31 0.00 1105920 Symbol#to_s [15]
0.25 0.00 1105920 String#to_sym [17]
0.18 0.00 1105920 Kernel#instance_variable_get [18]
0.01 0.00 85 GC.collect_young
-------------------------------------------------------
1.49 1.32 552960 Struct::eql?<243> {} [12]
[13] 5.9 0.41 0.15 552960 Numeric#eql? [13]
0.07 0.00 552960 Kernel#instance_of? [28]
0.07 0.00 552960 Kernel#__class__ [31]
-------------------------------------------------------
0.53 3.14 522240 Struct::eql?<243> {} [11]
[14] 3.4 0.26 0.06 522240 Struct#_attrs [14]
0.06 0.00 522240 Kernel#__class__ [38]
-------------------------------------------------------
1.49 1.32 552960 Struct::eql?<243> {} [12]
[15] 3.3 0.31 0.00 1105920 Symbol#to_s [15]
-------------------------------------------------------
2.30 4.43 522240 Thread.detect_recursion [10]
[16] 3.1 0.24 0.06 522240 Kernel#=== [16]
0.06 0.00 522240 Kernel#equal? [41]
-------------------------------------------------------
1.49 1.32 552960 Struct::eql?<243> {} [12]
[17] 2.6 0.25 0.00 1105920 String#to_sym [17]
-------------------------------------------------------
1.49 1.32 552960 Struct::eql?<243> {} [12]
[18] 1.9 0.18 0.00 1105920 Kernel#instance_variable_get [18]
-------------------------------------------------------
2.30 4.43 522240 Thread.detect_recursion [10]
[19] 1.5 0.14 0.00 1044480 Kernel#object_id [19]
-------------------------------------------------------
1.04 6.98 522240 Struct#eql? [9]
[20] 1.3 0.12 0.00 1044480 Kernel#__class__ [20]
-------------------------------------------------------
0.32 9.01 4096 Hash#[]= [7]
[21] 1.1 0.01 0.10 4096 Struct#hash [21]
0.03 0.07 4096 Thread.detect_outermost_recursion [24]
0.00 0.00 4096 Struct#size
-------------------------------------------------------
2.30 4.43 522240 Thread.detect_recursion [10]
[22] 1.0 0.09 0.00 522240 Rubinius::LookupTable#[]= [22]
-------------------------------------------------------
0.01 9.43 4096 Object::__script__<9> {} [6]
[23] 1.0 0.00 0.09 4096 P.new [23]
0.01 0.08 4096 Class#new [25]
-------------------------------------------------------
0.01 0.10 4096 Struct#hash [21]
[24] 1.0 0.03 0.07 4096 Thread.detect_outermost_recursion [24]
0.02 0.05 4096 Thread.detect_recursion [34]
-------------------------------------------------------
0.00 0.09 4096 P.new [23]
[25] 0.9 0.01 0.08 4096 Class#new [25]
0.01 0.07 4096 Struct#initialize [27]
-------------------------------------------------------
2.30 4.43 522240 Thread.detect_recursion [10]
[26] 0.9 0.09 0.00 522240 Rubinius::LookupTable#delete [26]
-------------------------------------------------------
0.01 0.08 4096 Class#new [25]
[27] 0.9 0.01 0.07 4096 Struct#initialize [27]
0.01 0.07 4096 Enumerable#each_with_index [29]
-------------------------------------------------------
0.41 0.15 552960 Numeric#eql? [13]
[28] 0.8 0.07 0.00 552960 Kernel#instance_of? [28]
-------------------------------------------------------
0.01 0.07 4096 Struct#initialize [27]
[29] 0.8 0.01 0.07 4096 Enumerable#each_with_index [29]
0.01 0.06 12288 Enumerable::each_with_index<448> {} [35]
-------------------------------------------------------
2.30 4.43 522240 Thread.detect_recursion [10]
[30] 0.8 0.07 0.00 522240 Thread.current [30]
-------------------------------------------------------
0.41 0.15 552960 Numeric#eql? [13]
[31] 0.8 0.07 0.00 552960 Kernel#__class__ [31]
-------------------------------------------------------
2.30 4.43 522240 Thread.detect_recursion [10]
[32] 0.7 0.07 0.00 522240 Rubinius::LookupTable#[] [32]
-------------------------------------------------------
0.72 8.15 522245 Hash::Entry#match? [8]
[33] 0.7 0.07 0.00 522245 Symbol.=== [33]
-------------------------------------------------------
0.03 0.07 4096 Thread.detect_outermost_recursion [24]
[34] 0.7 0.02 0.05 4096 Thread.detect_recursion [34]
0.01 0.04 4096 Struct::hash<275> {} [42]
0.00 0.00 4096 Kernel#===
0.00 0.00 8192 Kernel#object_id
-------------------------------------------------------
0.01 0.07 4096 Enumerable#each_with_index [29]
[35] 0.7 0.01 0.06 12288 Enumerable::each_with_index<448> {} [35]
0.03 0.03 12288 Struct::initialize<114> {} [40]
-------------------------------------------------------
1.04 6.98 522240 Struct#eql? [9]
[36] 0.7 0.06 0.00 522240 Kernel#== [36]
-------------------------------------------------------
0.72 8.15 522245 Hash::Entry#match? [8]
[37] 0.7 0.06 0.00 522245 Fixnum.=== [37]
-------------------------------------------------------
0.26 0.06 522240 Struct#_attrs [14]
[38] 0.7 0.06 0.00 522240 Kernel#__class__ [38]
-------------------------------------------------------
1.04 6.98 522240 Struct#eql? [9]
[39] 0.6 0.06 0.00 522240 Kernel#equal? [39]
-------------------------------------------------------
0.01 0.06 12288 Enumerable::each_with_index<448> {} [35]
[40] 0.6 0.03 0.03 12288 Struct::initialize<114> {} [40]
0.02 0.00 12288 Array#[]
0.00 0.00 12288 Symbol#to_s
0.00 0.00 12288 String#to_sym
0.00 0.00 12288 Kernel#instance_variable_set
-------------------------------------------------------
0.24 0.06 522240 Kernel#=== [16]
[41] 0.6 0.06 0.00 522240 Kernel#equal? [41]
-------------------------------------------------------
0.02 0.05 4096 Thread.detect_recursion [34]
[42] 0.5 0.01 0.04 4096 Struct::hash<275> {} [42]
0.02 0.01 12288 Struct::hash<275> {}
0.00 0.00 4096 Struct#_attrs
-------------------------------------------------------
[43] 0.4 0.00 0.04 1 Rubinius::Profiler::Instrumenter#stop [43]
0.00 0.04 1 Rubinius::Profiler::Instrumenter#__stop__ [44]
-------------------------------------------------------
0.00 0.04 1 Rubinius::Profiler::Instrumenter#stop [43]
[44] 0.4 0.00 0.04 1 Rubinius::Profiler::Instrumenter#__stop__ [44]
0.04 0.00 1 Rubinius::Tooling.disable [45]
-------------------------------------------------------
0.00 0.04 1 Rubinius::Profiler::Instrumenter#__stop__ [44]
[45] 0.4 0.04 0.00 1 Rubinius::Tooling.disable [45]
-------------------------------------------------------
33 methods omitted
78 methods called a total of 0 times
Raw
test.rb
require 'profiler'
profiler = Rubinius::Profiler::Instrumenter.new
profiler.start
P = Struct.new :x, :y, :z
hash = {}
(0..15).each do |x|
(0..15).each do |y|
(0..15).each do |z|
key = P.new x, y, z
hash[key] = true
end
end
end
profiler.stop
profiler.show
@DavidEGrayson
Copy link
Author

Most of the running time is spent inside Hash::Entry#match?. The time spent in Struct#hash is negligible.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment