diff --git a/repo/content/content_manager.go b/repo/content/content_manager.go index b553ec0c0..5721c148b 100644 --- a/repo/content/content_manager.go +++ b/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) } diff --git a/repo/content/content_manager_lock_free.go b/repo/content/content_manager_lock_free.go index d3ff64659..0626bb54c 100644 --- a/repo/content/content_manager_lock_free.go +++ b/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) } diff --git a/repo/content/index/id.go b/repo/content/index/id.go index 54d294cae..8a80eb365 100644 --- a/repo/content/index/id.go +++ b/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]) diff --git a/repo/content/index/id_test.go b/repo/content/index/id_test.go index a7406dc5d..ee55ba795 100644 --- a/repo/content/index/id_test.go +++ b/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) } diff --git a/repo/logging/logging_buf.go b/repo/logging/logging_buf.go new file mode 100644 index 000000000..4be72c507 --- /dev/null +++ b/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 +} diff --git a/repo/logging/logging_buf_test.go b/repo/logging/logging_buf_test.go new file mode 100644 index 000000000..147a6b360 --- /dev/null +++ b/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()) +}