I'm writing an async logger and using bufio for writing logs into file. This is done in the following way:
type ALogger struct {
records chan []byte
buff bufio.Writer
queueLen int32 // amount of items currently awaiting to be written to `records`
done chan struct{} // used for signaling inside `alog.Run()` as well as `inactive`
inactive chan struct{}
}
func (al *ALogger) write(s []byte) (int, error) {
bytesWritten := 0
for bytesWritten < len(s) {
bw, err := al.buff.Write(s[bytesWritten:])
if err != nil {
return bytesWritten, err
}
bytesWritten += bw
}
return bytesWritten, nil
}
func (al *ALogger) Run() error {
var stow []byte
for {
select {
case <-al.done: // used for sync pur
al.inactive <- struct{}{}
return nil
case r := <-al.records:
// from rought testing this approach is faster then flushing the buffer
r = append(stow, r...)
if bw, err := al.write(r); err != nil {
if err == io.ErrShortWrite { // doesn't occur but used to, idk why
stow = r[bw:]
} else {
return err
}
} else {
stow = []byte("")
}
default:
continue
}
}
}
func (al *ALogger) Print(s ...any) {
r := []byte(fmt.Sprint(s...))
atomic.AddInt32(&al.queueLen, 1)
al.records <- r
atomic.AddInt32(&al.queueLen, -1)
}
// where print is called
func job(r *rand.Rand) int64 {
val := r.Int63() % 10000
ng := int64(runtime.NumGoroutine())
work := md5.Sum([]byte(fmt.Sprint(ng + val))) // h(m)
work = md5.Sum([]byte(fmt.Sprint(work, ng+val))) // h(h(m) || m)
return int64(binary.BigEndian.Uint16(work[:2])) % 10000
}
// Is run inside a loop each in a seperate goroutine.
func RunALog(wg *sync.WaitGroup, eventCount, threadID int) {
r := rand.New(rand.NewSource(int64(threadID)))
for i := 0; i < eventCount; i++ {
alog.Print(fmt.Sprintf("{\"thread\": %d, \"timestamp\": %v, \"result\": %d}\n",
threadID,
time.Now(),
job(r),
))
}
wg.Done()
alog.Print("\n\n")
}
The method above runs in a separate goroutine and accepts records to log from other parts of the program without blocking execution. It runs fine and in fact I'm getting 4-5x gain in speed in comparison to log but for some reason it sometimes writes empty lines to log file. For example:
{"thread": 6, "timestamp": 2022-09-17 23:36:47.543629743 +0400 +04 m=+0.008094248, "result": 932}
{"thread": 6, "timestamp": 2022-09-17 23:36:47.543636105 +0400 +04 m=+0.008100609, "result": 8767}
{"thread": 6, "timestamp": 2022-09-17 23:36:47.543645313 +0400 +04 m=+0.008109817, "result": 2098}
{"thread": 6, "timestamp": 2022-09-17 23:36:47.543657035 +0400 +04 m=+0.008121539, "result": 7888}
// this one
// and this one too
{"thread": 6, "timestamp": 2022-09-17 23:36:47.543664098 +0400 +04 m=+0.008128612, "result": 6601}
{"thread": 4, "timestamp": 2022-09-17 23:36:47.543413818 +0400 +04 m=+0.007878332, "result": 5171}
{"thread": 4, "timestamp": 2022-09-17 23:36:47.543421653 +0400 +04 m=+0.007886167, "result": 5054}
{"thread": 6, "timestamp": 2022-09-17 23:36:47.5436703 +0400 +04 m=+0.008134804, "result": 1885}
UPD0: In debug noticed that r sometimes spontaneously receives [10 10] which is two end line symbols.
UDP1: Blank lines do not substitute normal log messages. If I run 7 goroutines with eventCount equals 50 I will get 350 normal records in log file, plus some blank lines on top.