slog: Records

Add the Record type, used to communicate between the Loggers and
Handlers.

We use a combination of a small inline array and a functional list
so that copies of a Record do not affect each other's sequence
of Attrs.

Change-Id: I4f800d6fccf7b4ba9a2d2e4b151f540fc883f335
Reviewed-on: https://go-review.googlesource.com/c/exp/+/426023
Run-TryBot: Jonathan Amsterdam <[email protected]>
Reviewed-by: Alan Donovan <[email protected]>

Author: jba

slog/list.go

@@ -0,0 +1,85 @@
+package slog
+
+// A list[T] is an immutable sequence.
+// It supports three operations: append, len and indexing (at).
+// The zero value is an empty list.
+//
+// Repeated calls to append happen in amortized O(1) space and time. (Appending
+// an element allocates one node directly, and the normalize operation always
+// doubles the front slice, so we can charge two slots to each element.)
+//
+// The len method takes constant time.
+//
+// The at method requires a normalized list, and then takes constant time.
+//
+// It is possible to obtain quadratic behavior by alternating append and at:
+// the normalize required by at is called for each appended element, causing
+// front to be copied each time.
+type list[T any] struct {
+	front   []T
+	back    *node[T] // reversed
+	lenBack int
+}
+
+type node[T any] struct {
+	el   T
+	next *node[T]
+}
+
+// append returns a new list consisting of the receiver with x appended.
+func (l list[T]) append(x T) list[T] {
+	if l.front == nil {
+		// Empty list; return one with one element.
+		return list[T]{
+			front:   []T{x},
+			back:    nil,
+			lenBack: 0,
+		}
+	}
+	if l.lenBack == len(l.front) {
+		// When there are as many elements in back as in front, grow
+		// front and move all of back to it.
+		l = l.normalize()
+	}
+	// Push a new node with the element onto back, which is stored in
+	// reverse order.
+	return list[T]{
+		front:   l.front,
+		back:    &node[T]{el: x, next: l.back},
+		lenBack: l.lenBack + 1,
+	}
+}
+
+// len returns the number of elements in the list.
+func (l list[T]) len() int {
+	return len(l.front) + l.lenBack
+}
+
+// at returns the ith element of the list.
+// The list must be normalized.
+func (l list[T]) at(i int) T {
+	if l.back != nil {
+		panic("not normalized")
+	}
+	return l.front[i]
+}
+
+// normalize returns a list whose back is nil and whose front contains all the
+// receiver's elements.
+func (l list[T]) normalize() list[T] {
+	if l.back == nil {
+		return l
+	}
+	newFront := make([]T, len(l.front)+l.lenBack)
+	copy(newFront, l.front)
+	i := len(newFront) - 1
+	for b := l.back; b != nil; b = b.next {
+		newFront[i] = b.el
+		i--
+	}
+	return list[T]{
+		front:   newFront,
+		back:    nil,
+		lenBack: 0,
+	}
+}

slog/list_test.go

@@ -0,0 +1,39 @@
+package slog
+
+import (
+	"testing"
+
+	"golang.org/x/exp/slices"
+)
+
+func TestList(t *testing.T) {
+	var l list[int]
+	for i := 0; i < 10; i++ {
+		l = l.append(i)
+	}
+	l = l.normalize()
+	var got, want []int
+	for i := 0; i < l.len(); i++ {
+		want = append(want, i)
+		got = append(got, l.at(i))
+	}
+	if !slices.Equal(got, want) {
+		t.Errorf("got %v, want %v", got, want)
+	}
+}
+
+func TestListAlloc(t *testing.T) {
+	for n := 1; n < 100; n++ {
+		got := testing.AllocsPerRun(1, func() {
+			var l list[int]
+			for i := 0; i < n; i++ {
+				l = l.append(i)
+			}
+		})
+		want := 1.5 * float64(n)
+		if got > want {
+			t.Fatalf("n=%d: got %f allocations, want <= %f",
+				n, got, want)
+		}
+	}
+}

slog/record.go

