Понимание выхода ruby-prof
Я запускал ruby-profiler в одной из моих программ. Я пытаюсь понять, что означают все поля. Я предполагаю, что все время процессора (а не время настенных часов), что является фантастическим. Я хочу понять, что означает "---". Есть ли какая-то информация о стеке. Что означают вызовы a/b?
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 calls) и сколько времени потребовалось для этих вызовов. Они заказываются, какие из них занимают наибольшее время исполнения. В вашем случае это метод receive_frame в классе ChatServer.
- Затем вы можете посмотреть в разделе, посвященном параметрам receive_frames (2 вниз и центрироваться по линии "100%" на методе receive_frame) и посмотреть, как его производительность разбита. каждый раздел настраивается таким же образом, и обычно последующий вызов функции, который занимает больше всего времени, находится в центре внимания следующего раздела. ruby-prof продолжит делать это через полный стек вызовов. Вы можете идти так глубоко, как хотите, пока не найдете узкое место, которое хотите решить.
