Если кто-то почему-то не знает, для Руби есть профилировщик RubyProf. Он умеет выводить результаты своей работы в нескольких форматах, в частности, plain-text-овых FlatPrinter и GraphPrinter. GraphPrinter значительно веселее и полезнее.
Рассмотрим такой кусок вывода GraphPrinter:
%total %self total self wait child calls Name
--------------------------------------------------------------------------------
0.00 0.00 0.00 0.00 1/5 Rake::Application#raw_load_rakefile
0.00 0.00 0.00 0.00 1/5 Array#collect
4.60 0.00 0.00 4.60 1/5 Rake::Application#standard_exception_handling
0.00 0.00 0.00 0.00 1/5 Enumerable#inject
0.00 0.00 0.00 0.00 1/5 Module#local_constants
46029.83% 2.15% 4.60 0.00 0.00 4.60 5 Array#each
0.00 0.00 0.00 0.00 8/1827 Module#constants
0.00 0.00 0.00 0.00 1/4 #[]
0.00 0.00 0.00 0.00 9/2042 Module#==
0.00 0.00 0.00 0.00 1/6192 Module#const_get
0.00 0.00 0.00 0.00 1/253 Array#concat
0.00 0.00 0.00 0.00 9/12 Array#each-1
4.60 0.00 0.00 4.60 1/1 Rake::Application#invoke_task
0.00 0.00 0.00 0.00 1/9783 String#==
0.00 0.00 0.00 0.00 1/102 ActiveSupport::Dependencies#uninherited_const_defined?
--------------------------------------------------------------------------------
Что это всё означает?
Прежде всего, это блок про метод Array#each. Он был вызван 5 раз. Колонки с числами как бы говорят нам: В Array (включая то, что из него вызывалось) интерпретатор провёл 46029.83% времени, а в непосредственно его коде — 2.15% времени (по 4.60 и 0.00 сек. соответственно). В Array#each интерпретатор 0.00 секунд провёл в состоянии ожидания ввода-вывода; а все 4.60 времени прошли в том, что этот Array#each вызывал.
Теперь — самое интересное: строки над Array#each — это то, что его вызывало. Его вызывали по одному разу из пяти методов. А строки под Array#each — это то, что вызывалось из него. В частности, именно из него были сделаны 8 из 1827 вызовов Module#constants, и так далее.
А Array#each-1 — это тот же Array#each на следующем уровне вложенности. То есть, прямо из Array#each был дёрнут Array#each ещё 9 раз.
