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

@@ -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
 			}
 		}
 	}

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