chore(repository): reduced memory allocations when logging content.ID (#2024)

This fixes regression introduced in #1960.

Tested by backing up Linux 5.14.8 source on M1 Mac (average of 15 runs):

Before: duration=6.7s avg_heap_objects=7411657 avg_heap_bytes=871794888
After: duration=5.6s (17% faster) avg_heap_objects=5947800 (20% less) avg_heap_bytes=795762120 (9% less)

repo/content/content_manager.go

@@ -783,6 +783,12 @@ func (bm *WriteManager) WriteContent(ctx context.Context, data gather.Bytes, pre
 	_, bi, err := bm.getContentInfoReadLocked(ctx, contentID)
 	bm.mu.RUnlock()
 
+	logbuf := logging.GetBuffer()
+	defer logbuf.Release()
+
+	logbuf.AppendString("write-content ")
+	contentID.AppendToLogBuffer(logbuf)
+
 	// content already tracked
 	if err == nil {
 		if !bi.GetDeleted() {
@@ -791,11 +797,12 @@ func (bm *WriteManager) WriteContent(ctx context.Context, data gather.Bytes, pre
 
 		previousWriteTime = bi.GetTimestampSeconds()
 
-		bm.log.Debugf("write-content %v previously-deleted", contentID)
-	} else {
-		bm.log.Debugf("write-content %v new", contentID)
+		logbuf.AppendString(" previously-deleted:")
+		logbuf.AppendInt64(previousWriteTime)
 	}
 
+	bm.log.Debugf(logbuf.String())
+
 	return contentID, bm.addToPackUnlocked(ctx, contentID, data, false, comp, previousWriteTime)
 }
 

repo/content/content_manager_lock_free.go

@@ -18,6 +18,7 @@
 	"github.com/kopia/kopia/repo/content/index"
 	"github.com/kopia/kopia/repo/encryption"
 	"github.com/kopia/kopia/repo/hashing"
+	"github.com/kopia/kopia/repo/logging"
 )
 
 const indexBlobCompactionWarningThreshold = 1000
@@ -109,12 +110,26 @@ func (bm *WriteManager) preparePackDataContent(pp *pendingPackInfo) (index.Build
 	packFileIndex := index.Builder{}
 	haveContent := false
 
+	sb := logging.GetBuffer()
+	defer sb.Release()
+
 	for _, info := range pp.currentPackItems {
 		if info.GetPackBlobID() == pp.packBlobID {
 			haveContent = true
 		}
 
-		bm.log.Debugf("add-to-pack %v %v p:%v %v d:%v", pp.packBlobID, info.GetContentID(), info.GetPackBlobID(), info.GetPackedLength(), info.GetDeleted())
+		sb.Reset()
+		sb.AppendString("add-to-pack ")
+		sb.AppendString(string(pp.packBlobID))
+		sb.AppendString(" ")
+		info.GetContentID().AppendToLogBuffer(sb)
+		sb.AppendString(" p:")
+		sb.AppendString(string(info.GetPackBlobID()))
+		sb.AppendString(" ")
+		sb.AppendUint32(info.GetPackedLength())
+		sb.AppendString(" d:")
+		sb.AppendBoolean(info.GetDeleted())
+		bm.log.Debugf(sb.String())
 
 		packFileIndex.Add(info)
 	}

repo/content/index/id.go

@@ -9,6 +9,7 @@
 	"github.com/pkg/errors"
 
 	"github.com/kopia/kopia/repo/hashing"
+	"github.com/kopia/kopia/repo/logging"
 )
 
 // IDPrefix represents a content ID prefix (empty string or single character between 'g' and 'z').
@@ -94,6 +95,18 @@ func (i ID) less(other ID) bool {
 	return bytes.Compare(i.data[:i.idLen], other.data[:other.idLen]) < 0
 }
 
+// AppendToLogBuffer appends content ID to log buffer.
+func (i ID) AppendToLogBuffer(sb *logging.Buffer) {
+	var buf [128]byte
+
+	if i.prefix != 0 {
+		sb.AppendByte(i.prefix)
+	}
+
+	hex.Encode(buf[0:i.idLen*2], i.data[0:i.idLen])
+	sb.AppendBytes(buf[0 : i.idLen*2])
+}
+
 // String returns a string representation of ID.
 func (i ID) String() string {
 	return string(i.Prefix()) + hex.EncodeToString(i.data[:i.idLen])

repo/content/index/id_test.go

@@ -5,6 +5,8 @@
 	"testing"
 
 	"github.com/stretchr/testify/require"
+
+	"github.com/kopia/kopia/repo/logging"
 )
 
 func TestIDValid(t *testing.T) {
@@ -23,12 +25,19 @@ func TestIDValid(t *testing.T) {
 
 	var validContentIDsOrdered []ID
 
+	sb := logging.GetBuffer()
+	defer sb.Release()
+
 	for _, s := range validIDsOrdered {
 		cid, err := ParseID(s)
 		require.NoError(t, err)
 
 		require.Equal(t, s, cid.String())
 
+		sb.Reset()
+		cid.AppendToLogBuffer(sb)
+		require.Equal(t, s, sb.String())
+
 		validContentIDsOrdered = append(validContentIDsOrdered, cid)
 	}
 

repo/logging/logging_buf.go

@@ -0,0 +1,148 @@
+package logging
+
+import (
+	"reflect"
+	"strconv"
+	"sync"
+	"time"
+	"unsafe"
+)
+
+// Buffer is a specialized buffer that can be kept in a pool used
+// for constructing logging messages without allocation.
+type Buffer struct {
+	buf      [1024]byte
+	validLen int // valid length
+}
+
+// nolint:gochecknoglobals
+var bufPool = &sync.Pool{
+	New: func() interface{} {
+		return &Buffer{}
+	},
+}
+
+// GetBuffer gets a logging buffer.
+func GetBuffer() *Buffer {
+	// nolint:forcetypeassert
+	return bufPool.Get().(*Buffer)
+}
+
+// Release releases logging buffer back to the pool.
+func (b *Buffer) Release() {
+	b.Reset()
+
+	bufPool.Put(b)
+}
+
+// Reset resets logging buffer back to zero length.
+func (b *Buffer) Reset() {
+	b.validLen = 0
+}
+
+// AppendByte appends a single byte/character.
+func (b *Buffer) AppendByte(val byte) *Buffer {
+	if b.validLen < len(b.buf) {
+		b.buf[b.validLen] = val
+		b.validLen++
+	}
+
+	return b
+}
+
+// AppendString appends a string of characters.
+func (b *Buffer) AppendString(val string) *Buffer {
+	vl := len(val)
+
+	if b.validLen+vl > len(b.buf) {
+		vl = len(b.buf) - b.validLen
+	}
+
+	if vl > 0 {
+		copy(b.buf[b.validLen:b.validLen+vl], val)
+		b.validLen += vl
+	}
+
+	return b
+}
+
+// AppendTime appends a time representation.
+func (b *Buffer) AppendTime(val time.Time, layout string) *Buffer {
+	var buf [64]byte
+
+	return b.AppendBytes(val.AppendFormat(buf[:0], layout))
+}
+
+// AppendBytes appends a slice of bytes.
+func (b *Buffer) AppendBytes(val []byte) *Buffer {
+	vl := len(val)
+
+	if b.validLen+vl > len(b.buf) {
+		vl = len(b.buf) - b.validLen
+	}
+
+	if vl > 0 {
+		copy(b.buf[b.validLen:b.validLen+vl], val)
+		b.validLen += vl
+	}
+
+	return b
+}
+
+// AppendBoolean appends boolean string ("true" or "false").
+func (b *Buffer) AppendBoolean(val bool) *Buffer {
+	if val {
+		return b.AppendString("true")
+	}
+
+	return b.AppendString("false")
+}
+
+// AppendInt32 appends int32 value formatted as a decimal string.
+func (b *Buffer) AppendInt32(val int32) *Buffer {
+	return b.AppendInt(int64(val), 10) //nolint:gomnd
+}
+
+// AppendInt64 appends int64 value formatted as a decimal string.
+func (b *Buffer) AppendInt64(val int64) *Buffer {
+	return b.AppendInt(val, 10) //nolint:gomnd
+}
+
+// AppendInt appends integer value formatted as a string in a given base.
+func (b *Buffer) AppendInt(val int64, base int) *Buffer {
+	var buf [64]byte
+
+	return b.AppendBytes(strconv.AppendInt(buf[:0], val, base))
+}
+
+// AppendUint32 appends uint32 value formatted as a decimal string.
+func (b *Buffer) AppendUint32(val uint32) *Buffer {
+	return b.AppendUint(uint64(val), 10) //nolint:gomnd
+}
+
+// AppendUint64 appends uint64 value formatted as a decimal string.
+func (b *Buffer) AppendUint64(val uint64) *Buffer {
+	return b.AppendUint(val, 10) //nolint:gomnd
+}
+
+// AppendUint appends unsigned integer value formatted as a string in a given base.
+func (b *Buffer) AppendUint(val uint64, base int) *Buffer {
+	var buf [64]byte
+
+	return b.AppendBytes(strconv.AppendUint(buf[:0], val, base))
+}
+
+// String returns a string value of a buffer. The value is valud as long as
+// string remains allocated and no Append*() methods have been called.
+func (b *Buffer) String() (s string) {
+	if b.validLen == 0 {
+		return ""
+	}
+
+	// *reflect.StringHeader can't be constructed, so we refer to output variable here
+	shdr := (*reflect.StringHeader)(unsafe.Pointer(&s)) //nolint:gosec
+	shdr.Data = uintptr(unsafe.Pointer(&b.buf))         //nolint:gosec
+	shdr.Len = b.validLen
+
+	return
+}

repo/logging/logging_buf_test.go

@@ -0,0 +1,77 @@
+package logging_test
+
+import (
+	"strings"
+	"testing"
+	"time"
+
+	"github.com/stretchr/testify/require"
+
+	"github.com/kopia/kopia/repo/logging"
+)
+
+func TestLoggingBuffer_ReusesMemory(t *testing.T) {
+	b := logging.GetBuffer()
+	defer b.Release()
+
+	b.AppendString("xx")
+
+	s := b.String()
+	require.Equal(t, "xx", s)
+
+	// ensure we're reusing memory
+	b.Reset()
+	b.AppendString("yy")
+
+	require.Equal(t, "yy", s)
+}
+
+func TestLoggingBuffer_Overflow(t *testing.T) {
+	b := logging.GetBuffer()
+	defer b.Release()
+
+	filler := strings.Repeat("x", 1020)
+	b.AppendString(filler)
+	b.AppendString("foobarbaz")
+
+	// only room for 4 more characters
+	require.Equal(t, filler+"foob", b.String())
+
+	b.Reset()
+
+	b.AppendString(filler)
+	b.AppendBytes([]byte{65, 66, 67, 68, 69})
+
+	// only room for 4 more characters
+	require.Equal(t, filler+"ABCD", b.String())
+}
+
+func TestLoggingBuffer_Append(t *testing.T) {
+	b := logging.GetBuffer()
+	defer b.Release()
+
+	require.Equal(t, "", b.String())
+
+	require.Equal(t,
+		"xx ABC D -42 -23 true 42 false 23 2000-01-02T03:04:05Z",
+		b.AppendString("xx").
+			AppendString(" ").
+			AppendBytes([]byte{65, 66, 67}).
+			AppendString(" ").
+			AppendByte('D').
+			AppendString(" ").
+			AppendInt32(-42).
+			AppendString(" ").
+			AppendInt64(-23).
+			AppendString(" ").
+			AppendBoolean(true).
+			AppendString(" ").
+			AppendUint32(42).
+			AppendString(" ").
+			AppendBoolean(false).
+			AppendString(" ").
+			AppendUint64(23).
+			AppendString(" ").
+			AppendTime(time.Date(2000, 1, 2, 3, 4, 5, 6, time.UTC), time.RFC3339).
+			String())
+}