github.com/zuoyebang/bitalostable@v1.0.1-0.20240229032404-e3b99a834294/event_listener_test.go (about)

     1  // Copyright 2018 The LevelDB-Go and Pebble and Bitalostored Authors. All rights reserved. Use
     2  // of this source code is governed by a BSD-style license that can be found in
     3  // the LICENSE file.
     4  
     5  package bitalostable
     6  
     7  import (
     8  	"bytes"
     9  	"fmt"
    10  	"io"
    11  	"os"
    12  	"reflect"
    13  	"runtime"
    14  	"strings"
    15  	"sync"
    16  	"testing"
    17  	"time"
    18  
    19  	"github.com/cockroachdb/errors"
    20  	"github.com/cockroachdb/redact"
    21  	"github.com/stretchr/testify/require"
    22  	"github.com/zuoyebang/bitalostable/internal/base"
    23  	"github.com/zuoyebang/bitalostable/internal/datadriven"
    24  	"github.com/zuoyebang/bitalostable/sstable"
    25  	"github.com/zuoyebang/bitalostable/vfs"
    26  )
    27  
    28  type syncedBuffer struct {
    29  	mu  sync.Mutex
    30  	buf bytes.Buffer
    31  }
    32  
    33  func (b *syncedBuffer) Reset() {
    34  	b.mu.Lock()
    35  	defer b.mu.Unlock()
    36  	b.buf.Reset()
    37  }
    38  
    39  func (b *syncedBuffer) Write(p []byte) (n int, err error) {
    40  	b.mu.Lock()
    41  	defer b.mu.Unlock()
    42  	return b.buf.Write(p)
    43  }
    44  
    45  func (b *syncedBuffer) Cost(args ...interface{}) func() {
    46  	begin := time.Now()
    47  	return func() {
    48  		s := fmt.Sprint(args...) + base.FmtDuration(time.Now().Sub(begin))
    49  		b.mu.Lock()
    50  		defer b.mu.Unlock()
    51  		b.buf.Write([]byte(s))
    52  		if n := len(s); n == 0 || s[n-1] != '\n' {
    53  			b.buf.Write([]byte("\n"))
    54  		}
    55  	}
    56  }
    57  
    58  func (b *syncedBuffer) Info(args ...interface{}) {
    59  	s := fmt.Sprint(args...)
    60  	b.mu.Lock()
    61  	defer b.mu.Unlock()
    62  	b.buf.Write([]byte(s))
    63  	if n := len(s); n == 0 || s[n-1] != '\n' {
    64  		b.buf.Write([]byte("\n"))
    65  	}
    66  }
    67  
    68  func (b *syncedBuffer) Warn(args ...interface{}) {
    69  	s := fmt.Sprint(args...)
    70  	b.mu.Lock()
    71  	defer b.mu.Unlock()
    72  	b.buf.Write([]byte(s))
    73  	if n := len(s); n == 0 || s[n-1] != '\n' {
    74  		b.buf.Write([]byte("\n"))
    75  	}
    76  }
    77  
    78  func (b *syncedBuffer) Warnf(format string, args ...interface{}) {
    79  	s := fmt.Sprintf(format, args...)
    80  	b.mu.Lock()
    81  	defer b.mu.Unlock()
    82  	b.buf.Write([]byte(s))
    83  	if n := len(s); n == 0 || s[n-1] != '\n' {
    84  		b.buf.Write([]byte("\n"))
    85  	}
    86  }
    87  
    88  func (b *syncedBuffer) Error(args ...interface{}) {
    89  	s := fmt.Sprint(args...)
    90  	b.mu.Lock()
    91  	defer b.mu.Unlock()
    92  	b.buf.Write([]byte(s))
    93  	if n := len(s); n == 0 || s[n-1] != '\n' {
    94  		b.buf.Write([]byte("\n"))
    95  	}
    96  }
    97  
    98  func (b *syncedBuffer) Infof(format string, args ...interface{}) {
    99  	s := fmt.Sprintf(format, args...)
   100  	b.mu.Lock()
   101  	defer b.mu.Unlock()
   102  	b.buf.Write([]byte(s))
   103  	if n := len(s); n == 0 || s[n-1] != '\n' {
   104  		b.buf.Write([]byte("\n"))
   105  	}
   106  }
   107  
   108  func (b *syncedBuffer) Errorf(format string, args ...interface{}) {
   109  	s := fmt.Sprintf(format, args...)
   110  	b.mu.Lock()
   111  	defer b.mu.Unlock()
   112  	b.buf.Write([]byte(s))
   113  	if n := len(s); n == 0 || s[n-1] != '\n' {
   114  		b.buf.Write([]byte("\n"))
   115  	}
   116  }
   117  
   118  func (b *syncedBuffer) Fatalf(format string, args ...interface{}) {
   119  	b.Infof(format, args...)
   120  	runtime.Goexit()
   121  }
   122  
   123  func (b *syncedBuffer) String() string {
   124  	b.mu.Lock()
   125  	defer b.mu.Unlock()
   126  	return b.buf.String()
   127  }
   128  
   129  type loggingFS struct {
   130  	vfs.FS
   131  	w io.Writer
   132  }
   133  
   134  func (fs loggingFS) Create(name string) (vfs.File, error) {
   135  	fmt.Fprintf(fs.w, "create: %s\n", name)
   136  	f, err := fs.FS.Create(name)
   137  	if err != nil {
   138  		return nil, err
   139  	}
   140  	return loggingFile{f, name, fs.w}, nil
   141  }
   142  
   143  func (fs loggingFS) Link(oldname, newname string) error {
   144  	fmt.Fprintf(fs.w, "link: %s -> %s\n", oldname, newname)
   145  	return fs.FS.Link(oldname, newname)
   146  }
   147  
   148  func (fs loggingFS) OpenDir(name string) (vfs.File, error) {
   149  	fmt.Fprintf(fs.w, "open-dir: %s\n", name)
   150  	f, err := fs.FS.OpenDir(name)
   151  	if err != nil {
   152  		return nil, err
   153  	}
   154  	return loggingFile{f, name, fs.w}, nil
   155  }
   156  
   157  func (fs loggingFS) Rename(oldname, newname string) error {
   158  	fmt.Fprintf(fs.w, "rename: %s -> %s\n", oldname, newname)
   159  	return fs.FS.Rename(oldname, newname)
   160  }
   161  
   162  func (fs loggingFS) ReuseForWrite(oldname, newname string) (vfs.File, error) {
   163  	fmt.Fprintf(fs.w, "reuseForWrite: %s -> %s\n", oldname, newname)
   164  	f, err := fs.FS.ReuseForWrite(oldname, newname)
   165  	if err == nil {
   166  		f = loggingFile{f, newname, fs.w}
   167  	}
   168  	return f, err
   169  }
   170  
   171  func (fs loggingFS) MkdirAll(dir string, perm os.FileMode) error {
   172  	fmt.Fprintf(fs.w, "mkdir-all: %s %#o\n", dir, perm)
   173  	return fs.FS.MkdirAll(dir, perm)
   174  }
   175  
   176  func (fs loggingFS) Lock(name string) (io.Closer, error) {
   177  	fmt.Fprintf(fs.w, "lock: %s\n", name)
   178  	return fs.FS.Lock(name)
   179  }
   180  
   181  type loggingFile struct {
   182  	vfs.File
   183  	name string
   184  	w    io.Writer
   185  }
   186  
   187  func (f loggingFile) Close() error {
   188  	fmt.Fprintf(f.w, "close: %s\n", f.name)
   189  	return f.File.Close()
   190  }
   191  
   192  func (f loggingFile) Sync() error {
   193  	fmt.Fprintf(f.w, "sync: %s\n", f.name)
   194  	return f.File.Sync()
   195  }
   196  
   197  // Verify event listener actions, as well as expected filesystem operations.
   198  func TestEventListener(t *testing.T) {
   199  	var d *DB
   200  	var buf syncedBuffer
   201  	mem := vfs.NewMem()
   202  	require.NoError(t, mem.MkdirAll("ext", 0755))
   203  
   204  	datadriven.RunTest(t, "testdata/event_listener", func(td *datadriven.TestData) string {
   205  		switch td.Cmd {
   206  		case "open":
   207  			buf.Reset()
   208  			opts := &Options{
   209  				FS:                    loggingFS{mem, &buf},
   210  				FormatMajorVersion:    FormatNewest,
   211  				EventListener:         MakeLoggingEventListener(&buf),
   212  				MaxManifestFileSize:   1,
   213  				L0CompactionThreshold: 10,
   214  				WALDir:                "wal",
   215  			}
   216  			// The table stats collector runs asynchronously and its
   217  			// timing is less predictable. It increments nextJobID, which
   218  			// can make these tests flaky. The TableStatsLoaded event is
   219  			// tested separately in TestTableStats.
   220  			opts.private.disableTableStats = true
   221  			var err error
   222  			d, err = Open("db", opts)
   223  			if err != nil {
   224  				return err.Error()
   225  			}
   226  			t := time.Now()
   227  			d.timeNow = func() time.Time {
   228  				t = t.Add(time.Second)
   229  				return t
   230  			}
   231  			return buf.String()
   232  
   233  		case "close":
   234  			buf.Reset()
   235  			if err := d.Close(); err != nil {
   236  				return err.Error()
   237  			}
   238  			return buf.String()
   239  
   240  		case "flush":
   241  			buf.Reset()
   242  			if err := d.Set([]byte("a"), nil, nil); err != nil {
   243  				return err.Error()
   244  			}
   245  			if err := d.Flush(); err != nil {
   246  				return err.Error()
   247  			}
   248  			return buf.String()
   249  
   250  		case "compact":
   251  			buf.Reset()
   252  			if err := d.Set([]byte("a"), nil, nil); err != nil {
   253  				return err.Error()
   254  			}
   255  			if err := d.Compact([]byte("a"), []byte("b"), false); err != nil {
   256  				return err.Error()
   257  			}
   258  			return buf.String()
   259  
   260  		case "checkpoint":
   261  			buf.Reset()
   262  			if err := d.Checkpoint("checkpoint"); err != nil {
   263  				return err.Error()
   264  			}
   265  			return buf.String()
   266  
   267  		case "disable-file-deletions":
   268  			buf.Reset()
   269  			d.mu.Lock()
   270  			d.disableFileDeletions()
   271  			d.mu.Unlock()
   272  			return buf.String()
   273  
   274  		case "enable-file-deletions":
   275  			buf.Reset()
   276  			func() {
   277  				defer func() {
   278  					if r := recover(); r != nil {
   279  						fmt.Fprint(&buf, r)
   280  					}
   281  				}()
   282  				d.mu.Lock()
   283  				defer d.mu.Unlock()
   284  				d.enableFileDeletions()
   285  			}()
   286  			return buf.String()
   287  
   288  		case "ingest":
   289  			buf.Reset()
   290  			f, err := mem.Create("ext/0")
   291  			if err != nil {
   292  				return err.Error()
   293  			}
   294  			w := sstable.NewWriter(f, sstable.WriterOptions{
   295  				TableFormat: d.FormatMajorVersion().MaxTableFormat(),
   296  			})
   297  			if err := w.Add(base.MakeInternalKey([]byte("a"), 0, InternalKeyKindSet), nil); err != nil {
   298  				return err.Error()
   299  			}
   300  			if err := w.Close(); err != nil {
   301  				return err.Error()
   302  			}
   303  			if err := d.Ingest([]string{"ext/0"}); err != nil {
   304  				return err.Error()
   305  			}
   306  			return buf.String()
   307  
   308  		case "metrics":
   309  			// The asynchronous loading of table stats can change metrics, so
   310  			// wait for all the tables' stats to be loaded.
   311  			d.mu.Lock()
   312  			d.waitTableStats()
   313  			d.mu.Unlock()
   314  
   315  			return d.Metrics().String()
   316  
   317  		case "sstables":
   318  			var buf bytes.Buffer
   319  			tableInfos, _ := d.SSTables()
   320  			for i, level := range tableInfos {
   321  				if len(level) == 0 {
   322  					continue
   323  				}
   324  				fmt.Fprintf(&buf, "%d:\n", i)
   325  				for _, m := range level {
   326  					fmt.Fprintf(&buf, "  %d:[%s-%s]\n",
   327  						m.FileNum, m.Smallest.UserKey, m.Largest.UserKey)
   328  				}
   329  			}
   330  			return buf.String()
   331  
   332  		default:
   333  			return fmt.Sprintf("unknown command: %s", td.Cmd)
   334  		}
   335  	})
   336  }
   337  
   338  func TestWriteStallEvents(t *testing.T) {
   339  	const flushCount = 10
   340  	const writeStallEnd = "write stall ending"
   341  
   342  	testCases := []struct {
   343  		delayFlush bool
   344  		expected   string
   345  	}{
   346  		{true, "memtable count limit reached"},
   347  		{false, "L0 file count limit exceeded"},
   348  	}
   349  
   350  	for _, c := range testCases {
   351  		t.Run("", func(t *testing.T) {
   352  			stallEnded := make(chan struct{}, 1)
   353  			createReleased := make(chan struct{}, flushCount)
   354  			var buf syncedBuffer
   355  			var delayOnce sync.Once
   356  			listener := EventListener{
   357  				TableCreated: func(info TableCreateInfo) {
   358  					if c.delayFlush == (info.Reason == "flushing") {
   359  						delayOnce.Do(func() {
   360  							<-createReleased
   361  						})
   362  					}
   363  				},
   364  				WriteStallBegin: func(info WriteStallBeginInfo) {
   365  					fmt.Fprintln(&buf, info.String())
   366  					createReleased <- struct{}{}
   367  				},
   368  				WriteStallEnd: func() {
   369  					fmt.Fprintln(&buf, writeStallEnd)
   370  					select {
   371  					case stallEnded <- struct{}{}:
   372  					default:
   373  					}
   374  				},
   375  			}
   376  			d, err := Open("db", &Options{
   377  				EventListener:               listener,
   378  				FS:                          vfs.NewMem(),
   379  				MemTableSize:                initialMemTableSize,
   380  				MemTableStopWritesThreshold: 2,
   381  				L0CompactionThreshold:       2,
   382  				L0StopWritesThreshold:       2,
   383  			})
   384  			require.NoError(t, err)
   385  			defer d.Close()
   386  
   387  			for i := 0; i < flushCount; i++ {
   388  				require.NoError(t, d.Set([]byte("a"), nil, NoSync))
   389  
   390  				ch, err := d.AsyncFlush()
   391  				require.NoError(t, err)
   392  
   393  				// If we're delaying the flush (because we're testing for memtable
   394  				// write stalls), we can't wait for the flush to finish as doing so
   395  				// would deadlock. If we're not delaying the flush (because we're
   396  				// testing for L0 write stals), we wait for the flush to finish so we
   397  				// don't create too many memtables which would trigger a memtable write
   398  				// stall.
   399  				if !c.delayFlush {
   400  					<-ch
   401  				}
   402  				if strings.Contains(buf.String(), c.expected) {
   403  					break
   404  				}
   405  			}
   406  			<-stallEnded
   407  
   408  			events := buf.String()
   409  			require.Contains(t, events, c.expected)
   410  			require.Contains(t, events, writeStallEnd)
   411  			if testing.Verbose() {
   412  				t.Logf("\n%s", events)
   413  			}
   414  		})
   415  	}
   416  }
   417  
   418  type redactLogger struct {
   419  	logger Logger
   420  }
   421  
   422  func (l redactLogger) Info(args ...interface{}) {
   423  	l.logger.Info(redact.Sprint(args...).Redact())
   424  }
   425  
   426  func (l redactLogger) Warn(args ...interface{}) {
   427  	l.logger.Warn(redact.Sprint(args...).Redact())
   428  }
   429  
   430  func (l redactLogger) Error(args ...interface{}) {
   431  	l.logger.Error(redact.Sprint(args...).Redact())
   432  }
   433  
   434  // Infof implements the Logger.Infof interface.
   435  func (l redactLogger) Infof(format string, args ...interface{}) {
   436  	l.logger.Infof("%s", redact.Sprintf(format, args...).Redact())
   437  }
   438  
   439  func (l redactLogger) Warnf(format string, args ...interface{}) {
   440  	l.logger.Warnf("%s", redact.Sprintf(format, args...).Redact())
   441  }
   442  
   443  func (l redactLogger) Errorf(format string, args ...interface{}) {
   444  	l.logger.Errorf("%s", redact.Sprintf(format, args...).Redact())
   445  }
   446  
   447  // Fatalf implements the Logger.Fatalf interface.
   448  func (l redactLogger) Fatalf(format string, args ...interface{}) {
   449  	l.logger.Fatalf("%s", redact.Sprintf(format, args...).Redact())
   450  }
   451  
   452  func (l redactLogger) Cost(arg ...interface{}) func() {
   453  	return l.logger.Cost(arg)
   454  }
   455  
   456  func TestEventListenerRedact(t *testing.T) {
   457  	// The vast majority of event listener fields logged are safe and do not
   458  	// need to be redacted. Verify that the rare, unsafe error does appear in
   459  	// the log redacted.
   460  	var log syncedBuffer
   461  	l := MakeLoggingEventListener(redactLogger{logger: &log})
   462  	l.WALDeleted(WALDeleteInfo{
   463  		JobID:   5,
   464  		FileNum: FileNum(20),
   465  		Err:     errors.Errorf("unredacted error: %s", "unredacted string"),
   466  	})
   467  	require.Equal(t, "[JOB 5] WAL delete error: unredacted error: ‹×›\n", log.String())
   468  }
   469  
   470  func TestEventListenerEnsureDefaultsBackgroundError(t *testing.T) {
   471  	e := EventListener{}
   472  	e.EnsureDefaults(nil)
   473  	e.BackgroundError(errors.New("an example error"))
   474  }
   475  
   476  func TestEventListenerEnsureDefaultsSetsAllCallbacks(t *testing.T) {
   477  	e := EventListener{}
   478  	e.EnsureDefaults(nil)
   479  	testAllCallbacksSetInEventListener(t, e)
   480  }
   481  
   482  func TestMakeLoggingEventListenerSetsAllCallbacks(t *testing.T) {
   483  	e := MakeLoggingEventListener(nil)
   484  	testAllCallbacksSetInEventListener(t, e)
   485  }
   486  
   487  func TestTeeEventListenerSetsAllCallbacks(t *testing.T) {
   488  	e := TeeEventListener(EventListener{}, EventListener{})
   489  	testAllCallbacksSetInEventListener(t, e)
   490  }
   491  
   492  func testAllCallbacksSetInEventListener(t *testing.T, e EventListener) {
   493  	t.Helper()
   494  	v := reflect.ValueOf(e)
   495  	for i := 0; i < v.NumField(); i++ {
   496  		fType := v.Type().Field(i)
   497  		fVal := v.Field(i)
   498  		require.Equal(t, reflect.Func, fType.Type.Kind(), "unexpected non-func field: %s", fType.Name)
   499  		require.False(t, fVal.IsNil(), "unexpected nil field: %s", fType.Name)
   500  	}
   501  }