silhouette

Here is an example of a generated profile report:

$ silhouette silhouette.out Number of threads: 1 Profiling based on method call. Cost of profiler: 0.45 seconds.

Flat profile (0.76 total seconds): % total self self total time seconds seconds calls ms/call ms/call name 19.74 0.15 0.15 1228 0.12 0.28 Silhouette::DefaultProfiler#process_return 10.53 0.23 0.08 1 80.00 640.00 Silhouette::BinaryEmitter#parse 6.58 0.28 0.05 6151 0.01 0.01 Array#[] 5.26 0.32 0.04 1229 0.03 0.07 Silhouette::DefaultProfiler#process_call 5.26 0.36 0.04 4966 0.01 0.01 IO#read 5.26 0.40 0.04 3842 0.01 0.01 Object#=== 3.95 0.43 0.03 4474 0.01 0.01 Hash#[] ...

Call Tree Profile: index calls ms/ self total call sec sec 1228/1 - - - Silhouette::BinaryEmitter#parse [243] [256] 1228 0.12 0.15 0.34 Silhouette::DefaultProfiler#process_return 2 0.01 0.00 0.02 Array#[] [4] 2 0.01 0.00 0.02 Hash#[] [162] 1 0.05 0.00 0.06 Silhouette::ProfileNode#add_cost [265] 1 0.02 0.00 0.02 Silhouette::ProfileNode#inc_call! [263] 2 0.01 0.00 0.02 Array#last [260] 1 0.01 0.00 0.02 Hash#[]= [37]

...

parent called/called child - - - Parent method name [parent_id] ... [method_id] calls 0.03 0.04 0.08 Method name called child 0.02 0.00 0.02 Child method name [child_id] ...

Explanation of Call Tree Profile:

For each method profiled, there is an entry that describes the method, it's parents and it's direct children. Above we've shown a real world output from the profiler and and explanation of each field.

First are listed all the parent methods that called the current method. The only stat available for the parent is the number of times the parent was called and the number of times the parent called the current method.

Next listed is the current method.

Finally, all the methods directly called by the current method are listed. The calls column is only the number of times the current method called the child, not the total number of calls the child received.