«Каждый, уважающий себя программист, осваивая новый язык пишет свой логгер» (с) давно было, источник цитаты канул в Лету, в общем — забылся.

Собственно вся история вопроса началась тут. Когда-то, около 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. И то и другое — есть внутренний механизм, и по сути одинаковый.

В данном обзоре сознательно не полез в Ассемблер, хотя и догадываюсь что все ответы можно найти там, но, в этом случае, текст статьи получился бы исключительно для «профи», которым это всё известно и так.

Спасибо, если дочитали до конца. Это моя первая статья в жизни. :)

Тестирование исполняемого кода Go