Понимание вывода ruby-prof
Я запустил ruby-profiler в одной из моих программ. Я пытаюсь выяснить, что означают каждое поле. Я предполагаю, что все время процессора (а не время настенных часов), это фантастика. Я хочу понять, что означает "---". Есть ли какая-то информация о стеке там? Что означают звонки а / б?
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!
--------------------------------------------------------------------------------
1 ответ
Решение
Каждый раздел вывода ruby-prof разбит на проверку конкретной функции. например, посмотрите на первый раздел вашего вывода. Метод read_frames в FrameParser находится в центре внимания и в основном говорит следующее:
- 100% времени выполнения, которое было профилировано, было потрачено внутри FrameParser#read_frames
- FrameParser#read_frames был вызван 6 раз.
- 5 из 6 вызовов read_frames поступили из FrameParser#receive_data, и это составило 100% времени выполнения (это строка над строкой read_frames).
- Строки ниже метода read_frames (но внутри этого первого раздела) - все методы, которые вызывает FrameParser#read_frames (вы должны знать об этом, поскольку это похоже на ваш код), за сколько из этих методов общее количество вызовов read_frames отвечает за (столбец вызовов a/b) и сколько времени заняли эти вызовы. Им приказано, кто из них занял наибольшее время исполнения. В вашем случае это метод receive_frame в классе ChatServer.
- Затем вы можете посмотреть вниз на раздел, посвященный receive_frames (2 вниз и центрированы линией "100%" на receive_frame), и посмотреть, как снижается его производительность. каждый раздел настраивается одинаково, и обычно последующий вызов функции, который занимал больше всего времени, является фокусом следующего раздела вниз. ruby-prof продолжит делать это через полный стек вызовов. Вы можете идти так глубоко, как захотите, пока не найдете узкое место, которое хотите устранить.