git/githistory/log: enforce throttle per log line

git/githistory/log/log.go

@@ -6,11 +6,16 @@ import (
 	"io/ioutil"
 	"strings"
 	"sync"
+	"time"
 
 	"github.com/git-lfs/git-lfs/tools"
 	"github.com/olekukonko/ts"
 )
 
+const (
+	DefaultLoggingThrottle = 200 * time.Millisecond
+)
+
 // Logger logs a series of tasks to an io.Writer, processing each task in order
 // until completion .
 type Logger struct {
@@ -21,6 +26,10 @@ type Logger struct {
 	// this logger is running within.
 	widthFn func() int
 
+	// throttle is the minimum amount of time that must pass between each
+	// instant data is logged.
+	throttle time.Duration
+
 	// queue is the incoming, unbuffered queue of tasks to enqueue.
 	queue chan Task
 	// tasks is the set of tasks to process.
@@ -38,7 +47,8 @@ func NewLogger(sink io.Writer) *Logger {
 	}
 
 	l := &Logger{
-		sink: sink,
+		sink:     sink,
+		throttle: DefaultLoggingThrottle,
 		widthFn: func() int {
 			size, err := ts.GetSize()
 			if err != nil {
@@ -168,12 +178,19 @@ func (l *Logger) consume() {
 func (l *Logger) logTask(task Task) {
 	defer l.wg.Done()
 
-	var last string
-	for last = range task.Updates() {
-		l.logLine(last)
+	var last time.Time
+
+	var msg string
+	for msg = range task.Updates() {
+		now := time.Now()
+
+		if now.After(last.Add(l.throttle)) {
+			l.logLine(msg)
+			last = now
+		}
 	}
 
-	l.log(fmt.Sprintf("%s, done\n", last))
+	l.log(fmt.Sprintf("%s, done\n", msg))
 }
 
 // logLine writes a complete line and moves the cursor to the beginning of the

git/githistory/log/log_test.go

@@ -4,6 +4,7 @@ import (
 	"bytes"
 	"strings"
 	"testing"
+	"time"
 
 	"github.com/stretchr/testify/assert"
 )
@@ -23,6 +24,7 @@ func TestLoggerLogsTasks(t *testing.T) {
 	}()
 
 	l := NewLogger(&buf)
+	l.throttle = 0
 	l.widthFn = func() int { return 0 }
 	l.enqueue(ChanTask(task))
 	l.Close()
@@ -47,6 +49,7 @@ func TestLoggerLogsMultipleTasksInOrder(t *testing.T) {
 	}()
 
 	l := NewLogger(&buf)
+	l.throttle = 0
 	l.widthFn = func() int { return 0 }
 	l.enqueue(ChanTask(t1), ChanTask(t2))
 	l.Close()
@@ -65,6 +68,7 @@ func TestLoggerLogsMultipleTasksWithoutBlocking(t *testing.T) {
 	var buf bytes.Buffer
 
 	l := NewLogger(&buf)
+	l.throttle = 0
 	t1, t2 := make(chan string), make(chan string)
 
 	l.widthFn = func() int { return 0 }
@@ -85,3 +89,54 @@ func TestLoggerLogsMultipleTasksWithoutBlocking(t *testing.T) {
 		"second, done\n",
 	}, ""), buf.String())
 }
+
+func TestLoggerThrottlesWrites(t *testing.T) {
+	var buf bytes.Buffer
+
+	t1 := make(chan string)
+	go func() {
+		t1 <- "first"                    // t = 0    ms, throttle was open
+		time.Sleep(3 * time.Millisecond) // t = 3    ms, throttle is closed
+		t1 <- "second"                   // t = 3+ε  ms, throttle is closed
+		time.Sleep(3 * time.Millisecond) // t = 6    ms, throttle is open
+		t1 <- "third"                    // t = 6+ε  ms, throttle was open
+		close(t1)                        // t = 6+2ε ms, throttle is closed
+	}()
+
+	l := NewLogger(&buf)
+	l.widthFn = func() int { return 0 }
+	l.throttle = 5 * time.Millisecond
+
+	l.enqueue(ChanTask(t1))
+	l.Close()
+
+	assert.Equal(t, strings.Join([]string{
+		"first\r",
+		"third\r",
+		"third, done\n",
+	}, ""), buf.String())
+}
+
+func TestLoggerThrottlesLastWrite(t *testing.T) {
+	var buf bytes.Buffer
+
+	t1 := make(chan string)
+	go func() {
+		t1 <- "first"                    // t = 0    ms, throttle was open
+		time.Sleep(3 * time.Millisecond) // t = 3    ms, throttle is closed
+		t1 <- "second"                   // t = 3+ε  ms, throttle is closed
+		close(t1)                        // t = 3+2ε ms, throttle is closed
+	}()
+
+	l := NewLogger(&buf)
+	l.widthFn = func() int { return 0 }
+	l.throttle = 5 * time.Millisecond
+
+	l.enqueue(ChanTask(t1))
+	l.Close()
+
+	assert.Equal(t, strings.Join([]string{
+		"first\r",
+		"second, done\n",
+	}, ""), buf.String())
+}