utils: fix excessive refresh frequency when BR_LOG_TO_TERM=1

pkg/utils/progress.go

@@ -4,6 +4,7 @@ package utils
 
 import (
 	"context"
+	"encoding/json"
 	"io"
 	"time"
 
@@ -45,11 +46,11 @@ func (pp *ProgressPrinter) goPrintProgress(
 	ctx context.Context,
 	testWriter io.Writer, // Only for tests
 ) {
-	var bar *pb.ProgressBar
+	bar := pb.New64(pp.total)
 	if pp.redirectLog || testWriter != nil {
-		tmpl := `{{percent .}}`
-		bar = pb.ProgressBarTemplate(tmpl).Start64(pp.total)
-		bar.SetRefreshRate(time.Second * 10)
+		tmpl := `{"P":"{{percent .}}","C":"{{counters . }}","E":"{{etime .}}","R":"{{rtime .}}","S":"{{speed .}}"}`
+		bar.SetTemplateString(tmpl)
+		bar.SetRefreshRate(2 * time.Minute)
 		bar.Set(pb.Static, false)       // Do not update automatically
 		bar.Set(pb.ReturnSymbol, false) // Do not append '\r'
 		bar.Set(pb.Terminal, false)     // Do not use terminal width
@@ -58,11 +59,12 @@ func (pp *ProgressPrinter) goPrintProgress(
 		bar.SetWriter(&wrappedWriter{name: pp.name})
 	} else {
 		tmpl := `{{string . "barName" | green}} {{ bar . "<" "-" (cycle . "-" "\\" "|" "/" ) "." ">"}} {{percent .}}`
-		bar = pb.ProgressBarTemplate(tmpl).Start64(pp.total)
+		bar.SetTemplateString(tmpl)
 		bar.Set("barName", pp.name)
 	}
 	if testWriter != nil {
 		bar.SetWriter(testWriter)
+		bar.SetRefreshRate(10 * time.Millisecond)
 	}
 	bar.Start()
 
@@ -99,7 +101,23 @@ type wrappedWriter struct {
 }
 
 func (ww *wrappedWriter) Write(p []byte) (int, error) {
-	log.Info(ww.name, zap.String("progress", string(p)))
+	var info struct {
+		P string
+		C string
+		E string
+		R string
+		S string
+	}
+	if err := json.Unmarshal(p, &info); err != nil {
+		return 0, err
+	}
+	log.Info("progress",
+		zap.String("step", ww.name),
+		zap.String("progress", info.P),
+		zap.String("count", info.C),
+		zap.String("speed", info.S),
+		zap.String("elapsed", info.E),
+		zap.String("remaining", info.R))
 	return len(p), nil
 }
 

pkg/utils/progress_test.go

@@ -33,13 +33,13 @@ func (r *testProgressSuite) TestProgress(c *C) {
 	updateCh2 := progress2.UpdateCh()
 	updateCh2 <- struct{}{}
 	p = <-pCh2
-	c.Assert(p, Matches, ".*50.*")
+	c.Assert(p, Matches, `.*"P":"50\.00%".*`)
 	updateCh2 <- struct{}{}
 	p = <-pCh2
-	c.Assert(p, Matches, ".*100.*")
+	c.Assert(p, Matches, `.*"P":"100\.00%".*`)
 	updateCh2 <- struct{}{}
 	p = <-pCh2
-	c.Assert(p, Matches, ".*100.*")
+	c.Assert(p, Matches, `.*"P":"100\.00%".*`)
 
 	pCh4 := make(chan string, 4)
 	progress4 := NewProgressPrinter("test", 4, false)
@@ -49,11 +49,11 @@ func (r *testProgressSuite) TestProgress(c *C) {
 	updateCh4 := progress4.UpdateCh()
 	updateCh4 <- struct{}{}
 	p = <-pCh4
-	c.Assert(p, Matches, ".*25.*")
+	c.Assert(p, Matches, `.*"P":"25\.00%".*`)
 	updateCh4 <- struct{}{}
 	close(updateCh4)
 	p = <-pCh4
-	c.Assert(p, Matches, ".*100.*")
+	c.Assert(p, Matches, `.*"P":"100\.00%".*`)
 
 	pCh8 := make(chan string, 8)
 	progress8 := NewProgressPrinter("test", 8, false)
@@ -65,10 +65,10 @@ func (r *testProgressSuite) TestProgress(c *C) {
 	updateCh8 <- struct{}{}
 	<-pCh8
 	p = <-pCh8
-	c.Assert(p, Matches, ".*25.*")
+	c.Assert(p, Matches, `.*"P":"25\.00%".*`)
 
 	// Cancel should stop progress at the current position.
 	cancel()
 	p = <-pCh8
-	c.Assert(p, Matches, ".*25.*")
+	c.Assert(p, Matches, `.*"P":"25\.00%".*`)
 }