github.com/cockroachdb/pebble@v1.1.1-0.20240513155919-3622ade60459/event_listener_test.go (about) 1 // Copyright 2018 The LevelDB-Go and Pebble 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 pebble 6 7 import ( 8 "bytes" 9 "fmt" 10 "reflect" 11 "strings" 12 "sync" 13 "testing" 14 "time" 15 16 "github.com/cockroachdb/datadriven" 17 "github.com/cockroachdb/errors" 18 "github.com/cockroachdb/pebble/internal/base" 19 "github.com/cockroachdb/pebble/objstorage/objstorageprovider" 20 "github.com/cockroachdb/pebble/sstable" 21 "github.com/cockroachdb/pebble/vfs" 22 "github.com/cockroachdb/redact" 23 "github.com/stretchr/testify/require" 24 ) 25 26 // Verify event listener actions, as well as expected filesystem operations. 27 func TestEventListener(t *testing.T) { 28 var d *DB 29 var memLog base.InMemLogger 30 mem := vfs.NewMem() 31 require.NoError(t, mem.MkdirAll("ext", 0755)) 32 33 datadriven.RunTest(t, "testdata/event_listener", func(t *testing.T, td *datadriven.TestData) string { 34 switch td.Cmd { 35 case "open": 36 memLog.Reset() 37 lel := MakeLoggingEventListener(&memLog) 38 flushBegin, flushEnd := lel.FlushBegin, lel.FlushEnd 39 lel.FlushBegin = func(info FlushInfo) { 40 // Make deterministic. 41 info.InputBytes = 100 42 flushBegin(info) 43 } 44 lel.FlushEnd = func(info FlushInfo) { 45 // Make deterministic. 46 info.InputBytes = 100 47 flushEnd(info) 48 } 49 opts := &Options{ 50 FS: vfs.WithLogging(mem, memLog.Infof), 51 FormatMajorVersion: internalFormatNewest, 52 EventListener: &lel, 53 MaxManifestFileSize: 1, 54 L0CompactionThreshold: 10, 55 WALDir: "wal", 56 } 57 // The table stats collector runs asynchronously and its 58 // timing is less predictable. It increments nextJobID, which 59 // can make these tests flaky. The TableStatsLoaded event is 60 // tested separately in TestTableStats. 61 opts.private.disableTableStats = true 62 var err error 63 d, err = Open("db", opts) 64 if err != nil { 65 return err.Error() 66 } 67 t := time.Now() 68 d.timeNow = func() time.Time { 69 t = t.Add(time.Second) 70 return t 71 } 72 d.opts.private.testingAlwaysWaitForCleanup = true 73 return memLog.String() 74 75 case "close": 76 memLog.Reset() 77 if err := d.Close(); err != nil { 78 return err.Error() 79 } 80 return memLog.String() 81 82 case "flush": 83 memLog.Reset() 84 if err := d.Set([]byte("a"), nil, nil); err != nil { 85 return err.Error() 86 } 87 if err := d.Flush(); err != nil { 88 return err.Error() 89 } 90 return memLog.String() 91 92 case "compact": 93 memLog.Reset() 94 if err := d.Set([]byte("a"), nil, nil); err != nil { 95 return err.Error() 96 } 97 if err := d.Compact([]byte("a"), []byte("b"), false); err != nil { 98 return err.Error() 99 } 100 return memLog.String() 101 102 case "checkpoint": 103 memLog.Reset() 104 if err := d.Checkpoint("checkpoint"); err != nil { 105 return err.Error() 106 } 107 return memLog.String() 108 109 case "disable-file-deletions": 110 memLog.Reset() 111 d.mu.Lock() 112 d.disableFileDeletions() 113 d.mu.Unlock() 114 return memLog.String() 115 116 case "enable-file-deletions": 117 memLog.Reset() 118 func() { 119 defer func() { 120 if r := recover(); r != nil { 121 memLog.Infof("%v", r) 122 } 123 }() 124 d.mu.Lock() 125 defer d.mu.Unlock() 126 d.enableFileDeletions() 127 }() 128 d.TestOnlyWaitForCleaning() 129 return memLog.String() 130 131 case "ingest": 132 memLog.Reset() 133 f, err := mem.Create("ext/0") 134 if err != nil { 135 return err.Error() 136 } 137 w := sstable.NewWriter(objstorageprovider.NewFileWritable(f), sstable.WriterOptions{ 138 TableFormat: d.FormatMajorVersion().MaxTableFormat(), 139 }) 140 if err := w.Add(base.MakeInternalKey([]byte("a"), 0, InternalKeyKindSet), nil); err != nil { 141 return err.Error() 142 } 143 if err := w.Close(); err != nil { 144 return err.Error() 145 } 146 if err := d.Ingest([]string{"ext/0"}); err != nil { 147 return err.Error() 148 } 149 return memLog.String() 150 151 case "ingest-flushable": 152 memLog.Reset() 153 154 // Prevent flushes during this test to ensure determinism. 155 d.mu.Lock() 156 d.mu.compact.flushing = true 157 d.mu.Unlock() 158 159 b := d.NewBatch() 160 if err := b.Set([]byte("a"), nil, nil); err != nil { 161 return err.Error() 162 } 163 if err := d.Apply(b, nil); err != nil { 164 return err.Error() 165 } 166 writeTable := func(name string, key byte) error { 167 f, err := mem.Create(name) 168 if err != nil { 169 return err 170 } 171 w := sstable.NewWriter(objstorageprovider.NewFileWritable(f), sstable.WriterOptions{ 172 TableFormat: d.FormatMajorVersion().MaxTableFormat(), 173 }) 174 if err := w.Add(base.MakeInternalKey([]byte{key}, 0, InternalKeyKindSet), nil); err != nil { 175 return err 176 } 177 if err := w.Close(); err != nil { 178 return err 179 } 180 return nil 181 } 182 tableA, tableB := "ext/a", "ext/b" 183 if err := writeTable(tableA, 'a'); err != nil { 184 return err.Error() 185 } 186 if err := writeTable(tableB, 'b'); err != nil { 187 return err.Error() 188 } 189 if err := d.Ingest([]string{tableA, tableB}); err != nil { 190 return err.Error() 191 } 192 193 // Re-enable flushes, to allow the subsequent flush to proceed. 194 d.mu.Lock() 195 d.mu.compact.flushing = false 196 d.mu.Unlock() 197 if err := d.Flush(); err != nil { 198 return err.Error() 199 } 200 return memLog.String() 201 202 case "metrics": 203 // The asynchronous loading of table stats can change metrics, so 204 // wait for all the tables' stats to be loaded. 205 d.mu.Lock() 206 d.waitTableStats() 207 d.mu.Unlock() 208 209 return d.Metrics().StringForTests() 210 211 case "sstables": 212 var buf bytes.Buffer 213 tableInfos, _ := d.SSTables() 214 for i, level := range tableInfos { 215 if len(level) == 0 { 216 continue 217 } 218 fmt.Fprintf(&buf, "%d:\n", i) 219 for _, m := range level { 220 fmt.Fprintf(&buf, " %d:[%s-%s]\n", 221 m.FileNum, m.Smallest.UserKey, m.Largest.UserKey) 222 } 223 } 224 return buf.String() 225 226 default: 227 return fmt.Sprintf("unknown command: %s", td.Cmd) 228 } 229 }) 230 } 231 232 func TestWriteStallEvents(t *testing.T) { 233 const flushCount = 10 234 const writeStallEnd = "write stall ending" 235 236 testCases := []struct { 237 delayFlush bool 238 expected string 239 }{ 240 {true, "memtable count limit reached"}, 241 {false, "L0 file count limit exceeded"}, 242 } 243 244 for _, c := range testCases { 245 t.Run("", func(t *testing.T) { 246 stallEnded := make(chan struct{}, 1) 247 createReleased := make(chan struct{}, flushCount) 248 var log base.InMemLogger 249 var delayOnce sync.Once 250 listener := &EventListener{ 251 TableCreated: func(info TableCreateInfo) { 252 if c.delayFlush == (info.Reason == "flushing") { 253 delayOnce.Do(func() { 254 <-createReleased 255 }) 256 } 257 }, 258 WriteStallBegin: func(info WriteStallBeginInfo) { 259 log.Infof("%s", info.String()) 260 createReleased <- struct{}{} 261 }, 262 WriteStallEnd: func() { 263 log.Infof("%s", writeStallEnd) 264 select { 265 case stallEnded <- struct{}{}: 266 default: 267 } 268 }, 269 } 270 d, err := Open("db", &Options{ 271 EventListener: listener, 272 FS: vfs.NewMem(), 273 MemTableSize: initialMemTableSize, 274 MemTableStopWritesThreshold: 2, 275 L0CompactionThreshold: 2, 276 L0StopWritesThreshold: 2, 277 }) 278 require.NoError(t, err) 279 defer d.Close() 280 281 for i := 0; i < flushCount; i++ { 282 require.NoError(t, d.Set([]byte("a"), nil, NoSync)) 283 284 ch, err := d.AsyncFlush() 285 require.NoError(t, err) 286 287 // If we're delaying the flush (because we're testing for memtable 288 // write stalls), we can't wait for the flush to finish as doing so 289 // would deadlock. If we're not delaying the flush (because we're 290 // testing for L0 write stals), we wait for the flush to finish so we 291 // don't create too many memtables which would trigger a memtable write 292 // stall. 293 if !c.delayFlush { 294 <-ch 295 } 296 if strings.Contains(log.String(), c.expected) { 297 break 298 } 299 } 300 <-stallEnded 301 302 events := log.String() 303 require.Contains(t, events, c.expected) 304 require.Contains(t, events, writeStallEnd) 305 if testing.Verbose() { 306 t.Logf("\n%s", events) 307 } 308 }) 309 } 310 } 311 312 type redactLogger struct { 313 logger Logger 314 } 315 316 // Infof implements the Logger.Infof interface. 317 func (l redactLogger) Infof(format string, args ...interface{}) { 318 l.logger.Infof("%s", redact.Sprintf(format, args...).Redact()) 319 } 320 321 // Fatalf implements the Logger.Fatalf interface. 322 func (l redactLogger) Fatalf(format string, args ...interface{}) { 323 l.logger.Fatalf("%s", redact.Sprintf(format, args...).Redact()) 324 } 325 326 func TestEventListenerRedact(t *testing.T) { 327 // The vast majority of event listener fields logged are safe and do not 328 // need to be redacted. Verify that the rare, unsafe error does appear in 329 // the log redacted. 330 var log base.InMemLogger 331 l := MakeLoggingEventListener(redactLogger{logger: &log}) 332 l.WALDeleted(WALDeleteInfo{ 333 JobID: 5, 334 FileNum: FileNum(20), 335 Err: errors.Errorf("unredacted error: %s", "unredacted string"), 336 }) 337 require.Equal(t, "[JOB 5] WAL delete error: unredacted error: ‹×›\n", log.String()) 338 } 339 340 func TestEventListenerEnsureDefaultsBackgroundError(t *testing.T) { 341 e := EventListener{} 342 e.EnsureDefaults(nil) 343 e.BackgroundError(errors.New("an example error")) 344 } 345 346 func TestEventListenerEnsureDefaultsSetsAllCallbacks(t *testing.T) { 347 e := EventListener{} 348 e.EnsureDefaults(nil) 349 testAllCallbacksSetInEventListener(t, e) 350 } 351 352 func TestMakeLoggingEventListenerSetsAllCallbacks(t *testing.T) { 353 e := MakeLoggingEventListener(nil) 354 testAllCallbacksSetInEventListener(t, e) 355 } 356 357 func TestTeeEventListenerSetsAllCallbacks(t *testing.T) { 358 e := TeeEventListener(EventListener{}, EventListener{}) 359 testAllCallbacksSetInEventListener(t, e) 360 } 361 362 func testAllCallbacksSetInEventListener(t *testing.T, e EventListener) { 363 t.Helper() 364 v := reflect.ValueOf(e) 365 for i := 0; i < v.NumField(); i++ { 366 fType := v.Type().Field(i) 367 fVal := v.Field(i) 368 require.Equal(t, reflect.Func, fType.Type.Kind(), "unexpected non-func field: %s", fType.Name) 369 require.False(t, fVal.IsNil(), "unexpected nil field: %s", fType.Name) 370 } 371 }