Введение
На тему профилирования CPU написано много статей. Тем не менее, эта тема обычно рассматривается в контексте конкретных задач, проблемы которых затеняют некоторые тонкости. Это может вызвать трудности или привести к ошибочному выводу при анализе собственного решения. В этой статье нет примера успешной оптимизации какого-нибудь невероятного кода, но на простейших примерах объясняется, какую информацию может дать профиль CPU и как ей воспользоваться. А также подсвечиваются некоторые тонкости.
Получение профиля
Построить профиль CPU можно разными способами:
Пакет runtime/pprof
Пакет net/http/pprof
Benchmark
Пример использования runtime/pprof:
package main
import (
"fmt"
"os"
"runtime/pprof"
)
func main() {
f, _ := os.Create("cpu.out")
defer f.Close()
pprof.StartCPUProfile(f)
defer pprof.StopCPUProfile()
someFunc()
}
func someFunc() {
var i int
i++
fmt.Println(i)
}В предложенном примере профиль CPU строится самой программой, поэтому в функции main создаётся файл cpu.out:
f, _ := os.Create("cpu.out")
defer f.Close()И запускается профилирование:
pprof.StartCPUProfile(f)
defer pprof.StopCPUProfile()Результат будет записываться в ранее созданный файл cpu.out. Теперь всё готово для запуска "бизнес-логики":
someFunc()Предлагаемая функция someFunc ничего особенного не делает, она достаточно примитивная - ничего не принимает, ничего не получает, а лишь выводит в stdout значение некоторой локальной переменной:
func someFunc() {
var i int
i++
fmt.Println(i)
}После запуска программы:
go run main.goБудет создан файл с профилем - cpu.out. Как видно, способ достаточно милый, но вряд ли применим к реальной системе, т.к. требует изменение кода.
Для профилирования http-сервиса используется пакет net/http/pprof:
package main
import (
"fmt"
"net/http"
_ "net/http/pprof"
)
func main() {
http.HandleFunc("/number", numberHandler)
fmt.Println("Start service!")
http.ListenAndServe(":8080", nil)
}
func numberHandler(res http.ResponseWriter, req *http.Request) {
someFunc()
res.WriteHeader(http.StatusOK)
}
func someFunc() {
var i int
i++
fmt.Println(i)
}Следует обратить внимание, что для возможности снятия профиля CPU необходимо добавить неиспользуемый импорт:
_ "net/http/pprof"Предлагаемый код http-сервиса тоже не особо сложный - всего один метод /number. При запуске сервиса:
go run main.goи отправке http-запроса:
curl -I http://127.0.0.1:8080/numberБудет запущена логика уже рассмотренной функции someFunc, а также вернётся ответ с кодом 200:
HTTP/1.1 200 OK
Date: Mon, 06 Jan 2025 19:41:23 GMTДля снятия профиля CPU и скачивания файла с результатом необходимо в браузере открыть страницу http://localhost:8080/debug/pprof/profile.
Разработка не ограничивается одним лишь написанием API, на практике может понадобится снятие профиля CPU для конкретной функции. В этом случае нужно написать тест производительности - benchmark. Для простоты рассмотрим только функцию someFunc:
package main
import (
"fmt"
)
func someFunc() {
var i int
i++
fmt.Println(i)
}Вот для неё benchmark:
package main
import "testing"
func BenchmarkSomeFunc(b *testing.B) {
for i := 0; i < b.N; i++ {
someFunc()
}
}После запуска теста:
go clean --testcache && go test -bench=BenchmarkSomeFunc -cpuprofile=cpu.outТакже создастся файл с профилем cpu.out.
Магические числа
Что ж! Пора посмотреть на профиль. На локальной машине у меня перезаписывался один и тот же файл cpu.out. Таким образом, выполнив команду:
go tool pprof -text cpu.outоткроется профиль, полученный в рамках теста производительности:
File: app.test
Type: cpu
Time: Jan 9, 2025 at 7:38am (UTC)
Duration: 2.03s, Total samples = 1.93s (95.23%)
Showing nodes accounting for 1.93s, 100% of 1.93s total
flat flat% sum% cum cum%
1.61s 83.42% 83.42% 1.61s 83.42% internal/runtime/syscall.Syscall6
0.08s 4.15% 87.56% 0.09s 4.66% runtime.casgstatus
0.03s 1.55% 89.12% 0.07s 3.63% runtime.reentersyscall
0.02s 1.04% 90.16% 0.02s 1.04% fmt.(*buffer).write (inline)
0.02s 1.04% 91.19% 0.02s 1.04% internal/poll.(*fdMutex).rwunlock
0.02s 1.04% 92.23% 0.02s 1.04% runtime.exitsyscallfast
0.02s 1.04% 93.26% 0.02s 1.04% runtime.getcallerfp
0.02s 1.04% 94.30% 0.02s 1.04% sync.(*Pool).pin
0.01s 0.52% 94.82% 0.03s 1.55% fmt.(*fmt).fmtInteger
0.01s 0.52% 95.34% 0.04s 2.07% fmt.(*pp).doPrintln
0.01s 0.52% 95.85% 0.03s 1.55% fmt.(*pp).free
0.01s 0.52% 96.37% 0.01s 0.52% internal/runtime/atomic.(*Uint32).CompareAndSwap (inline)
0.01s 0.52% 96.89% 1.85s 95.85% os.(*File).write (inline)
0.01s 0.52% 97.41% 0.09s 4.66% runtime.exitsyscall
0.01s 0.52% 97.93% 0.01s 0.52% runtime.save
0.01s 0.52% 98.45% 0.02s 1.04% sync.(*Pool).Put
0.01s 0.52% 98.96% 1.62s 83.94% syscall.RawSyscall6
0.01s 0.52% 99.48% 1.82s 94.30% syscall.Write (inline)
0.01s 0.52% 100% 1.81s 93.78% syscall.write
0 0% 100% 1.93s 100% app.BenchmarkSomeFunc
0 0% 100% 1.93s 100% app.someFunc
0 0% 100% 0.02s 1.04% fmt.(*fmt).pad
0 0% 100% 0.03s 1.55% fmt.(*pp).fmtInteger
0 0% 100% 0.03s 1.55% fmt.(*pp).printArg
0 0% 100% 1.93s 100% fmt.Fprintln
0 0% 100% 1.93s 100% fmt.Println (inline)
0 0% 100% 0.01s 0.52% fmt.newPrinter
0 0% 100% 1.84s 95.34% internal/poll.(*FD).Write
0 0% 100% 0.02s 1.04% internal/poll.(*FD).writeUnlock
0 0% 100% 1.82s 94.30% internal/poll.ignoringEINTRIO (inline)
0 0% 100% 1.85s 95.85% os.(*File).Write
0 0% 100% 0.09s 4.66% runtime.entersyscall
0 0% 100% 0.01s 0.52% sync.(*Pool).Get
0 0% 100% 1.80s 93.26% syscall.Syscall
0 0% 100% 1.93s 100% testing.(*B).launch
0 0% 100% 1.93s 100% testing.(*B).runNВ литературе довольно часто на этом заканчиваются все объяснения профиля CPU :) Профиль получен - что ещё нужно? Иногда встречал более глубокий анализ: "по профилю видно, что функция internal/runtime/syscall.Syscall6 выполнилась за 1.61s". С чем, конечно, трудно поспорить. Такое изложение материала обычно не вызывает вопросов, более того, создаётся иллюзия понимания сути анализа. Но на деле, когда реально ищешь источник проблемы, становится ясно, что упущены некоторые мелочи, недопонимание которых превращает профилирование в бессмысленное занятие. С syscall.Syscall6 всё понятно, а что можно сказать насчёт syscall.write? Сколько времени выполнялась эта функция - 0.01 секунд или 1.81? А что означают проценты? И почему для syscall.write они разные: 0.52%, 100% и 93.78%? На этом этапе анализа можно заметить названия этих величин: flat, sum, cum. А что они значат? Для простоты восприятия вспомним, что из себя представляет программа - последовательность вызовов различных функций или методов. Вызываемая функция может производить некоторые вычисления, а дальше вызывать другие функции и передавать в них результат, что видно в someFunc:
func someFunc() {
var i int
i++
fmt.Println(i)
}Вычисления очень примитивные, но выбран именно такой пример, чтобы сложность кода не затеняла тонкости профилирования. В теле функции someFunc объявляется целочисленная переменная, значение которой увеличивается на единицу:
var i int
i++Время на выполнение этой непосредственной логики функции someFunc обозначают, как flat. Понятно, что этот код будет очень быстро выполняться, поэтому на профиле значение flat для рассматриваемой функции равно 0.
Далее someFunc вызывает другую функцию - Println, передаёт в неё результат и ожидает её завершение. Функция Println тоже требует некоторого времени на выполнение. Поэтому фактическое время на работу функции someFunc складывается из времени выполнения её собственной логики и времени, которе требуется на ожидание завершения Println. Это суммарное время обозначают, как cum.
Наверное, может удивить, что такая простая функция создаёт такой непростой профиль. Эта сложность объясняется "начинкой" функции fmt.Println, что приводит к суммарному времени выполнения рассматриваемой функции в 1.93 секунды (cum = 1.93s). Значение cum% показывает сколько процентов составляет суммарное время, затрачиваемое на конкретную функцию, от общего времени выполнения.
Значение flat% информирует сколько процентов составляет время, необходимое для завершения непосредственной логики рассматриваемой функции, от общего времени выполнения. Для функции someFunc интервал в 0 секунд (flat=0s) составляет 0% от общего времени (1.93s).
Остаётся разобраться со значением sum%. В рассматриваемом профиле результат отсортирован по значениям flat в порядке убывания. Поэтому все дальнейшие рассуждения будут справедливы именно для такой сортировки. Значение sum% для конкретной функции представляет собой сумму либо flat% этой функции с flat% более медленных функций, либо flat% этой функции с sum% следующей более медленной функцией.
flat flat% sum% cum cum%
1.61s 83.42% 83.42% 1.61s 83.42% internal/runtime/syscall.Syscall6
0.08s 4.15% 87.56% 0.09s 4.66% runtime.casgstatus
0.03s 1.55% 89.12% 0.07s 3.63% runtime.reentersyscallТаким образом, для самой медленной функции internal/runtime/syscall.Syscall6 sum% совпадает с flat%. А вот для других, например для runtime.casgstatus, это значение равно сумме flat% internal/runtime/syscall.Syscall6 и flat% рассматриваемой функции, т.е. 83.42% + 4.15% ~ 87.56%. Для runtime.reentersyscall sum% будет определяться суммой либо flat% всех более медленных функций и flat% runtime.reentersyscall, либо суммой sum% предыдущей функции (runtime.casgstatus) и flat% runtime.reentersyscall, т.е. 83.42% + 4.15% + 1.55% или 87.56% + 1.55% ~ 89.12%.
Смысл чисел
Понимание величин профиля - первый шаг к пониманию самого профиля. Теперь нужно выяснить, какую информацию несут эти значения. Для удобства ещё раз продублирую полученный профиль CPU:
File: app.test
Type: cpu
Time: Jan 9, 2025 at 7:38am (UTC)
Duration: 2.03s, Total samples = 1.93s (95.23%)
Showing nodes accounting for 1.93s, 100% of 1.93s total
flat flat% sum% cum cum%
1.61s 83.42% 83.42% 1.61s 83.42% internal/runtime/syscall.Syscall6
0.08s 4.15% 87.56% 0.09s 4.66% runtime.casgstatus
0.03s 1.55% 89.12% 0.07s 3.63% runtime.reentersyscall
0.02s 1.04% 90.16% 0.02s 1.04% fmt.(*buffer).write (inline)
0.02s 1.04% 91.19% 0.02s 1.04% internal/poll.(*fdMutex).rwunlock
0.02s 1.04% 92.23% 0.02s 1.04% runtime.exitsyscallfast
0.02s 1.04% 93.26% 0.02s 1.04% runtime.getcallerfp
0.02s 1.04% 94.30% 0.02s 1.04% sync.(*Pool).pin
0.01s 0.52% 94.82% 0.03s 1.55% fmt.(*fmt).fmtInteger
0.01s 0.52% 95.34% 0.04s 2.07% fmt.(*pp).doPrintln
0.01s 0.52% 95.85% 0.03s 1.55% fmt.(*pp).free
0.01s 0.52% 96.37% 0.01s 0.52% internal/runtime/atomic.(*Uint32).CompareAndSwap (inline)
0.01s 0.52% 96.89% 1.85s 95.85% os.(*File).write (inline)
0.01s 0.52% 97.41% 0.09s 4.66% runtime.exitsyscall
0.01s 0.52% 97.93% 0.01s 0.52% runtime.save
0.01s 0.52% 98.45% 0.02s 1.04% sync.(*Pool).Put
0.01s 0.52% 98.96% 1.62s 83.94% syscall.RawSyscall6
0.01s 0.52% 99.48% 1.82s 94.30% syscall.Write (inline)
0.01s 0.52% 100% 1.81s 93.78% syscall.write
0 0% 100% 1.93s 100% app.BenchmarkSomeFunc
0 0% 100% 1.93s 100% app.someFunc
0 0% 100% 0.02s 1.04% fmt.(*fmt).pad
0 0% 100% 0.03s 1.55% fmt.(*pp).fmtInteger
0 0% 100% 0.03s 1.55% fmt.(*pp).printArg
0 0% 100% 1.93s 100% fmt.Fprintln
0 0% 100% 1.93s 100% fmt.Println (inline)
0 0% 100% 0.01s 0.52% fmt.newPrinter
0 0% 100% 1.84s 95.34% internal/poll.(*FD).Write
0 0% 100% 0.02s 1.04% internal/poll.(*FD).writeUnlock
0 0% 100% 1.82s 94.30% internal/poll.ignoringEINTRIO (inline)
0 0% 100% 1.85s 95.85% os.(*File).Write
0 0% 100% 0.09s 4.66% runtime.entersyscall
0 0% 100% 0.01s 0.52% sync.(*Pool).Get
0 0% 100% 1.80s 93.26% syscall.Syscall
0 0% 100% 1.93s 100% testing.(*B).launch
0 0% 100% 1.93s 100% testing.(*B).runNНапомню, что значения отсортированы по flat, что позволяет быстро выявить самую "тяжёлую" функцию - internal/runtime/syscall.Syscall6. Её собственное время выполнения flat = 1.61s, что составляет 83.42% от общего времени выполнения всей логики (1.93s). Значение flat совпадает с cum (1.61s), это говорит о том, что время, которое требуется на выполнение internal/runtime/syscall.Syscall6, в основном уходит на её собственную логику - если в Syscall6 присутствуют вызовы других функций, то на них практически ничего не тратится.
По значениям sum% можно оперативно выяснить, что на функции:
flat flat% sum% cum cum%
1.61s 83.42% 83.42% 1.61s 83.42% internal/runtime/syscall.Syscall6
0.08s 4.15% 87.56% 0.09s 4.66% runtime.casgstatus
0.03s 1.55% 89.12% 0.07s 3.63% runtime.reentersyscall
0.02s 1.04% 90.16% 0.02s 1.04% fmt.(*buffer).write (inline)
0.02s 1.04% 91.19% 0.02s 1.04% internal/poll.(*fdMutex).rwunlock
0.02s 1.04% 92.23% 0.02s 1.04% runtime.exitsyscallfast
0.02s 1.04% 93.26% 0.02s 1.04% runtime.getcallerfp
0.02s 1.04% 94.30% 0.02s 1.04% sync.(*Pool).pin
0.01s 0.52% 94.82% 0.03s 1.55% fmt.(*fmt).fmtInteger
0.01s 0.52% 95.34% 0.04s 2.07% fmt.(*pp).doPrintln
0.01s 0.52% 95.85% 0.03s 1.55% fmt.(*pp).free
0.01s 0.52% 96.37% 0.01s 0.52% internal/runtime/atomic.(*Uint32).CompareAndSwap (inline)
0.01s 0.52% 96.89% 1.85s 95.85% os.(*File).write (inline)
0.01s 0.52% 97.41% 0.09s 4.66% runtime.exitsyscall
0.01s 0.52% 97.93% 0.01s 0.52% runtime.save
0.01s 0.52% 98.45% 0.02s 1.04% sync.(*Pool).Put
0.01s 0.52% 98.96% 1.62s 83.94% syscall.RawSyscall6
0.01s 0.52% 99.48% 1.82s 94.30% syscall.Write (inline)
0.01s 0.52% 100% 1.81s 93.78% syscall.writeуходит всё время, которое требуется для завершения someFunc. А вот в следующем списке:
0 0% 100% 1.93s 100% app.BenchmarkSomeFunc
0 0% 100% 1.93s 100% app.someFunc
0 0% 100% 0.02s 1.04% fmt.(*fmt).pad
0 0% 100% 0.03s 1.55% fmt.(*pp).fmtInteger
0 0% 100% 0.03s 1.55% fmt.(*pp).printArg
0 0% 100% 1.93s 100% fmt.Fprintln
0 0% 100% 1.93s 100% fmt.Println (inline)
0 0% 100% 0.01s 0.52% fmt.newPrinter
0 0% 100% 1.84s 95.34% internal/poll.(*FD).Write
0 0% 100% 0.02s 1.04% internal/poll.(*FD).writeUnlock
0 0% 100% 1.82s 94.30% internal/poll.ignoringEINTRIO (inline)
0 0% 100% 1.85s 95.85% os.(*File).Write
0 0% 100% 0.09s 4.66% runtime.entersyscall
0 0% 100% 0.01s 0.52% sync.(*Pool).Get
0 0% 100% 1.80s 93.26% syscall.Syscall
0 0% 100% 1.93s 100% testing.(*B).launch
0 0% 100% 1.93s 100% testing.(*B).runNфункции в основном ожидают выполнение других функций, т.к. для них flat = 0, а cum отлично от 0.
Граф
В текстовом представлении профиля CPU можно увидеть много полезной информации, но, к сожалению, трудно понять последовательность вызовов функций. А ведь эта информация может ощутимо облегчить восприятие. Поэтому на практике также используется граф. Его можно получить, выполнив следующую команду:
go tool pprof -http=localhost:1234 cpu.outПосле чего в браузере автоматически откроется страница http://localhost:1234/ui/ с графом:
Граф даёт более наглядное представление о ходе выполнения логики. На нём также присутствуют значения flat, flat%, cum, cum%.
Например, по рис. 3 видно, что тестовая среда запускает BenchmarkSomeFunc, который тестирует someFunc. Запись "0 of 1.93s (100%)" блока app.someFunc нужно понимать так: функция someFunc выполнялась 1.93 секунды (cum = 1.93s), что составляет 100% от общего времени выполнения логики (cum% = 100%). Из этих 1.93 секунды 0 секунд потратилось на выполнение непосредственной логики (flat = 0s) рассматриваемой функции, а 1.93 секунды ушло на ожидание выполнения fmt.Println.
Более показательным примером является работа функции fmt.Fprintln: она также затратила минимум времени на выполнение собственной логики (flat = 0s), в основном ждала целых 1.93 секунды выполнение аж 4-х функций: fmt.doPrintln, fmt.free, fmt.newPrinter, os.Write. Рассмотрим только fmt.doPrintln, т.к. другие блоки описываются по аналогии. Итак, fmt.doPrintln выполнялась 0.04 секунды (cum = 0.04s), что составляет 2.07% от общего времени выполнения (cum% = 2.07%). Из этих 0.04 секунды 0.01 потратилось на выполнение непосредственной логики fmt.doPrintln (flat = 0.01s), что составляет 0.52% от общего времени выполнения (flat% = 0.52%), а 0.03 секунды рассматриваемая функция ожидала выполнение fmt.printArg.
Следует обратить внимание, что самый затратный путь выделен красным цветом. Чем дольше выполнялась функция, тем больше по размеру и сильнее выделен её блок.
Тонкости
Наверное, полученную информацию хочется поскорее применить на практике - начать что-то анализировать, думать об оптимизации кода, ну, или просто кому-то помочь. Например, обратился коллега с вопросом про профилирование CPU. А вы ему: а что там? Там всё просто! Накидаете код:
package main
import (
"fmt"
"os"
"runtime/pprof"
)
func main() {
f, _ := os.Create("cpu.out")
defer f.Close()
pprof.StartCPUProfile(f)
defer pprof.StopCPUProfile()
someFunc()
}
func someFunc() {
var i int
i++
fmt.Println(i)
}Вряд ли будет написан тест производительности. Сомнительно, что будет подниматься http-сервер. Скорее всего, дело закончится написанием пятиминутного кода с построением профиля средствами самой программы, т.к. захочется поскорее поделиться своей экспертизой в этом вопросе. Затем с важным видом будет запущена программа:
go run main.goС чувством выполненного долга будет открыт cpu.out:
File: main
Type: cpu
Time: Jan 15, 2025 at 1:51pm (UTC)
Duration: 205.40ms, Total samples = 0
Showing nodes accounting for 0, 0% of 0 total
flat flat% sum% cum cum%А далее вспыхнет лёгкий румянец на щёчках, стыдливо забегают глазки... Неловкий момент! - профиля нет. А почему? Возможно, вспомнится, что при построении профиля через тест производительности, такой проблемы не наблюдалось. А также тот факт, что benchmark запускает многократно тестируемую функцию. После чего может сложиться впечатление, что профилировщик просто не успевает ничего построить из-за высокой скорости выполнения программы. На этом моменте можно успокоиться, а можно проверить гипотезу, добавив задержку по времени:
package main
import (
"fmt"
"os"
"runtime/pprof"
"time"
)
func main() {
f, _ := os.Create("cpu.out")
defer f.Close()
pprof.StartCPUProfile(f)
defer pprof.StopCPUProfile()
someFunc()
}
func someFunc() {
var i int
i++
fmt.Println(i)
time.Sleep(time.Second)
}Одной секунды должно быть достаточно, но эта правка не изменит картину:
File: main
Type: cpu
Time: Jan 15, 2025 at 2:01pm (UTC)
Duration: 1s, Total samples = 0
Showing nodes accounting for 0, 0% of 0 total
flat flat% sum% cum cum%Пожалуй, не буду томить читателей, а сразу напишу, что профиль построится, если горутина будет занимать процессорное время, а не просто "парковаться" в глобальную очередь:
package main
import (
"fmt"
"os"
"runtime/pprof"
"time"
)
func main() {
f, _ := os.Create("cpu.out")
defer f.Close()
pprof.StartCPUProfile(f)
defer pprof.StopCPUProfile()
someFunc()
}
func someFunc() {
var i int
t := time.After(10 * time.Millisecond)
OUT:
for {
select {
case <-t:
break OUT
default:
i++
fmt.Println(i)
}
}
}Результат профилирования:
File: main
Type: cpu
Time: Jan 15, 2025 at 2:15pm (UTC)
Duration: 208.03ms, Total samples = 10ms ( 4.81%)
Showing nodes accounting for 10ms, 100% of 10ms total
flat flat% sum% cum cum%
10ms 100% 100% 10ms 100% internal/runtime/syscall.Syscall6
0 0% 100% 10ms 100% fmt.Fprintln
0 0% 100% 10ms 100% fmt.Println (inline)
0 0% 100% 10ms 100% internal/poll.(*FD).Write
0 0% 100% 10ms 100% internal/poll.ignoringEINTRIO (inline)
0 0% 100% 10ms 100% main.main
0 0% 100% 10ms 100% main.someFunc
0 0% 100% 10ms 100% os.(*File).Write
0 0% 100% 10ms 100% os.(*File).write (inline)
0 0% 100% 10ms 100% runtime.main
0 0% 100% 10ms 100% syscall.RawSyscall6
0 0% 100% 10ms 100% syscall.Syscall
0 0% 100% 10ms 100% syscall.Write (inline)
0 0% 100% 10ms 100% syscall.writeТакже полезно вспомнить особенности работы профилировщика CPU. А именно, то, что он работает не всё время. Его работа основана на получении сигналов операционной системы. Т.е. запущенная программа каждые 10 миллисекунд получает сигнал SIGPROF. После чего она приостанавливается и активирует профилировщик, который начинает собирать статистику выполнения. После сбора информации управление возвращается программе до следующего получения SIGPROF. Это описание работы профилировщика достаточно поверхностное, оно даёт соответствующее представление о его работе. Т.к. можно уменьшить выполнение функции до трёх миллисекунд:
t := time.After(3 * time.Millisecond)И получить следующий профиль:
File: main
Type: cpu
Time: Jan 15, 2025 at 2:45pm (UTC)
Duration: 205.67ms, Total samples = 10ms ( 4.86%)
Showing nodes accounting for 10ms, 100% of 10ms total
flat flat% sum% cum cum%
10ms 100% 100% 10ms 100% internal/runtime/syscall.Syscall6
0 0% 100% 10ms 100% fmt.Fprintln
0 0% 100% 10ms 100% fmt.Println (inline)
0 0% 100% 10ms 100% internal/poll.(*FD).Write
0 0% 100% 10ms 100% internal/poll.ignoringEINTRIO (inline)
0 0% 100% 10ms 100% main.main
0 0% 100% 10ms 100% main.someFunc
0 0% 100% 10ms 100% os.(*File).Write
0 0% 100% 10ms 100% os.(*File).write (inline)
0 0% 100% 10ms 100% runtime.main
0 0% 100% 10ms 100% syscall.RawSyscall6
0 0% 100% 10ms 100% syscall.Syscall
0 0% 100% 10ms 100% syscall.Write (inline)
0 0% 100% 10ms 100% syscall.writeКонечно, ограничение в 3 миллисекунды в коде и значение в 10 миллисекунд в профиле для функции someFunc можно объяснить тем, что по умолчанию при профилировании программа прерывается каждые 10 миллисекунд. Наверное, профилировщик округляет фактическое выполнение функции. Эту мысль можно подтвердить, если запустить несколько раз программу с разными временными задержками - в профиле будут наблюдаться только значения кратные 10: 10, 20, 30, 40 миллисекунд. Также можно предположить, что при задержке в 3 миллисекунды:
t := time.After(3 * time.Millisecond)по факту someFunc будет выполняться чуть дольше, т.к. time.After, скорее всего, чуть сложнее, чем может показаться на первый взгляд, а профилировщик просто считает количество прерываний программы. Такое предположение хорошо объясняет разные результаты при многократном запуске программы. Т.е. при задержке в 13 миллисекунд:
t := time.After(13 * time.Millisecond)просто запуская программу несколько раз подряд, сначала можно получить cum = 10ms, а затем cum = 20ms для одной и той же функции someFunc. Тем не менее, при задержке в 3 миллисекунды профиль может построиться, а может и не построиться. Поэтому объяснение с округлением времени выполнения функции как-то не внушает доверия. Можно, конечно, бесконечно долго делать предположения и находить контрпримеры, но самый верный подход в данной ситуации - изучить код пакета runtime/pprof и дебажить. С одной стороны это правильно, с другой - а нужно ли это? Изменим немного код:
package main
import (
"fmt"
"os"
"runtime/pprof"
"time"
)
func main() {
f, _ := os.Create("cpu.out")
defer f.Close()
pprof.StartCPUProfile(f)
defer pprof.StopCPUProfile()
start := time.Now()
someFunc()
fmt.Println(time.Since(start))
}
func someFunc() {
var i int
t := time.After(3 * time.Millisecond)
OUT:
for {
select {
case <-t:
break OUT
default:
i++
fmt.Println(i)
}
}
}Не будем ориентироваться только на значения профилировщика, а измерим продолжительность выполнения someFunc:
start := time.Now()
someFunc()
fmt.Println(time.Since(start))При запуске программы в stdout будет выведено время:
...
3.077125msИ построен профиль CPU:
File: main
Type: cpu
Time: Jan 15, 2025 at 3:26pm (UTC)
Duration: 209.44ms, Total samples = 10ms ( 4.77%)
Showing nodes accounting for 10ms, 100% of 10ms total
flat flat% sum% cum cum%
10ms 100% 100% 10ms 100% internal/runtime/syscall.Syscall6
0 0% 100% 10ms 100% fmt.Fprintln
0 0% 100% 10ms 100% fmt.Println (inline)
0 0% 100% 10ms 100% internal/poll.(*FD).Write
0 0% 100% 10ms 100% internal/poll.ignoringEINTRIO (inline)
0 0% 100% 10ms 100% main.main
0 0% 100% 10ms 100% main.someFunc
0 0% 100% 10ms 100% os.(*File).Write
0 0% 100% 10ms 100% os.(*File).write (inline)
0 0% 100% 10ms 100% runtime.main
0 0% 100% 10ms 100% syscall.RawSyscall6
0 0% 100% 10ms 100% syscall.Syscall
0 0% 100% 10ms 100% syscall.Write (inline)
0 0% 100% 10ms 100% syscall.writeЧто получается? - фактическое время выполнения someFunc равно 3.08 миллисекунды, т.е. time.After не так уж сильно замедляет работу программы. А профилировщик показывает 10 миллисекунд. Плохо ли это? - разумеется, это ужасно!... Но это ужасно, если не понимать суть профилирования CPU. Дело в том, что этот профиль даёт не количественную оценку, а качественную. Его цель обнаружить "бутылочное горлышко", а не предоставить точную, детальную информацию. Т.е. при различных временных задержках функции someFunc:
t := time.After(15 * time.Millisecond)File: main
Type: cpu
Time: Jan 15, 2025 at 4:00pm (UTC)
Duration: 207.25ms, Total samples = 20ms ( 9.65%)
Showing nodes accounting for 20ms, 100% of 20ms total
flat flat% sum% cum cum%
20ms 100% 100% 20ms 100% internal/runtime/syscall.Syscall6
0 0% 100% 20ms 100% fmt.Fprintln
0 0% 100% 20ms 100% fmt.Println (inline)
0 0% 100% 20ms 100% internal/poll.(*FD).Write
0 0% 100% 20ms 100% internal/poll.ignoringEINTRIO (inline)
0 0% 100% 20ms 100% main.main
0 0% 100% 20ms 100% main.someFunc
0 0% 100% 20ms 100% os.(*File).Write
0 0% 100% 20ms 100% os.(*File).write (inline)
0 0% 100% 20ms 100% runtime.main
0 0% 100% 20ms 100% syscall.RawSyscall6
0 0% 100% 20ms 100% syscall.Syscall
0 0% 100% 20ms 100% syscall.Write (inline)
0 0% 100% 20ms 100% syscall.writet := time.After(37 * time.Millisecond)File: main
Type: cpu
Time: Jan 15, 2025 at 4:01pm (UTC)
Duration: 206.62ms, Total samples = 40ms (19.36%)
Showing nodes accounting for 40ms, 100% of 40ms total
flat flat% sum% cum cum%
20ms 50.00% 50.00% 20ms 50.00% internal/runtime/syscall.Syscall6
10ms 25.00% 75.00% 10ms 25.00% runtime.casgstatus
10ms 25.00% 100% 10ms 25.00% runtime.nanotime (inline)
0 0% 100% 30ms 75.00% fmt.Fprintln
0 0% 100% 30ms 75.00% fmt.Println (inline)
0 0% 100% 30ms 75.00% internal/poll.(*FD).Write
0 0% 100% 30ms 75.00% internal/poll.ignoringEINTRIO (inline)
0 0% 100% 40ms 100% main.main
0 0% 100% 40ms 100% main.someFunc
0 0% 100% 30ms 75.00% os.(*File).Write
0 0% 100% 30ms 75.00% os.(*File).write (inline)
0 0% 100% 10ms 25.00% runtime.(*timer).maybeRunChan
0 0% 100% 10ms 25.00% runtime.chanrecv
0 0% 100% 10ms 25.00% runtime.entersyscall
0 0% 100% 40ms 100% runtime.main
0 0% 100% 10ms 25.00% runtime.reentersyscall
0 0% 100% 10ms 25.00% runtime.selectnbrecv
0 0% 100% 20ms 50.00% syscall.RawSyscall6
0 0% 100% 30ms 75.00% syscall.Syscall
0 0% 100% 30ms 75.00% syscall.Write (inline)
0 0% 100% 30ms 75.00% syscall.writet := time.After(60 * time.Millisecond)File: main
Type: cpu
Time: Jan 15, 2025 at 4:02pm (UTC)
Duration: 207.50ms, Total samples = 60ms (28.92%)
Showing nodes accounting for 60ms, 100% of 60ms total
flat flat% sum% cum cum%
40ms 66.67% 66.67% 40ms 66.67% internal/runtime/syscall.Syscall6
10ms 16.67% 83.33% 50ms 83.33% os.(*File).write (inline)
10ms 16.67% 100% 10ms 16.67% runtime.nanotime (inline)
0 0% 100% 50ms 83.33% fmt.Fprintln
0 0% 100% 50ms 83.33% fmt.Println (inline)
0 0% 100% 40ms 66.67% internal/poll.(*FD).Write
0 0% 100% 40ms 66.67% internal/poll.ignoringEINTRIO (inline)
0 0% 100% 60ms 100% main.main
0 0% 100% 60ms 100% main.someFunc
0 0% 100% 50ms 83.33% os.(*File).Write
0 0% 100% 10ms 16.67% runtime.(*timer).maybeRunChan
0 0% 100% 10ms 16.67% runtime.chanrecv
0 0% 100% 60ms 100% runtime.main
0 0% 100% 10ms 16.67% runtime.selectnbrecv
0 0% 100% 40ms 66.67% syscall.RawSyscall6
0 0% 100% 40ms 66.67% syscall.Syscall
0 0% 100% 40ms 66.67% syscall.Write (inline)
0 0% 100% 40ms 66.67% syscall.writeПолучаются разные значения cum, но качественная картина не меняется - основное процессорное время уходит на выполнение internal/runtime/syscall.Syscall6.
Вывод
Профиль CPU позволяет оперативно выявить функции, занимающие основное процессорное время
Граф профиля CPU наглядно отображает стек вызовов функций, выделяет самый затратный по времени путь
Несмотря на качественное представление о ходе выполнения логики, профиль CPU позволяет выявить "бутылочное горлышко"
Отсутствие функции в профиле или flat=0s может означать, что её логика выполняется менее 1 миллисекунды