@@ -0,0 +1,127 @@
+// Copyright 2022 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package slog
+
+import (
+	"runtime"
+	"time"
+)
+
+const nAttrsInline = 5
+
+// A Record holds information about a log event.
+type Record struct {
+	// The time at which the output method (Log, Info, etc.) was called.
+	time time.Time
+
+	// The log message.
+	message string
+
+	// The level of the event.
+	level Level
+
+	// The pc at the time the record was constructed, as determined
+	// by runtime.Callers using the calldepth argument to NewRecord.
+	pc uintptr
+
+	// Allocation optimization: an inline array sized to hold
+	// the majority of log calls (based on examination of open-source
+	// code). The array holds the end of the sequence of Attrs.
+	tail [nAttrsInline]Attr
+
+	// The number of Attrs in tail.
+	nTail int
+
+	// The sequence of Attrs except for the tail, represented as a functional
+	// list of arrays.
+	attrs list[[nAttrsInline]Attr]
+}
+
+// MakeRecord creates a new Record from the given arguments.
+// Use [Record.AddAttr] to add attributes to the Record.
+// If calldepth is greater than zero, [Record.SourceLine] will
+// return the file and line number at that depth,
+// where 1 means the caller of MakeRecord.
+//
+// MakeRecord is intended for logging APIs that want to support a [Handler] as
+// a backend.
+func MakeRecord(t time.Time, level Level, msg string, calldepth int) Record {
+	var p uintptr
+	if calldepth > 0 {
+		p = pc(calldepth + 1)
+	}
+	return Record{
+		time:    t,
+		message: msg,
+		level:   level,
+		pc:      p,
+	}
+}
+
+func pc(depth int) uintptr {
+	var pcs [1]uintptr
+	runtime.Callers(depth, pcs[:])
+	return pcs[0]
+}
+
+// Time returns the time of the log event.
+func (r *Record) Time() time.Time { return r.time }
+
+// Message returns the log message.
+func (r *Record) Message() string { return r.message }
+
+// Level returns the level of the log event.
+func (r *Record) Level() Level { return r.level }
+
+// SourceLine returns the file and line of the log event.
+// If the Record was created without the necessary information,
+// or if the location is unavailable, it returns ("", 0).
+func (r *Record) SourceLine() (file string, line int) {
+	fs := runtime.CallersFrames([]uintptr{r.pc})
+	// TODO: error-checking?
+	f, _ := fs.Next()
+	return f.File, f.Line
+}
+
+// Attrs returns a copy of the sequence of Attrs in r.
+func (r *Record) Attrs() []Attr {
+	res := make([]Attr, 0, r.attrs.len()*nAttrsInline+r.nTail)
+	r.attrs = r.attrs.normalize()
+	for _, f := range r.attrs.front {
+		res = append(res, f[:]...)
+	}
+	for _, a := range r.tail[:r.nTail] {
+		res = append(res, a)
+	}
+	return res
+}
+
+// NumAttrs returns the number of Attrs in r.
+func (r *Record) NumAttrs() int {
+	return r.attrs.len()*nAttrsInline + r.nTail
+}
+
+// Attr returns the i'th Attr in r.
+func (r *Record) Attr(i int) Attr {
+	if r.attrs.back != nil {
+		r.attrs = r.attrs.normalize()
+	}
+	alen := r.attrs.len() * nAttrsInline
+	if i < alen {
+		return r.attrs.at(i / nAttrsInline)[i%nAttrsInline]
+	}
+	return r.tail[i-alen]
+}
+
+// AddAttr appends an attributes to the record's list of attributes.
+// It does not check for duplicate keys.
+func (r *Record) AddAttr(a Attr) {
+	if r.nTail == len(r.tail) {
+		r.attrs = r.attrs.append(r.tail)
+		r.nTail = 0
+	}
+	r.tail[r.nTail] = a
+	r.nTail++
+}

slog/record_test.go

