Add buffered write syncer

zapcore/buffered_write_syncer.go

@@ -0,0 +1,130 @@
+// Copyright (c) 2021 Uber Technologies, Inc.
+//
+// Permission is hereby granted, free of charge, to any person obtaining a copy
+// of this software and associated documentation files (the "Software"), to deal
+// in the Software without restriction, including without limitation the rights
+// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+// copies of the Software, and to permit persons to whom the Software is
+// furnished to do so, subject to the following conditions:
+//
+// The above copyright notice and this permission notice shall be included in
+// all copies or substantial portions of the Software.
+//
+// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+// THE SOFTWARE.
+
+package zapcore
+
+import (
+	"bufio"
+	"sync"
+	"time"
+)
+
+// A BufferedWriteSyncer is a WriteSyncer that can also flush any buffered data
+// with the ability to change the buffer size, flush interval and Clock.
+// The default values are; Size 256kb, FlushInterval 30s.
+type BufferedWriteSyncer struct {
+	WriteSyncer
+
+	Size          int
+	FlushInterval time.Duration
+	Clock         Clock
+
+	// unexported fields for state
+	mu          sync.Mutex
+	writer      *bufio.Writer
+	ticker      *time.Ticker
+	stop        chan struct{}
+	initialized bool
+}
+
+const (
+	// _defaultBufferSize specifies the default size used by Buffer.
+	_defaultBufferSize = 256 * 1024 // 256 kB
+
+	// _defaultFlushInterval specifies the default flush interval for
+	// Buffer.
+	_defaultFlushInterval = 30 * time.Second
+)
+
+func (s *BufferedWriteSyncer) loadConfig() {
+	size := s.Size
+	if size == 0 {
+		size = _defaultBufferSize
+	}
+
+	flushInterval := s.FlushInterval
+	if flushInterval == 0 {
+		flushInterval = _defaultFlushInterval
+	}
+
+	if s.Clock == nil {
+		s.Clock = DefaultClock
+	}
+	s.ticker = s.Clock.NewTicker(flushInterval)
+
+	s.writer = bufio.NewWriterSize(s.WriteSyncer, size)
+	s.stop = make(chan struct{})
+	s.initialized = true
+	go s.flushLoop()
+}
+
+// Write writes log data into buffer syncer directly, multiple Write calls will be batched,
+// and log data will be flushed to disk when the buffer is full or periodically.
+func (s *BufferedWriteSyncer) Write(bs []byte) (int, error) {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+
+	if !s.initialized {
+		s.loadConfig()
+	}
+
+	// To avoid partial writes from being flushed, we manually flush the existing buffer if:
+	// * The current write doesn't fit into the buffer fully, and
+	// * The buffer is not empty (since bufio will not split large writes when the buffer is empty)
+	if len(bs) > s.writer.Available() && s.writer.Buffered() > 0 {
+		if err := s.writer.Flush(); err != nil {
+			return 0, err
+		}
+	}
+
+	return s.writer.Write(bs)
+}
+
+// Sync flushes buffered log data into disk directly.
+func (s *BufferedWriteSyncer) Sync() error {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+
+	return s.writer.Flush()
+}
+
+// flushLoop flushes the buffer at the configured interval until Close is
+// called.
+func (s *BufferedWriteSyncer) flushLoop() {
+	for {
+		select {
+		case <-s.ticker.C:
+			// we just simply ignore error here
+			// because the underlying bufio writer stores any errors
+			// and we return any error from Sync() as part of the close
+			_ = s.Sync()
+		case <-s.stop:
+			return
+		}
+	}
+}
+
+// Close closes the buffer, cleans up background goroutines, and flushes
+// remaining, unwritten data. This will not close the underlying WriteSyncer.
+func (s *BufferedWriteSyncer) Close() error {
+	s.ticker.Stop()
+	close(s.stop)
+	return s.Sync()
+}

