From fdcbd54cd7810ff9b471f4af273671e25baf11e4 Mon Sep 17 00:00:00 2001
From: Jakob Borg <jakob@kastelo.net>
Date: Tue, 7 Feb 2017 07:25:09 +0000
Subject: [PATCH] lib/events: Be more resilient against dropping events (fixes
 #3952)

Instead of just immediately dropping the event if the subscription isn't
ready to receive it, give it 15 ms to catch up. The value 15 ms is
grabbed out of thin air - it just seems reasonable to me.

The timer juggling makes the event send pretty much exactly twice as
slow as it was before, but we're still under a microsecond. I think it's
negligible compared to whatever event that just happened that we're
interested in logging (usually a file operation of some kind).

	benchmark                  old ns/op     new ns/op     delta
	BenchmarkBufferedSub-8     475           950           +100.00%

	benchmark                  old allocs     new allocs     delta
	BenchmarkBufferedSub-8     4              4              +0.00%

	benchmark                  old bytes     new bytes     delta
	BenchmarkBufferedSub-8     104           117           +12.50%

GitHub-Pull-Request: https://github.com/syncthing/syncthing/pull/3960
---
 lib/events/events.go      | 27 ++++++++++++++++++++++++---
 lib/events/events_test.go |  2 +-
 2 files changed, 25 insertions(+), 4 deletions(-)

diff --git a/lib/events/events.go b/lib/events/events.go
index 2abd61af..45354709 100644
--- a/lib/events/events.go
+++ b/lib/events/events.go
@@ -51,6 +51,8 @@ const (
 
 var runningTests = false
 
+const eventLogTimeout = 15 * time.Millisecond
+
 func (t EventType) String() string {
 	switch t {
 	case Starting:
@@ -122,6 +124,7 @@ type Logger struct {
 	subs                []*Subscription
 	nextSubscriptionIDs []int
 	nextGlobalID        int
+	timeout             *time.Timer
 	mutex               sync.Mutex
 }
 
@@ -149,9 +152,16 @@ var (
 )
 
 func NewLogger() *Logger {
-	return &Logger{
-		mutex: sync.NewMutex(),
+	l := &Logger{
+		mutex:   sync.NewMutex(),
+		timeout: time.NewTimer(time.Second),
 	}
+	// Make sure the timer is in the stopped state and hasn't fired anything
+	// into the channel.
+	if !l.timeout.Stop() {
+		<-l.timeout.C
+	}
+	return l
 }
 
 func (l *Logger) Log(t EventType, data interface{}) {
@@ -171,10 +181,21 @@ func (l *Logger) Log(t EventType, data interface{}) {
 			e.SubscriptionID = l.nextSubscriptionIDs[i]
 			l.nextSubscriptionIDs[i]++
 
+			l.timeout.Reset(eventLogTimeout)
+			timedOut := false
+
 			select {
 			case s.events <- e:
-			default:
+			case <-l.timeout.C:
 				// if s.events is not ready, drop the event
+				timedOut = true
+			}
+
+			// If stop returns false it already sent something to the
+			// channel. If we didn't already read it above we must do so now
+			// or we get a spurious timeout on the next loop.
+			if !l.timeout.Stop() && !timedOut {
+				<-l.timeout.C
 			}
 		}
 	}
diff --git a/lib/events/events_test.go b/lib/events/events_test.go
index ceec063e..950fc50a 100644
--- a/lib/events/events_test.go
+++ b/lib/events/events_test.go
@@ -12,7 +12,7 @@ import (
 	"time"
 )
 
-const timeout = 100 * time.Millisecond
+const timeout = 5 * time.Second
 
 func init() {
 	runningTests = true