«Каждый, уважающий себя программист, осваивая новый язык пишет свой логгер» (с) давно было, источник цитаты канул в Лету, в общем — забылся.
Собственно вся история вопроса началась тут. Когда-то, около 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. И то и другое — есть внутренний механизм, и по сути одинаковый.
В данном обзоре сознательно не полез в Ассемблер, хотя и догадываюсь что все ответы можно найти там, но, в этом случае, текст статьи получился бы исключительно для «профи», которым это всё известно и так.
Спасибо, если дочитали до конца. Это моя первая статья в жизни. :)
