«Каждый, уважающий себя программист, осваивая новый язык пишет свой логгер» (с) давно было, источник цитаты канул в Лету, в общем — забылся.
Собственно вся история вопроса началась тут. Когда-то, около 3 лет назад, осваивая новый для себя язык, тоже написал свой логгер. Он писался подглядыванием в стандартный логгер, и первое что мне захотелось изменить в нем — это устранить буфер сообщений из структуры самого логера. Это мне показалось тогда нормальным, логгер становится реентерабельным и стало можно пробрасывать один и тот же логгер в несколько горутин, обрамив мьютексом только сам процесс вывода.
Это уменьшает фактическое время блокировок, а значит «хорошо и правильно». :)
Позже, логгер был заброшен, в боевых проектах применялся в основном zap и кое-где попадался logrus. Судя по бенчмаркам, zap был шустр, и в общем-то на этом можно было бы статью и закончить .. но, в один прекрасный момент меня посетила мысль: «а не завести ли свой гитхаб и выложить в него что-нибудь хорошее?» :)
И тут собственно возникло неожиданное продолжение, т. к. выкладывать на гитхаб, писанное на коленке и в начале пути не комильфо, надо бы подчистить и улучшить. Подчистки и улучшения конечно же сопровождались покрытием тестами и бенчмарками. И вот тут, для себя, сделал «открытие», что в Golang всё не совсем так, как это представляется с высоты 40+ лет программирования и опыта писания собственных (Ре)Ассемблеров, компиляторов и пр.. И так.
Для статьи был взят стандартный, библиотечный логгер из пакета log, и доработан в части накопления данных по времени исполнения и аллокациям, перенеся пакет в тестируемый код. Дополнение:
const MaxRepeats = 1000 // for tests into main() only
const MaxPoints = MaxRepeats*2 + 4 // small more that need
// StatItem -- one record for test statistics
type StatItem struct {
Mallocs uint64
Frees uint64
HeapObjects uint64
Moment time.Time
}
// A Logger represents an active logging object that generates lines of
// output to an io.Writer. Each logging operation makes a single call to
// the Writer's Write method. A Logger can be used simultaneously from
// multiple goroutines; it guarantees to serialize access to the Writer.
type Logger struct {
mu sync.Mutex // ensures atomic writes; protects the following fields
prefix string // prefix on each line to identify the logger (but see Lmsgprefix)
flag int // properties
out io.Writer // destination for output
buf []byte // for accumulating text to write
isDiscard int32 // atomic boolean: whether out == io.Discard
// Profiling memory usage for tests
MStat runtime.MemStats
Points [MaxPoints]StatItem // array! Allocating may be by compiler
Len int
}
func (l *Logger) AddPoint() {
if l.Len < MaxPoints {
runtime.ReadMemStats(&l.MStat)
l.Points[l.Len].Mallocs = l.MStat.Mallocs
l.Points[l.Len].Frees = l.MStat.Frees
l.Points[l.Len].HeapObjects = l.MStat.HeapObjects
l.Points[l.Len].Moment = time.Now()
l.Len++
// for go benchmarks only:
if l.Len > MaxPoints {
l.Len = 0
}
}
}
Ничего сверхестественного, добавляем структуру сохранения и метод для снятия данных в заданной точке. Пытаемся избежать аллокаций и в логгер добавляем массив заранее определенного размера, известного на стадии компиляции. Как-бы любой «уважающий себя компилятор» выделит память под логгер и массив одним запросом.. :)
Далее, делаем ручной тест:
package main
import (
"bytes"
"memtest/logger"
"os"
)
// Global vars. Waiting this will be allocated by compiler
var outbuf [1024]byte // array! allocating may be by compiler
var outWriter = bytes.NewBuffer(outbuf[:0]) // create slice from array and generate new Writer may be by compiler too
func main() {
var stdLog = stdlogger.New(outWriter, "", 0)
stdLog.AddPoint() // [0]
for i := 0; i < stdlogger.MaxRepeats; i++ {
outWriter.Reset()
stdLog.AddPoint()
stdLog.Print("This a simple message")
stdLog.AddPoint() // [2] for first cycle!
}
stdLog.AddPoint()
// clear out flags and switch for see
stdLog.SetFlags(0)
stdLog.SetOutput(os.Stdout)
for i := 0; i < stdLog.Len; i++ {
//stdLog.Printf("\n%v", stdLog.Points[i])
}
stdLog.Printf("Total time=%d ns", stdLog.Points[stdLog.Len-].Moment.Sub(stdLog.Points[0].Moment).Nanoseconds())
stdLog.Printf("Total allocates=%d, frees=%d, heap objects=%d",
stdLog.Points[stdLog.Len-1].Mallocs-stdLog.Points[0].Mallocs,
stdLog.Points[stdLog.Len-1].Frees-stdLog.Points[0].Frees,
stdLog.Points[stdLog.Len-1].HeapObjects-stdLog.Points[0].HeapObjects,
)
stdLog.Printf("\nAvg time=%d ns/op", stdLog.Points[stdLog.Len-1].Moment.Sub(stdLog.Points[0].Moment).Nanoseconds()/stdlogger.MaxRepeats)
stdLog.Printf("Avg allocates=%d, frees=%d, objects=%d /op",
(stdLog.Points[stdLog.Len-1].Mallocs-stdLog.Points[0].Mallocs)/stdlogger.MaxRepeats,
(stdLog.Points[stdLog.Len-1].Frees-stdLog.Points[0].Frees)/stdlogger.MaxRepeats,
(stdLog.Points[stdLog.Len-1].HeapObjects-stdLog.Points[0].HeapObjects)/stdlogger.MaxRepeats,
)
stdLog.Printf("\nFirst run time=%d ns", stdLog.Points[2].Moment.Sub(stdLog.Points[0].Moment).Nanoseconds())
stdLog.Printf("First run allocated=%d, frees=%d, objects=%d",
stdLog.Points[2].Mallocs-stdLog.Points[0].Mallocs,
stdLog.Points[2].Frees-stdLog.Points[0].Frees,
stdLog.Points[2].HeapObjects-stdLog.Points[0].HeapObjects,
)
}
Запускаем .. и получаем нечто странное:
/tmp/GoLand/___go_build_memtest
Total time=12754376 ns
Total allocates=1005, frees=0, heap objects=1005
Avg time=12754 ns/op
Avg allocates=1, frees=0, objects=1 /op
First run time=60205 ns
First run allocated=6, frees=0, objects=6
Всего аллоцировано 1005 объектов в куче! Количество проходов = 1000 и за первый проход аллоцировано 6 объектов. Одна аллокация в цикле тестирования и первом проходе понятна: там выводится строка, под которую выделяется память внутри fmt.Sprintf(), что нормально.
Откуда 5 аллокаций при первом проходе?
Хорошо, пишем бенчмарк:
package stdlogger
import (
"bytes"
"testing"
)
var outbuf [1024]byte // array! allocating may be by compiler
var outWriter = bytes.NewBuffer(outbuf[:0]) // create slice from array and generate new Writer may be by compiler too
func Benchmark_stdLog(b *testing.B) {
var stdLog = New(outWriter, "", 0)
b.ResetTimer()
for i := 0; i < b.N; i++ {
outWriter.Reset()
stdLog.AddPoint()
stdLog.Print("This a simple message")
stdLog.AddPoint()
}
}
, запускаем командой go test -bench=. -benchmem -cpu=1, чтобы не смотреть во сколько потоков запускает тест и .. получаем ответ:
goos: linux
goarch: amd64
pkg: memtest/stdlogger
cpu: Intel(R) Core(TM) i5-9400F CPU @ 2.90GHz
Benchmark_stdLog 8744750 134.3 ns/op 24 B/op 1 allocs/op
.. просто удивительная разница по времени исполнения! А ведь в первом и втором цикле вызывается ровно один и тот же код, и массив точек съема данных для бенчмарка закольцован, а цикл в main() не выходит за его границу. Ну ок, давайте запустим тест с явным указанием повторов:
а) командой: go test -bench=. -benchmem -cpu=1 -benchtime=1x -count=1000
goos: linux
goarch: amd64
pkg: memtest/stdlogger
cpu: Intel(R) Core(TM) i5-9400F CPU @ 2.90GHz
Benchmark_stdLog 1 11981 ns/op 416 B/op 6 allocs/op
… тут ещё 998 строк примерно как ниже:
Benchmark_stdLog 1 7366 ns/op 184 B/op 4 allocs/op
б) командой: go test -bench=. -benchmem -cpu=1 -benchtime=1000x -count=1
goos: linux
goarch: amd64
pkg: memtest/stdlogger
cpu: Intel(R) Core(TM) i5-9400F CPU @ 2.90GHz
Benchmark_stdLog 1000 2334 ns/op 24 B/op 1 allocs/op
Как всё интересно-то! Параметр -benchtime – в нашем случае это количество повторов, передаваемое в цикл b.N. То есть, при N=1 мы получаем 1000 перезапусков теста и оценку скорости исполнения «в среднем», но по 1 повтору кода. И тут внезапно обнаруживаем, что «в среднем» у нас не 6 аллокаций, а .. только 4. То есть пара объектов сохраняет свое время жизни между вызовами тестируемой функции несмотря на всю локальность объявлений..
Второй вариант дает нам 1000 повторов цикла при однократном запуске теста и тут однократность первых аллокаций вполне штатно показывает на одно размещение внутри цикла. Ну, мы же помним про fmt.Sprintf(), ничего удивительного, кроме .. времени исполнения. Давайте увеличим количество повторов:
go test -bench=. -benchmem -cpu=1 -benchtime=100000x -count=1
goos: linux
goarch: amd64
pkg: memtest/stdlogger
cpu: Intel(R) Core(TM) i5-9400F CPU @ 2.90GHz
Benchmark_stdLog 100000 153.9 ns/op 24 B/op 1 allocs/op
Ну вот, всё ожидаемо.
А теперь вопрос на засыпку: почему бенчмарк в пункте «б» исполнившись в точности также 1000 раз за 1 проход показал иное время исполнения 2334 наносекунды на цикл, в то время как тест в main() выдал почти в 6 раз большее значение: Avg time=12754 ns/op?
А давайте увеличим константу const MaxRepeats = 10000
и прогоним main() ещё раз:
Total time=124476321 ns
Total allocates=10005, frees=0, heap objects=10005
Avg time=12447 ns/op
Avg allocates=1, frees=0, objects=1 /op
First run time=132694 ns
First run allocated=6, frees=0, objects=6
, странно не правда ли? Среднее время исполнения в main() практически не изменилось! То есть нечто крайне интересное происходит при тестировании go test -bench=…
Заглядываем в код benchmark.go и .. видим, что принципиальных отличий нет, кроме блокировки мьютексом исполняемого кода (даже понятно зачем) и ручного запуска runtime.GC() перед началом цикла тестовой функции. Ровно тот же самый вызов runtime.ReadMemStats(&memStats) для подсчета аллокаций до и после запуска тестируемой функции, тот же вызов time.Now() для подсчета времени исполнения..
Ну, ок. Давайте вызовем тоже GC предварительно в нашем main(), а ещё дополним вывод количества сохраненных точек и размер массива для контроля .. и получим:
Len=20002, cap=20004
Total time=125534130 ns
Total allocates=10005, frees=0, heap objects=10005
Avg time=12553 ns/op
Avg allocates=1, frees=0, objects=1 /op
First run time=55850 ns
First run allocated=6, frees=0, objects=6
Ничего революционного однако не произошло.. как было 12.5 микросекунд на цикл исполнения так примерно и осталось. Как было 5 дополнительных аллокаций, так и осталось. Как-бы уже возникают вопросы к скорости исполнения, которые показывает бенчмарк, ибо отличие в 6 раз должно быть как-то объяснено.
Вопрос на засыпку 2: А что тогда измеряет benchmark? :)
Ещё один момент:
В тесте main() логгер создается локально, что требует выделения памяти или на стеке или в куче. Хорошо. Давайте перенесем объявление логгера в статический глобал. Тут уже, компилятор точно знает что это одна такая переменная, размер занимаемой памяти фиксирован и известен на стадии компиляции и ее можно выделить статически:
var stdLog = stdlogger.Logger{
MStat: runtime.MemStats{},
Points: [20004]stdlogger.StatItem{},
Len: 0,
}
func main() {
stdlogger.SetOutput(outWriter)
stdlogger.SetFlags(0) stdlogger.SetPrefix("")
// .. далее по тексту выше, запускаем main() .. и получаем:
/tmp/GoLand/___go_build_memtest
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x18 pc=0x48cad6]
goroutine 1 [running]:
memtest/stdlogger.(*Logger).Output(0x56e240, 0x1?, {0xc00001c1b0, 0x15})
~/myProjectsGo/memtest/stdlogger/stdlog.go:237 +0x356
memtest/stdlogger.(*Logger).Print(0x56e240, {0xc00009af10?, 0xc0000a0150?, 0x7ff4d8554bb8?})
~/myProjectsGo/memtest/stdlogger/stdlog.go:256 +0x5a
main.main()
~/myProjectsGo/memtest/main.go:30 +0xdd
Ух-ты! Паника! Забавно, что она возникает там, где и должна возникать в коде этого логера, т. к. внутренний буфер l.buf []byte не инициализируется ни в самом коде логера NEW() ни тут в нашем тестовом коде. Однако, динамически выделенная память под логгер функцией New() работает штатно, а вот объявление глобальной переменной — нет.
Забавный фокус Go, о котором хорошо осведомлены авторы пакета:
var std = New(os.Stderr, "", LstdFlags)Стандартный логгер — также глобален, но выделяет память динамически, тоже вызывая метод log.New().. Каким волшебным образом, динамически создаваемая структура методом New(), без явной инициализации слайса, тем не менее, нормально аллоцирует память далее в коде исполнения, в то время как та же самая структура, но объявленная по сути статически, уже такого не делает?
Откуда все-таки берутся аллокации там, где компилятор точно знает размер и способен выделять память самостоятельно? А так ли это? Давайте проверим, и выведем пустую строку:
func main() {
stdLog := stdlogger.New(outWriter, "", 0)
runtime.GC()
stdLog.AddPoint() // [0]
for i := 0; i < stdlogger.MaxRepeats; i++ {
outWriter.Reset()
stdLog.AddPoint()
stdLog.Print("")
stdLog.AddPoint() // [2] for first cycle!
}
stdLog.AddPoint()
, запускаем main() и получаем:
Len=20002, cap=20004
Total time=121876995 ns
Total allocates=4, frees=0, heap objects=4
Avg time=12187 ns/op
Avg allocates=0, frees=0, objects=0 /op
First run time=17479 ns
First run allocated=4, frees=0, objects=4
Во-от. Fmt.Sprintf() не аллоцировал память, что видно по средним показателям, но первый вызов цикла все равно аллоцировал 4 объекта в куче. Забавно, что теперь, вернувшись к примеру из самого начала (такое же локальное создание логгера в начале main()) получили существенно меньшее время исполнения первого прохода.. это как? :)
Путем манипуляций с пакетом, можно убедиться что поле логгера buf []byte на самом деле под капотом имеет 2 аллокации: память под сам массив + память под структуру слайса. (сколько аллокаций делает make(map[...]...) можно догадаться, глянув на структуру мапы под капотом). Кроме того строчка l.buf = l.buf[:0] на самом деле создает новый слайс и сохраняет его в старом месте, а не обнуляет, как можно наивно подумать. Ну и кроме этого, передача результата fmt.Sprintf() в параметр l.Output() также под капотом может содержать аллокацию, т. к. строка в Go это структура из указателя и размера строки.
Но, если это так, то почему аллокация в этих случаях делается один раз и только при первом проходе?
В целом, вопросов возникло много, буду признателен тем, кто хорошо разобрался в том, что творится под капотом Go. Пока ясно одно: внутренняя аллокация памяти «на стеке» и «в куче» не имеет принципиальной разницы, что и указано авторами, где-то в Faq по модели памяти Go. И то и другое — есть внутренний механизм, и по сути одинаковый.
В данном обзоре сознательно не полез в Ассемблер, хотя и догадываюсь что все ответы можно найти там, но, в этом случае, текст статьи получился бы исключительно для «профи», которым это всё известно и так.
Спасибо, если дочитали до конца. Это моя первая статья в жизни. :)
