Files
seaweedfs/weed/util/log_buffer/log_buffer_queryability_test.go
T
Chris Lu e873e671b6 filer: share one log-buffer window snapshot across all subscriber reads (#10267)
* log_buffer: share one window snapshot across all subscriber reads

Every in-memory read handed each subscriber a private pooled copy of the
window it wanted, so N subscribers reading the same data cost N copies of
up to 8MB each -- and slow consumers (grpc send backpressure) held those
copies live for their whole iteration. With hundreds of mount subscribers
that multiplied into gigabytes of live heap on the filer.

Share the bytes instead of copying per reader:

- Sealed windows get a lazily created GC-owned snapshot, made once by the
  first reader and handed out zero-copy to the rest. The snapshot travels
  with its window when SealBuffer shifts slots, so recycling the sealed
  array never invalidates it.
- The current window keeps a shared snapshot of its append-only prefix
  buf[:pos], extended on demand; each byte is copied once per window
  (writer-rate-bound) instead of once per reader. At seal a fully
  extended prefix becomes the sealed window's snapshot.

ReadFromBuffer now reports whether the returned buffer is a pooled copy
(flush path) or a shared view that must not be released; the read loops
only recycle pooled buffers.

With 200 subscribers consuming at grpc pace over sealed and current
windows, peak live heap drops from 5.2GB to 178MB.

* log_buffer: clear released read buffer so a panic cannot double-free it

The read loops release the previous iteration's pooled buffer and then
call ReadFromBuffer. If that call panicked before reassigning bytesBuf,
the deferred cleanup would put the same buffer into the pool a second
time, letting two future readers share one backing array. Nil the
pointer at the release site so the defer sees nothing to free.
2026-07-08 01:50:51 -07:00

304 lines
10 KiB
Go

package log_buffer
import (
"bytes"
"testing"
"time"
"github.com/seaweedfs/seaweedfs/weed/pb/filer_pb"
"github.com/seaweedfs/seaweedfs/weed/util"
"google.golang.org/protobuf/proto"
)
// TestBufferQueryability tests that data written to the buffer can be immediately queried
func TestBufferQueryability(t *testing.T) {
// Create a log buffer with a long flush interval to prevent premature flushing
logBuffer := NewLogBuffer("test-buffer", 10*time.Minute,
func(logBuffer *LogBuffer, startTime, stopTime time.Time, buf []byte, minOffset, maxOffset int64) {
// Mock flush function - do nothing to keep data in memory
},
func(startPosition MessagePosition, stopTsNs int64, eachLogEntryFn EachLogEntryFuncType) (MessagePosition, bool, error) {
// Mock read from disk function
return startPosition, false, nil
},
func() {
// Mock notify function
})
// Test data similar to schema registry messages
testKey := []byte(`{"keytype":"SCHEMA","subject":"test-topic-value","version":1,"magic":1}`)
testValue := []byte(`{"subject":"test-topic-value","version":1,"id":1,"schemaType":"AVRO","schema":"\"string\"","deleted":false}`)
// Create a LogEntry with offset (simulating the schema registry scenario)
logEntry := &filer_pb.LogEntry{
TsNs: time.Now().UnixNano(),
PartitionKeyHash: 12345,
Data: testValue,
Key: testKey,
Offset: 1,
}
// Add the entry to the buffer
if err := logBuffer.AddLogEntryToBuffer(logEntry); err != nil {
t.Fatalf("Failed to add log entry: %v", err)
}
// Verify the buffer has data
if logBuffer.pos == 0 {
t.Fatal("Buffer should have data after adding entry")
}
// Test immediate queryability - read from buffer starting from beginning
startPosition := NewMessagePosition(0, 0) // Start from beginning
bufferCopy, batchIndex, _, err := logBuffer.ReadFromBuffer(startPosition)
if err != nil {
t.Fatalf("ReadFromBuffer failed: %v", err)
}
if bufferCopy == nil {
t.Fatal("ReadFromBuffer returned nil buffer - data should be queryable immediately")
}
if batchIndex != 1 {
t.Errorf("Expected batchIndex=1, got %d", batchIndex)
}
// Verify we can read the data back
buf := bufferCopy.Bytes()
if len(buf) == 0 {
t.Fatal("Buffer copy is empty")
}
// Parse the first entry from the buffer
if len(buf) < 4 {
t.Fatal("Buffer too small to contain entry size")
}
size := util.BytesToUint32(buf[0:4])
if len(buf) < 4+int(size) {
t.Fatalf("Buffer too small to contain entry data: need %d, have %d", 4+int(size), len(buf))
}
entryData := buf[4 : 4+int(size)]
// Unmarshal and verify the entry
retrievedEntry := &filer_pb.LogEntry{}
if err := proto.Unmarshal(entryData, retrievedEntry); err != nil {
t.Fatalf("Failed to unmarshal retrieved entry: %v", err)
}
// Verify the data matches
if !bytes.Equal(retrievedEntry.Key, testKey) {
t.Errorf("Key mismatch: expected %s, got %s", string(testKey), string(retrievedEntry.Key))
}
if !bytes.Equal(retrievedEntry.Data, testValue) {
t.Errorf("Value mismatch: expected %s, got %s", string(testValue), string(retrievedEntry.Data))
}
if retrievedEntry.Offset != 1 {
t.Errorf("Offset mismatch: expected 1, got %d", retrievedEntry.Offset)
}
t.Logf("Buffer queryability test passed - data is immediately readable")
}
// TestMultipleEntriesQueryability tests querying multiple entries from buffer
func TestMultipleEntriesQueryability(t *testing.T) {
logBuffer := NewLogBuffer("test-multi-buffer", 10*time.Minute,
func(logBuffer *LogBuffer, startTime, stopTime time.Time, buf []byte, minOffset, maxOffset int64) {
// Mock flush function
},
func(startPosition MessagePosition, stopTsNs int64, eachLogEntryFn EachLogEntryFuncType) (MessagePosition, bool, error) {
return startPosition, false, nil
},
func() {})
// Add multiple entries
for i := 1; i <= 3; i++ {
logEntry := &filer_pb.LogEntry{
TsNs: time.Now().UnixNano() + int64(i*1000), // Ensure different timestamps
PartitionKeyHash: int32(i),
Data: []byte("test-data-" + string(rune('0'+i))),
Key: []byte("test-key-" + string(rune('0'+i))),
Offset: int64(i),
}
if err := logBuffer.AddLogEntryToBuffer(logEntry); err != nil {
t.Fatalf("Failed to add log entry: %v", err)
}
}
// Read all entries
startPosition := NewMessagePosition(0, 0)
bufferCopy, batchIndex, _, err := logBuffer.ReadFromBuffer(startPosition)
if err != nil {
t.Fatalf("ReadFromBuffer failed: %v", err)
}
if bufferCopy == nil {
t.Fatal("ReadFromBuffer returned nil buffer")
}
if batchIndex != 3 {
t.Errorf("Expected batchIndex=3, got %d", batchIndex)
}
// Count entries in buffer
buf := bufferCopy.Bytes()
entryCount := 0
pos := 0
for pos+4 < len(buf) {
size := util.BytesToUint32(buf[pos : pos+4])
if pos+4+int(size) > len(buf) {
break
}
entryData := buf[pos+4 : pos+4+int(size)]
entry := &filer_pb.LogEntry{}
if err := proto.Unmarshal(entryData, entry); err != nil {
t.Fatalf("Failed to unmarshal entry %d: %v", entryCount+1, err)
}
entryCount++
pos += 4 + int(size)
t.Logf("Entry %d: Key=%s, Data=%s, Offset=%d", entryCount, string(entry.Key), string(entry.Data), entry.Offset)
}
if entryCount != 3 {
t.Errorf("Expected 3 entries, found %d", entryCount)
}
t.Logf("Multiple entries queryability test passed - found %d entries", entryCount)
}
// TestSchemaRegistryScenario tests the specific scenario that was failing
func TestSchemaRegistryScenario(t *testing.T) {
logBuffer := NewLogBuffer("_schemas", 10*time.Minute,
func(logBuffer *LogBuffer, startTime, stopTime time.Time, buf []byte, minOffset, maxOffset int64) {
// Mock flush function - simulate what happens in real scenario
t.Logf("FLUSH: startTime=%v, stopTime=%v, bufSize=%d, minOffset=%d, maxOffset=%d",
startTime, stopTime, len(buf), minOffset, maxOffset)
},
func(startPosition MessagePosition, stopTsNs int64, eachLogEntryFn EachLogEntryFuncType) (MessagePosition, bool, error) {
return startPosition, false, nil
},
func() {})
// Simulate schema registry message
schemaKey := []byte(`{"keytype":"SCHEMA","subject":"test-schema-value","version":1,"magic":1}`)
schemaValue := []byte(`{"subject":"test-schema-value","version":1,"id":12,"schemaType":"AVRO","schema":"\"string\"","deleted":false}`)
logEntry := &filer_pb.LogEntry{
TsNs: time.Now().UnixNano(),
PartitionKeyHash: 12345,
Data: schemaValue,
Key: schemaKey,
Offset: 0, // First message
}
// Add to buffer
if err := logBuffer.AddLogEntryToBuffer(logEntry); err != nil {
t.Fatalf("Failed to add log entry: %v", err)
}
// Simulate the SQL query scenario - read from offset 0
startPosition := NewMessagePosition(0, 0)
bufferCopy, _, _, err := logBuffer.ReadFromBuffer(startPosition)
if err != nil {
t.Fatalf("Schema registry scenario failed: %v", err)
}
if bufferCopy == nil {
t.Fatal("Schema registry scenario: ReadFromBuffer returned nil - this is the bug!")
}
// Verify schema data is readable
buf := bufferCopy.Bytes()
if len(buf) < 4 {
t.Fatal("Buffer too small")
}
size := util.BytesToUint32(buf[0:4])
entryData := buf[4 : 4+int(size)]
retrievedEntry := &filer_pb.LogEntry{}
if err := proto.Unmarshal(entryData, retrievedEntry); err != nil {
t.Fatalf("Failed to unmarshal schema entry: %v", err)
}
// Verify schema value is preserved
if !bytes.Equal(retrievedEntry.Data, schemaValue) {
t.Errorf("Schema value lost! Expected: %s, Got: %s", string(schemaValue), string(retrievedEntry.Data))
}
if len(retrievedEntry.Data) != len(schemaValue) {
t.Errorf("Schema value length mismatch! Expected: %d, Got: %d", len(schemaValue), len(retrievedEntry.Data))
}
t.Logf("Schema registry scenario test passed - schema value preserved: %d bytes", len(retrievedEntry.Data))
}
// TestTimeBasedFirstReadBeforeEarliest ensures starting slightly before earliest memory
// does not force a disk resume and returns in-memory data (regression test)
func TestTimeBasedFirstReadBeforeEarliest(t *testing.T) {
flushed := false
logBuffer := NewLogBuffer("local", 10*time.Minute,
func(logBuffer *LogBuffer, startTime, stopTime time.Time, buf []byte, minOffset, maxOffset int64) {
// keep in memory; we just want earliest time populated
_ = buf
},
func(startPosition MessagePosition, stopTsNs int64, eachLogEntryFn EachLogEntryFuncType) (MessagePosition, bool, error) {
// disk should not be consulted in this regression path
return startPosition, false, nil
},
func() {})
// Seed one entry so earliestTime is set
baseTs := time.Now().Add(-time.Second)
entry := &filer_pb.LogEntry{TsNs: baseTs.UnixNano(), Data: []byte("x"), Key: []byte("k"), Offset: 0}
if err := logBuffer.AddLogEntryToBuffer(entry); err != nil {
t.Fatalf("Failed to add log entry: %v", err)
}
_ = flushed
// Start read 1ns before earliest memory, with offset sentinel (-2)
startPos := NewMessagePosition(baseTs.Add(-time.Nanosecond).UnixNano(), -2)
buf, _, _, err := logBuffer.ReadFromBuffer(startPos)
if err != nil {
t.Fatalf("ReadFromBuffer returned err: %v", err)
}
if buf == nil {
t.Fatalf("Expected in-memory data, got nil buffer")
}
}
// TestEarliestTimeExactRead ensures starting exactly at earliest time returns first entry (no skip)
func TestEarliestTimeExactRead(t *testing.T) {
logBuffer := NewLogBuffer("local", 10*time.Minute,
func(logBuffer *LogBuffer, startTime, stopTime time.Time, buf []byte, minOffset, maxOffset int64) {},
func(startPosition MessagePosition, stopTsNs int64, eachLogEntryFn EachLogEntryFuncType) (MessagePosition, bool, error) {
return startPosition, false, nil
},
func() {})
ts := time.Now()
entry := &filer_pb.LogEntry{TsNs: ts.UnixNano(), Data: []byte("a"), Key: []byte("k"), Offset: 0}
if err := logBuffer.AddLogEntryToBuffer(entry); err != nil {
t.Fatalf("Failed to add log entry: %v", err)
}
startPos := NewMessagePosition(ts.UnixNano(), -2)
buf, _, _, err := logBuffer.ReadFromBuffer(startPos)
if err != nil {
t.Fatalf("ReadFromBuffer err: %v", err)
}
if buf == nil || buf.Len() == 0 {
t.Fatalf("Expected data at earliest time, got nil/empty")
}
}