Understanding ruby-prof exit

Question

I ran ruby-profiler in one of my programs. I am trying to understand what all fields mean. I assume that the entire processor time (and not the wall clock time), which is fantastic. I want to understand what "---" means. Is there any kind of stack info. What do a / b calls mean?

Thread ID: 81980260 Total Time: 0.28 %total %self total self wait child calls Name -------------------------------------------------------------------------------- 0.28 0.00 0.00 0.28 5/6 FrameParser#receive_data 100.00% 0.00% 0.28 0.00 0.00 0.28 6 FrameParser#read_frames 0.28 0.00 0.00 0.28 4/4 ChatServerClient#receive_frame 0.00 0.00 0.00 0.00 5/47 Fixnum#+ 0.00 0.00 0.00 0.00 1/2 DebugServer#receive_frame 0.00 0.00 0.00 0.00 10/29 String#[] 0.00 0.00 0.00 0.00 10/21 <Class::Range>#allocate 0.00 0.00 0.00 0.00 10/71 String#index -------------------------------------------------------------------------------- 100.00% 0.00% 0.28 0.00 0.00 0.28 5 FrameParser#receive_data 0.28 0.00 0.00 0.28 5/6 FrameParser#read_frames 0.00 0.00 0.00 0.00 5/16 ActiveSupport::CoreExtensions::String::OutputSafety#add_with_safety -------------------------------------------------------------------------------- 0.28 0.00 0.00 0.28 4/4 FrameParser#read_frames 100.00% 0.00% 0.28 0.00 0.00 0.28 4 ChatServerClient#receive_frame 0.28 0.00 0.00 0.28 4/6 <Class::Lal>#safe_call -------------------------------------------------------------------------------- 0.00 0.00 0.00 0.00 1/6 <Class::Lal>#safe_call 0.00 0.00 0.00 0.00 1/6 DebugServer#receive_frame 0.28 0.00 0.00 0.28 4/6 ChatServerClient#receive_frame 100.00% 0.00% 0.28 0.00 0.00 0.28 6 <Class::Lal>#safe_call 0.21 0.00 0.00 0.21 2/4 ChatUserFunction#register 0.06 0.00 0.00 0.06 2/2 ChatUserFunction#packet 0.01 0.00 0.00 0.01 4/130 Class#new 0.00 0.00 0.00 0.00 1/1 DebugServer#profile_stop 0.00 0.00 0.00 0.00 1/33 String#== 0.00 0.00 0.00 0.00 1/6 <Class::Lal>#safe_call 0.00 0.00 0.00 0.00 5/5 JSON#parse 0.00 0.00 0.00 0.00 5/8 <Class::Log>#log 0.00 0.00 0.00 0.00 5/5 String#strip! -------------------------------------------------------------------------------- 

Answer 1

Each ruby-prof output section is broken down into a specific function. for example, look at the first section of your output. The read_frames method in FrameParser is the focus, and basically it says the following:

• 100% of the runtime that was profiled was spent inside FrameParser # read_frames
• FrameParser # read_frames has been called 6 times.
• 5 out of 6 read_frames calls come from FrameParser # receive_data, and this is 100% of the execution time (this is the line above the read_frames line).
• The lines below the read_frames method (but inside this first section) are all the methods that call FrameParser # read_frames (you should be aware of this, since this looks like your code), how many of these methods call the total number of read_frames calls are answered (column a / b calls) and how long it took for these calls. They are ordered which of them take the longest execution time. In your case, this is the receive_frame method in the ChatServer class.
• Then you can look in the section on receive_frames parameters (2 down and center along the “100%” line on the receive_frame method) and see how its performance is broken. each section is configured in the same way, and usually the subsequent function call, which takes the most time, is the focus of the next section. ruby-prof will continue to do this through a full call stack. You can go as deep as you like until you find the bottleneck you want to solve.