Go неверное выделение памяти для []byte или ошибка в go test benchmark?

Question

Смотрим стандартный логгер из пакета log. В его структуре находится поле(свойство) buf:

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
}

Функция log.New() также не инициализует это поле и оно остается nil, что видно под дебаггером. Если запустить вот такой бенчмарк с -benchmem:

var stdLgr = log.New(bufWriter, "", log.Ldate)
func Benchmark_Stdlog(b *testing.B) {
  for i := 0; i < b.N; i++ {
    bufWriter.Reset()
    stdLgr.Printf("any info message")
  }
}

То получаем:

Benchmark_Stdlog-4 360367 2898 ns/op 16 B/op 1 allocs/op

где наглядно видно что логгер делает только одну аллокацию и только для операции fmt.Sprintf() внутри себя. Хотя под дебагером видно, что слайс buf наращивает свою длину согласно принятому в Go алгоритму: 8, 16,32,64 байта.

Это ошибка бенчмарка, что он не видит аллокаций для полей структур типа []byte (возможно и иных слайсов!) или это особенное поведение компилятора Go для неинициализированного слайса байт?

Кстати, если заменить поле логгера на глобальный буфер этого же типа: var buf []byte то бенчмарк точно также не видит аллоцирование памяти функцией append()!

Кто-то может объяснить что происходит? Проверил на версии Go 1.20.0

Answer 1

UPDATE

Вот прямое доказательство того, что log не делает переаллокации. Я скопировал /usr/local/go/src/log/log.go к себе и поменял видимость поля buf на Buf

package main

import (
    "os"
    "reflect"
    "runtime"

    "example.org/trylog/mylog"
)
func main() {
    var ms0 runtime.MemStats
    l := mylog.New(os.Stdout, "", mylog.Ldate)
    runtime.ReadMemStats(&ms0)
    l.Println(ms0.Mallocs, ms0.Frees, cap(l.Buf), reflect.ValueOf(l.Buf).Pointer())
    runtime.ReadMemStats(&ms0)
    l.Println(ms0.Mallocs, ms0.Frees, cap(l.Buf), reflect.ValueOf(l.Buf).Pointer())
    runtime.ReadMemStats(&ms0)
    l.Println(ms0.Mallocs, ms0.Frees, cap(l.Buf), reflect.ValueOf(l.Buf).Pointer())
    runtime.ReadMemStats(&ms0)
    l.Println(ms0.Mallocs, ms0.Frees, cap(l.Buf), reflect.ValueOf(l.Buf).Pointer())
    runtime.ReadMemStats(&ms0)
    l.Println(ms0.Mallocs, ms0.Frees, cap(l.Buf), reflect.ValueOf(l.Buf).Pointer())

}

(пакет example.org/trylog/mylog - это мой пакет, в который я скопировал стандартный log)

Что получилось:

2023/04/02 134 2 0 0
2023/04/02 164 9 32 824633852064
2023/04/02 169 9 64 824633868416
2023/04/02 172 9 64 824633868416
2023/04/02 175 9 64 824633868416

Что видно - при первых двух вызовах Buf менялся - изменились размер и положение в памяти. А потом всё, размер зафиксировался, указатель перестал изменяться. Аллокации в последних вызовах происходят за счёт fmt.Sprint и reflect.Valueof.

ИСХОДНЫЙ ОТВЕТ

Я бы предположил, что аллокация, которую показывает бенчмарк, происходит только в fmt.Sprintf. Вот код log.Printf:

// Printf calls l.Output to print to the logger.
// Arguments are handled in the manner of fmt.Printf.
func (l *Logger) Printf(format string, v ...any) {
    if l.isDiscard.Load() {
        return
    }
    l.Output(2, fmt.Sprintf(format, v...))
}

Видно, что за сборку сообщения отвечает fmt. Функция Output пишет во внутренний буфер заголовок и готовую строку:

func (l *Logger) Output(calldepth int, s string) error {
    // ...
    l.buf = l.buf[:0]
    l.formatHeader(&l.buf, now, file, line)
    l.buf = append(l.buf, s...)
    if len(s) == 0 || s[len(s)-1] != '\n' {
        l.buf = append(l.buf, '\n')
    }
    _, err := l.out.Write(l.buf)
    return err
}

Как мне кажется, вот эта строчка делает весь фокус с нулевой аллокацией: l.buf = l.buf[:0]

Получается, что между вызовами функций логера внутренний буфер не изменяется в размерах (capacity), меняется только длина размещённых внутри данных. Другими словами, при нескольких первых прогонах бенчмарка этот буфер был аллоцирован до нужного размера, а затем памяти было достаточно, чтобы обойтись без аллокаций. Так как результаты бенчмарка содержат усреднённое значение, то несколько аллокаций, поделённые на тысячи прогонов, даёт среднее значение 0.

Проверка: давайте проверим число аллокаций для теста stdLog.Print(), то есть исключим из уравнения fmt.Sprintf. В этом случае в буфер пишется заголовок время имя_файла:строка, но не формируется строка сообщения.

func Benchmark_Stdlog_EmptyMsg(b *testing.B) {
    bz := make([]byte, 1024)
    bufWriter := bytes.NewBuffer(bz)
    var stdLgr = log.New(bufWriter, "", log.Ldate)
    for i := 0; i < b.N; i++ {
        bufWriter.Reset()
        stdLgr.Print()
    }
}

Benchmark_Stdlog_EmptyMsg-8       653286          2531 ns/op           0 B/op          0 allocs/op

Видите? Ноль аллокаций.

БЛОГ НА HUSL

Go неверное выделение памяти для []byte или ошибка в go test benchmark?

Ответы (1 шт):