@@ -0,0 +1,144 @@
+// Copyright 2022 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package slog
+
+import (
+	"strings"
+	"testing"
+	"time"
+
+	"golang.org/x/exp/slices"
+	"golang.org/x/exp/slog/internal/buffer"
+)
+
+func TestRecordAttrs(t *testing.T) {
+	as := []Attr{Int("k1", 1), String("k2", "foo"), Int("k3", 3),
+		Int64("k4", -1), Float64("f", 3.1), Uint64("u", 999)}
+	r := newRecordWithAttrs(as)
+	if g, w := r.NumAttrs(), len(as); g != w {
+		t.Errorf("NumAttrs: got %d, want %d", g, w)
+	}
+	if got := r.Attrs(); !attrsEqual(got, as) {
+		t.Errorf("got %v, want %v", got, as)
+	}
+}
+
+func TestRecordSourceLine(t *testing.T) {
+	// Zero call depth => empty file/line
+	for _, test := range []struct {
+		depth            int
+		wantFile         string
+		wantLinePositive bool
+	}{
+		{0, "", false},
+		{-16, "", false},
+		{1, "record.go", true},
+	} {
+		r := MakeRecord(time.Time{}, 0, "", test.depth)
+		gotFile, gotLine := r.SourceLine()
+		if i := strings.LastIndexByte(gotFile, '/'); i >= 0 {
+			gotFile = gotFile[i+1:]
+		}
+		if gotFile != test.wantFile || (gotLine > 0) != test.wantLinePositive {
+			t.Errorf("depth %d: got (%q, %d), want (%q, %t)",
+				test.depth, gotFile, gotLine, test.wantFile, test.wantLinePositive)
+		}
+	}
+}
+
+func TestAliasing(t *testing.T) {
+	intAttrs := func(from, to int) []Attr {
+		var as []Attr
+		for i := from; i < to; i++ {
+			as = append(as, Int("k", i))
+		}
+		return as
+	}
+
+	check := func(r *Record, want []Attr) {
+		t.Helper()
+		got := r.Attrs()
+		if !attrsEqual(got, want) {
+			t.Errorf("got %v, want %v", got, want)
+		}
+	}
+
+	r1 := MakeRecord(time.Time{}, 0, "", 0)
+	for i := 0; i < nAttrsInline+3; i++ {
+		r1.AddAttr(Int("k", i))
+	}
+	check(&r1, intAttrs(0, nAttrsInline+3))
+	r2 := r1
+	check(&r2, intAttrs(0, nAttrsInline+3))
+	// if cap(r1.attrs2) <= len(r1.attrs2) {
+	// 	t.Fatal("cap not greater than len")
+	// }
+	r1.AddAttr(Int("k", nAttrsInline+3))
+	r2.AddAttr(Int("k", -1))
+	check(&r1, intAttrs(0, nAttrsInline+4))
+	check(&r2, append(intAttrs(0, nAttrsInline+3), Int("k", -1)))
+}
+
+func newRecordWithAttrs(as []Attr) Record {
+	r := MakeRecord(time.Now(), InfoLevel, "", 0)
+	for _, a := range as {
+		r.AddAttr(a)
+	}
+	return r
+}
+
+func attrsEqual(as1, as2 []Attr) bool {
+	return slices.EqualFunc(as1, as2, Attr.Equal)
+}
+
+// Currently, pc(2) takes over 400ns, which is too expensive
+// to call it for every log message.
+func BenchmarkPC(b *testing.B) {
+	b.ReportAllocs()
+	var x uintptr
+	for i := 0; i < b.N; i++ {
+		x = pc(3)
+	}
+	_ = x
+}
+
+func BenchmarkSourceLine(b *testing.B) {
+	r := MakeRecord(time.Now(), InfoLevel, "", 5)
+	b.Run("alone", func(b *testing.B) {
+		for i := 0; i < b.N; i++ {
+			file, line := r.SourceLine()
+			_ = file
+			_ = line
+		}
+	})
+	b.Run("stringifying", func(b *testing.B) {
+		for i := 0; i < b.N; i++ {
+			file, line := r.SourceLine()
+			buf := buffer.New()
+			buf.WriteString(file)
+			buf.WriteByte(':')
+			itoa((*[]byte)(buf), line, -1)
+			s := string(*buf)
+			buf.Free()
+			_ = s
+		}
+	})
+}
+
+func BenchmarkRecord(b *testing.B) {
+	const nAttrs = nAttrsInline * 10
+	var a Attr
+
+	for i := 0; i < b.N; i++ {
+		r := MakeRecord(time.Time{}, InfoLevel, "", 0)
+		for j := 0; j < nAttrs; j++ {
+			r.AddAttr(Int("k", j))
+		}
+		for j := 0; j < nAttrs; j++ {
+			a = r.Attr(j)
+		}
+	}
+	_ = a
+}