Graph Profiles¶ ↑
Graph profiles show how long each method runs, which methods call it and which methods it calls.
As an example, here is the output from running printers_test.rb:
Measure Mode: wall_time Thread ID: 70310439543100 Fiber ID: 70310456289620 Total Time: 0.05264616012573242 Sort by: total_time
%total %self total self wait child calls name
100.00% 0.01% 0.053 0.000 0.000 0.053 1 PrintersTest#setup
0.053 0.000 0.000 0.053 1/1 Object#run_primes
0.053 0.000 0.000 0.053 1/1 PrintersTest#setup
99.99% 0.01% 0.053 0.000 0.000 0.053 1 Object#run_primes
0.052 0.000 0.000 0.052 1/1 Object#find_primes
0.001 0.000 0.000 0.001 1/1 Object#make_random_array
0.000 0.000 0.000 0.000 1/1 Object#find_largest
0.052 0.000 0.000 0.052 1/1 Object#run_primes
98.35% 0.00% 0.052 0.000 0.000 0.052 1 Object#find_primes
0.052 0.000 0.000 0.051 1/1 Array#select
0.052 0.000 0.000 0.051 1/1 Object#find_primes
98.34% 0.61% 0.052 0.000 0.000 0.051 1 Array#select
0.051 0.000 0.000 0.051 1000/1000 Object#is_prime
0.051 0.000 0.000 0.051 1000/1000 Array#select
97.74% 0.93% 0.051 0.000 0.000 0.051 1000 Object#is_prime
0.051 0.051 0.000 0.000 1000/1001 Integer#upto
0.000 0.000 0.000 0.000 1/1001 Object#find_largest
0.051 0.051 0.000 0.000 1000/1001 Object#is_prime
96.91% 96.91% 0.051 0.051 0.000 0.000 1001 Integer#upto
0.001 0.000 0.000 0.001 1/1 Object#run_primes
1.51% 0.00% 0.001 0.000 0.000 0.001 1 Object#make_random_array
0.001 0.000 0.000 0.000 1/1 Array#each_index
0.000 0.000 0.000 0.000 1/1 Class#new
0.001 0.000 0.000 0.000 1/1 Object#make_random_array
1.50% 0.56% 0.001 0.000 0.000 0.000 1 Array#each_index
0.000 0.000 0.000 0.000 1000/1000 Kernel#rand
0.000 0.000 0.000 0.000 1000/1000 Array#each_index
0.94% 0.72% 0.000 0.000 0.000 0.000 1000 Kernel#rand
0.000 0.000 0.000 0.000 1000/1000 Kernel#respond_to_missing?
0.000 0.000 0.000 0.000 1000/1000 Kernel#rand 0.22% 0.22% 0.000 0.000 0.000 0.000 1000 Kernel#respond_to_missing?
0.000 0.000 0.000 0.000 1/1 Object#run_primes
0.12% 0.02% 0.000 0.000 0.000 0.000 1 Object#find_largest
0.000 0.000 0.000 0.000 1/1001 Integer#upto
0.000 0.000 0.000 0.000 1/1 Array#first
0.000 0.000 0.000 0.000 1/1 Object#make_random_array
0.01% 0.00% 0.000 0.000 0.000 0.000 1 Class#new
0.000 0.000 0.000 0.000 1/1 Array#initialize
0.000 0.000 0.000 0.000 1/1 Class#new 0.01% 0.01% 0.000 0.000 0.000 0.000 1 Array#initialize
0.000 0.000 0.000 0.000 1/1 Object#find_largest 0.00% 0.00% 0.000 0.000 0.000 0.000 1 Array#first
Overview¶ ↑
Dashed lines divide the report into entries, with one entry per method. Entries are sorted by total time which is the time spent in the method plus its children.
Each entry has a primary line demarked by values in the %total and %self columns. The primary line represents the method being profiled. Lines above it are the methods that called this method (parents) while the lines below it are the methods it called (children).
All values are in seconds. For the primary line, the columns represent:
%total - The percentage of time spent in this method and its children %self - The percentage of time spent in this method total - The time spent in this method and its children. self - The time spent in this method. wait - The time spent waiting for other threads in this method. child - The time spent in this method's children. calls - The number of times this method was called. name - The name of the method.
The interpretation of method names is:
MyObject#test - An instance method "test" of the class "MyObject" <Object:MyObject>#test - The <> characters indicate a singleton method on a singleton class.
For example, we see that 97.74% of the time was spent in Object#is_prime and its children. Of that time, almost everything was contributed by Integer#upto. Overall, Integer#upto was called 1001 times and 1000 of those calls were made by Object#is_prime.
Parents¶ ↑
In each entry, the lines above the primary line are the methods that called the current method. If the current method is a root method then no parents are shown.
For parent lines, the columns represent:
total - The time spent in the current method and its children on behalf of the parent method. self - The time spent in this method on behalf of the parent method. child - The time spent in this method's children on behalf of the parent. wait - The time spent waiting for other threads in this method's children on behalf of the parent. calls - The number of times the parent method called the current method vs. the total number of calls of the current method.
Looking at the main entry for Integer#upto, we see that it was called 1000 times from Object#is_prime and 1 time from find_largest.
Children¶ ↑
In each entry, the lines below the primary line are the methods that the current method called. If the current method is a leaf method then no children are shown.
For children lines, the columns represent:
total - The time spent in the child, and its descendants, on behalf of the current method self - The time spent in the child on behalf of the current method. wait - The time spent waiting for other threads in the child's and its descendants on behalf of the current method. child - The time spent in the child's descendants on behalf of the current method. calls - The number of times the child method was called by the current method vs. the total number of calls of the child method.
If we look at the main entry for Objext#run_primes, we see that it called three other methods - Object#find_primes, Object#make_random_array and Object#find_largest.