zapcore/buffered_write_syncer_bench_test.go

@@ -0,0 +1,49 @@
+// Copyright (c) 2021 Uber Technologies, Inc.
+//
+// Permission is hereby granted, free of charge, to any person obtaining a copy
+// of this software and associated documentation files (the "Software"), to deal
+// in the Software without restriction, including without limitation the rights
+// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+// copies of the Software, and to permit persons to whom the Software is
+// furnished to do so, subject to the following conditions:
+//
+// The above copyright notice and this permission notice shall be included in
+// all copies or substantial portions of the Software.
+//
+// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+// THE SOFTWARE.
+
+package zapcore
+
+import (
+	"io/ioutil"
+	"os"
+	"testing"
+
+	"github.com/stretchr/testify/require"
+)
+
+func BenchmarkBufferedWriteSyncer(b *testing.B) {
+	b.Run("write file with buffer", func(b *testing.B) {
+		file, err := ioutil.TempFile("", "log")
+		require.NoError(b, err)
+		defer file.Close()
+		defer os.Remove(file.Name())
+
+		w := &BufferedWriteSyncer{
+			WriteSyncer: AddSync(file),
+		}
+		defer w.Close()
+		b.ResetTimer()
+		b.RunParallel(func(pb *testing.PB) {
+			for pb.Next() {
+				w.Write([]byte("foobarbazbabble"))
+			}
+		})
+	})
+}

zapcore/buffered_write_syncer_test.go

@@ -0,0 +1,106 @@
+// Copyright (c) 2021 Uber Technologies, Inc.
+//
+// Permission is hereby granted, free of charge, to any person obtaining a copy
+// of this software and associated documentation files (the "Software"), to deal
+// in the Software without restriction, including without limitation the rights
+// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+// copies of the Software, and to permit persons to whom the Software is
+// furnished to do so, subject to the following conditions:
+//
+// The above copyright notice and this permission notice shall be included in
+// all copies or substantial portions of the Software.
+//
+// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+// THE SOFTWARE.
+
+package zapcore
+
+import (
+	"bytes"
+	"testing"
+	"time"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"go.uber.org/zap/internal/ztest"
+)
+
+func TestBufferWriter(t *testing.T) {
+	// If we pass a plain io.Writer, make sure that we still get a WriteSyncer
+	// with a no-op Sync.
+	t.Run("sync", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		ws := &BufferedWriteSyncer{WriteSyncer: AddSync(buf)}
+
+		requireWriteWorks(t, ws)
+		assert.Empty(t, buf.String(), "Unexpected log calling a no-op Write method.")
+		assert.NoError(t, ws.Sync(), "Unexpected error calling a no-op Sync method.")
+		assert.Equal(t, "foo", buf.String(), "Unexpected log string")
+		assert.NoError(t, ws.Close())
+	})
+
+	t.Run("close", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		ws := &BufferedWriteSyncer{WriteSyncer: AddSync(buf)}
+		requireWriteWorks(t, ws)
+		assert.Empty(t, buf.String(), "Unexpected log calling a no-op Write method.")
+		assert.NoError(t, ws.Close())
+		assert.Equal(t, "foo", buf.String(), "Unexpected log string")
+	})
+
+	t.Run("wrap twice", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		bufsync := &BufferedWriteSyncer{WriteSyncer: AddSync(buf)}
+		ws := &BufferedWriteSyncer{WriteSyncer: bufsync}
+		requireWriteWorks(t, ws)
+		assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.")
+		assert.NoError(t, ws.Close())
+		assert.NoError(t, bufsync.Close())
+		assert.Equal(t, "foo", buf.String(), "Unexpected log string")
+	})
+
+	t.Run("small buffer", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		ws := &BufferedWriteSyncer{WriteSyncer: AddSync(buf), Size: 5}
+
+		requireWriteWorks(t, ws)
+		assert.Equal(t, "", buf.String(), "Unexpected log calling a no-op Write method.")
+		requireWriteWorks(t, ws)
+		assert.Equal(t, "foo", buf.String(), "Unexpected log string")
+		assert.NoError(t, ws.Close())
+	})
+
+	t.Run("flush error", func(t *testing.T) {
+		ws := &BufferedWriteSyncer{WriteSyncer: &ztest.FailWriter{}, Size: 4}
+		n, err := ws.Write([]byte("foo"))
+		require.NoError(t, err, "Unexpected error writing to WriteSyncer.")
+		require.Equal(t, 3, n, "Wrote an unexpected number of bytes.")
+		ws.Write([]byte("foo"))
+		assert.Error(t, ws.Close(), "Expected close to fail.")
+	})
+
+	t.Run("flush timer", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		clock := newControlledClock()
+		ws := &BufferedWriteSyncer{
+			WriteSyncer:   AddSync(buf),
+			Size:          6,
+			FlushInterval: time.Microsecond,
+			Clock:         clock,
+		}
+		requireWriteWorks(t, ws)
+		clock.Add(10 * time.Millisecond)
+		assert.Equal(t, "foo", buf.String(), "Unexpected log string")
+
+		// flush twice to validate loop logic
+		requireWriteWorks(t, ws)
+		clock.Add(10 * time.Millisecond)
+		assert.Equal(t, "foofoo", buf.String(), "Unexpected log string")
+		assert.NoError(t, ws.Close())
+	})
+}

