mirror of
https://github.com/seaweedfs/seaweedfs.git
synced 2026-07-22 16:03:20 +00:00
e873e671b6
* 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.
304 lines
10 KiB
Go
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")
|
|
}
|
|
}
|