seaweedfs/weed/util/log_buffer/log_buffer.go

282 lines
6.7 KiB
Go
Raw Normal View History

2020-04-11 19:37:41 +00:00
package log_buffer
2020-03-31 05:57:45 +00:00
import (
"bytes"
2020-03-31 05:57:45 +00:00
"sync"
"time"
"github.com/golang/protobuf/proto"
2020-04-05 07:51:16 +00:00
"github.com/chrislusf/seaweedfs/weed/glog"
2020-03-31 05:57:45 +00:00
"github.com/chrislusf/seaweedfs/weed/pb/filer_pb"
"github.com/chrislusf/seaweedfs/weed/util"
)
2020-04-11 09:19:45 +00:00
const BufferSize = 4 * 1024 * 1024
const PreviousBufferCount = 3
2020-04-05 23:51:30 +00:00
type dataToFlush struct {
startTime time.Time
stopTime time.Time
data *bytes.Buffer
2020-04-05 23:51:30 +00:00
}
2020-03-31 05:57:45 +00:00
type LogBuffer struct {
2020-04-11 09:19:45 +00:00
prevBuffers *SealedBuffers
2020-03-31 05:57:45 +00:00
buf []byte
2020-04-05 07:51:16 +00:00
idx []int
2020-03-31 05:57:45 +00:00
pos int
startTime time.Time
stopTime time.Time
sizeBuf []byte
flushInterval time.Duration
flushFn func(startTime, stopTime time.Time, buf []byte)
2020-04-05 07:51:16 +00:00
notifyFn func()
2020-03-31 05:57:45 +00:00
isStopping bool
2020-04-05 23:51:30 +00:00
flushChan chan *dataToFlush
2020-05-11 08:53:54 +00:00
lastTsNs int64
2020-04-05 07:51:16 +00:00
sync.RWMutex
2020-03-31 05:57:45 +00:00
}
2020-04-05 07:51:16 +00:00
func NewLogBuffer(flushInterval time.Duration, flushFn func(startTime, stopTime time.Time, buf []byte), notifyFn func()) *LogBuffer {
2020-03-31 05:57:45 +00:00
lb := &LogBuffer{
2020-04-11 09:19:45 +00:00
prevBuffers: newSealedBuffers(PreviousBufferCount),
buf: make([]byte, BufferSize),
2020-03-31 05:57:45 +00:00
sizeBuf: make([]byte, 4),
flushInterval: flushInterval,
flushFn: flushFn,
2020-04-05 07:51:16 +00:00
notifyFn: notifyFn,
2020-04-05 23:51:30 +00:00
flushChan: make(chan *dataToFlush, 256),
2020-03-31 05:57:45 +00:00
}
go lb.loopFlush()
2020-04-05 23:51:30 +00:00
go lb.loopInterval()
2020-03-31 05:57:45 +00:00
return lb
}
2020-04-16 09:55:09 +00:00
func (m *LogBuffer) AddToBuffer(partitionKey, data []byte) {
2020-03-31 05:57:45 +00:00
2020-04-10 08:35:59 +00:00
m.Lock()
defer func() {
m.Unlock()
if m.notifyFn != nil {
m.notifyFn()
}
}()
// need to put the timestamp inside the lock
ts := time.Now()
2020-05-11 08:53:54 +00:00
tsNs := ts.UnixNano()
if m.lastTsNs >= tsNs {
// this is unlikely to happen, but just in case
tsNs = m.lastTsNs + 1
ts = time.Unix(0, tsNs)
}
m.lastTsNs = tsNs
2020-03-31 05:57:45 +00:00
logEntry := &filer_pb.LogEntry{
2020-05-11 08:53:54 +00:00
TsNs: tsNs,
2020-04-16 09:55:09 +00:00
PartitionKeyHash: util.HashToInt32(partitionKey),
2020-03-31 05:57:45 +00:00
Data: data,
}
logEntryData, _ := proto.Marshal(logEntry)
size := len(logEntryData)
if m.pos == 0 {
m.startTime = ts
}
if m.startTime.Add(m.flushInterval).Before(ts) || len(m.buf)-m.pos < size+4 {
2020-04-05 23:51:30 +00:00
m.flushChan <- m.copyToFlush()
2020-03-31 05:57:45 +00:00
m.startTime = ts
2020-04-05 07:51:16 +00:00
if len(m.buf) < size+4 {
m.buf = make([]byte, 2*size+4)
}
2020-03-31 05:57:45 +00:00
}
m.stopTime = ts
2020-04-05 07:51:16 +00:00
m.idx = append(m.idx, m.pos)
2020-03-31 05:57:45 +00:00
util.Uint32toBytes(m.sizeBuf, uint32(size))
copy(m.buf[m.pos:m.pos+4], m.sizeBuf)
copy(m.buf[m.pos+4:m.pos+4+size], logEntryData)
m.pos += size + 4
2020-04-30 10:05:34 +00:00
// fmt.Printf("entry size %d total %d count %d, buffer:%p\n", size, m.pos, len(m.idx), m)
2020-03-31 05:57:45 +00:00
}
func (m *LogBuffer) Shutdown() {
m.Lock()
defer m.Unlock()
2020-03-31 05:57:45 +00:00
if m.isStopping {
return
}
m.isStopping = true
2020-04-05 23:51:30 +00:00
toFlush := m.copyToFlush()
m.flushChan <- toFlush
close(m.flushChan)
2020-03-31 05:57:45 +00:00
}
func (m *LogBuffer) loopFlush() {
2020-04-05 23:51:30 +00:00
for d := range m.flushChan {
if d != nil {
2020-04-30 10:05:34 +00:00
// fmt.Printf("flush [%v, %v] size %d\n", d.startTime, d.stopTime, len(d.data.Bytes()))
m.flushFn(d.startTime, d.stopTime, d.data.Bytes())
d.releaseMemory()
2020-04-05 23:51:30 +00:00
}
}
}
func (m *LogBuffer) loopInterval() {
2020-03-31 05:57:45 +00:00
for !m.isStopping {
time.Sleep(m.flushInterval)
2020-03-31 05:57:45 +00:00
m.Lock()
if m.isStopping {
m.Unlock()
return
}
// println("loop interval")
2020-04-05 23:51:30 +00:00
toFlush := m.copyToFlush()
m.flushChan <- toFlush
m.Unlock()
2020-03-31 05:57:45 +00:00
}
}
2020-04-05 23:51:30 +00:00
func (m *LogBuffer) copyToFlush() *dataToFlush {
2020-04-05 19:38:29 +00:00
2020-07-11 16:12:03 +00:00
if m.pos > 0 {
2020-04-06 03:15:17 +00:00
// fmt.Printf("flush buffer %d pos %d empty space %d\n", len(m.buf), m.pos, len(m.buf)-m.pos)
2020-07-11 16:12:03 +00:00
var d *dataToFlush
if m.flushFn != nil {
d = &dataToFlush{
startTime: m.startTime,
stopTime: m.stopTime,
data: copiedBytes(m.buf[:m.pos]),
}
2020-04-05 23:51:30 +00:00
}
// fmt.Printf("flusing [0,%d) with %d entries\n", m.pos, len(m.idx))
m.buf = m.prevBuffers.SealBuffer(m.startTime, m.stopTime, m.buf, m.pos)
2020-03-31 05:57:45 +00:00
m.pos = 0
2020-04-05 07:51:16 +00:00
m.idx = m.idx[:0]
2020-04-05 23:51:30 +00:00
return d
2020-04-05 07:51:16 +00:00
}
2020-04-05 23:51:30 +00:00
return nil
2020-04-05 07:51:16 +00:00
}
func (d *dataToFlush) releaseMemory() {
d.data.Reset()
bufferPool.Put(d.data)
}
func (m *LogBuffer) ReadFromBuffer(lastReadTime time.Time) (bufferCopy *bytes.Buffer) {
2020-04-05 07:51:16 +00:00
m.RLock()
defer m.RUnlock()
2020-04-30 10:05:34 +00:00
/*
fmt.Printf("read buffer %p: %v last stop time: [%v,%v], pos %d, entries:%d, prevBufs:%d\n", m, lastReadTime, m.startTime, m.stopTime, m.pos, len(m.idx), len(m.prevBuffers.buffers))
for i, prevBuf := range m.prevBuffers.buffers {
fmt.Printf(" prev %d : %s\n", i, prevBuf.String())
}
*/
2020-04-05 07:51:16 +00:00
if lastReadTime.Equal(m.stopTime) {
return nil
2020-04-05 07:51:16 +00:00
}
if lastReadTime.After(m.stopTime) {
// glog.Fatalf("unexpected last read time %v, older than latest %v", lastReadTime, m.stopTime)
return nil
2020-03-31 05:57:45 +00:00
}
2020-04-05 07:51:16 +00:00
if lastReadTime.Before(m.startTime) {
// println("checking ", lastReadTime.UnixNano())
for i, buf := range m.prevBuffers.buffers {
if buf.startTime.After(lastReadTime) {
if i == 0 {
2020-04-21 00:43:50 +00:00
// println("return the earliest in memory", buf.startTime.UnixNano())
return copiedBytes(buf.buf[:buf.size])
}
2020-04-30 10:05:34 +00:00
// println("return the", i, "th in memory", buf.startTime.UnixNano())
return copiedBytes(buf.buf[:buf.size])
}
if !buf.startTime.After(lastReadTime) && buf.stopTime.After(lastReadTime) {
pos := buf.locateByTs(lastReadTime)
2020-04-21 00:43:50 +00:00
// fmt.Printf("locate buffer[%d] pos %d\n", i, pos)
return copiedBytes(buf.buf[pos:buf.size])
}
}
2020-04-30 10:05:34 +00:00
// println("return the current buf", lastReadTime.UnixNano())
return copiedBytes(m.buf[:m.pos])
2020-04-05 07:51:16 +00:00
}
lastTs := lastReadTime.UnixNano()
l, h := 0, len(m.idx)-1
2020-04-06 03:15:17 +00:00
2020-04-05 23:51:30 +00:00
/*
2020-04-10 08:35:59 +00:00
for i, pos := range m.idx {
logEntry, ts := readTs(m.buf, pos)
2020-04-13 04:00:55 +00:00
event := &filer_pb.SubscribeMetadataResponse{}
2020-04-10 08:35:59 +00:00
proto.Unmarshal(logEntry.Data, event)
entry := event.EventNotification.OldEntry
if entry == nil {
entry = event.EventNotification.NewEntry
}
fmt.Printf("entry %d ts: %v offset:%d dir:%s name:%s\n", i, time.Unix(0, ts), pos, event.Directory, entry.Name)
2020-04-05 23:51:30 +00:00
}
2020-04-10 08:35:59 +00:00
fmt.Printf("l=%d, h=%d\n", l, h)
*/
2020-04-05 07:51:16 +00:00
2020-04-06 00:34:26 +00:00
for l <= h {
2020-04-05 07:51:16 +00:00
mid := (l + h) / 2
pos := m.idx[mid]
_, t := readTs(m.buf, pos)
2020-04-05 07:51:16 +00:00
if t <= lastTs {
l = mid + 1
} else if lastTs < t {
var prevT int64
if mid > 0 {
2020-04-06 03:15:17 +00:00
_, prevT = readTs(m.buf, m.idx[mid-1])
2020-04-05 07:51:16 +00:00
}
if prevT <= lastTs {
// fmt.Printf("found l=%d, m-1=%d(ts=%d), m=%d(ts=%d), h=%d [%d, %d) \n", l, mid-1, prevT, mid, t, h, pos, m.pos)
return copiedBytes(m.buf[pos:m.pos])
2020-04-05 07:51:16 +00:00
}
h = mid
2020-04-05 07:51:16 +00:00
}
// fmt.Printf("l=%d, h=%d\n", l, h)
}
2020-04-06 03:15:17 +00:00
// FIXME: this could be that the buffer has been flushed already
return nil
2020-04-06 03:15:17 +00:00
2020-04-05 07:51:16 +00:00
}
func (m *LogBuffer) ReleaseMeory(b *bytes.Buffer) {
bufferPool.Put(b)
}
var bufferPool = sync.Pool{
New: func() interface{} {
return new(bytes.Buffer)
},
}
func copiedBytes(buf []byte) (copied *bytes.Buffer) {
copied = bufferPool.Get().(*bytes.Buffer)
2020-04-29 09:41:01 +00:00
copied.Reset()
copied.Write(buf)
2020-04-05 07:51:16 +00:00
return
}
func readTs(buf []byte, pos int) (size int, ts int64) {
2020-04-05 07:51:16 +00:00
size = int(util.BytesToUint32(buf[pos : pos+4]))
entryData := buf[pos+4 : pos+4+size]
2020-04-05 07:51:16 +00:00
logEntry := &filer_pb.LogEntry{}
err := proto.Unmarshal(entryData, logEntry)
if err != nil {
glog.Fatalf("unexpected unmarshal filer_pb.LogEntry: %v", err)
}
return size, logEntry.TsNs
2020-04-05 07:51:16 +00:00
2020-03-31 05:57:45 +00:00
}