zapcore/write_syncer_bench_test.go

@@ -21,13 +21,16 @@
 package zapcore
 
 import (
+	"io/ioutil"
+	"os"
 	"testing"
 
+	"github.com/stretchr/testify/assert"
 	"go.uber.org/zap/internal/ztest"
 )
 
 func BenchmarkMultiWriteSyncer(b *testing.B) {
-	b.Run("2", func(b *testing.B) {
+	b.Run("2 discarder", func(b *testing.B) {
 		w := NewMultiWriteSyncer(
 			&ztest.Discarder{},
 			&ztest.Discarder{},
@@ -39,7 +42,7 @@ func BenchmarkMultiWriteSyncer(b *testing.B) {
 			}
 		})
 	})
-	b.Run("4", func(b *testing.B) {
+	b.Run("4 discarder", func(b *testing.B) {
 		w := NewMultiWriteSyncer(
 			&ztest.Discarder{},
 			&ztest.Discarder{},
@@ -53,4 +56,38 @@ func BenchmarkMultiWriteSyncer(b *testing.B) {
 			}
 		})
 	})
+	b.Run("4 discarder with buffer", func(b *testing.B) {
+		w := &BufferedWriteSyncer{
+			WriteSyncer: NewMultiWriteSyncer(
+				&ztest.Discarder{},
+				&ztest.Discarder{},
+				&ztest.Discarder{},
+				&ztest.Discarder{},
+			),
+		}
+		defer w.Close()
+		b.ResetTimer()
+		b.RunParallel(func(pb *testing.PB) {
+			for pb.Next() {
+				w.Write([]byte("foobarbazbabble"))
+			}
+		})
+	})
+}
+
+func BenchmarkWriteSyncer(b *testing.B) {
+	b.Run("write file with no buffer", func(b *testing.B) {
+		file, err := ioutil.TempFile("", "log")
+		assert.NoError(b, err)
+		defer file.Close()
+		defer os.Remove(file.Name())
+
+		w := AddSync(file)
+		b.ResetTimer()
+		b.RunParallel(func(pb *testing.PB) {
+			for pb.Next() {
+				w.Write([]byte("foobarbazbabble"))
+			}
+		})
+	})
 }

zapcore/write_syncer_test.go

@@ -23,9 +23,8 @@ package zapcore
 import (
 	"bytes"
 	"errors"
-	"testing"
-
 	"io"
+	"testing"
 
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"