Monthly Archives: March 2020

go test -v streaming output

The testing package is one of my favourite packages in the Go standard library, not just because of its low noise approach to unit testing, but, over the lifetime of Go, it has received a steady stream of quality of life improvements driven by real world usage.

The most recent example of this is, in Go 1.14, go test -v will stream t.Log output as it happens, rather than hoarding it til the end of the test run. Here’s an example;

package main

import (
	"fmt"
	"testing"
	"time"
)

func TestLogStreaming(t *testing.T) {
	for i := 0; i < 5; i++ {
		time.Sleep(300 * time.Millisecond)
		fmt.Println("fmt.Println:", i)
		t.Log("t.Log:", i)
	}
}

Note: Calling fmt.Println inside a test is generally considered a no no as it bypasses the testing package’s output buffering irrespective of the -v flag. However, for this example, it‘s necessary to demonstrate the streaming t.Log change.

% go1.13 test -v tlog_test.go
=== RUN   TestLogStreaming
fmt.Println: 0
fmt.Println: 1
fmt.Println: 2
fmt.Println: 3
fmt.Println: 4
--- PASS: TestLogStreaming (1.52s)
    tlog_test.go:13: t.Log: 0
    tlog_test.go:13: t.Log: 1
    tlog_test.go:13: t.Log: 2
    tlog_test.go:13: t.Log: 3
    tlog_test.go:13: t.Log: 4
PASS
ok      command-line-arguments  1.971s

Under Go 1.13 and earlier the fmt.Println lines output immediately. t.Log lines are buffered and are printed after the test completes.

% go1.14 test -v tlog_test.go
=== RUN   TestLogStreaming
fmt.Println: 0
    TestLogStreaming: tlog_test.go:13: t.Log: 0
fmt.Println: 1
    TestLogStreaming: tlog_test.go:13: t.Log: 1
fmt.Println: 2
    TestLogStreaming: tlog_test.go:13: t.Log: 2
fmt.Println: 3
    TestLogStreaming: tlog_test.go:13: t.Log: 3
fmt.Println: 4
    TestLogStreaming: tlog_test.go:13: t.Log: 4
--- PASS: TestLogStreaming (1.51s)
PASS
ok      command-line-arguments  1.809s

Under Go 1.14 the fmt.Println and t.Log lines are interleaved, rather than waiting for the test to complete, demonstrating that test output is streamed when go test -v is used.

This is a great quality of life improvement for integration style tests that often retry for long periods when the test is failing. Streaming t.Log output will help Gophers debug those test failures without having to wait until the entire test times out to receive their output.

Are large slices more expensive than smaller ones?

Programmers have a tendency to be superstitious. Particularly, when a programmer hears that copies are expensive, they start to see them everywhere, especially when they learn that, in Go, every assignment is a copy.

Consider this code; x is three orders of magnitude larger than y, is the assignment of x to a more expensive than the assignment of y to b?

func f() {
       x, y := make([]byte, 9000), make([]byte, 9)
       a := x
       b := y
       // ...
 }

The answer is; no. x and y have the same type, []byte, that is, a slice of bytes. As both variables have the same type, their assignment involves copying the same amount of data. Both assignments have the same cost.

All slices are the same size; three machine words (three uintptrs). The first word in the slice is a pointer to the slice’s backing array, the storage for the slice, the second word is the slice’s length, and the third is the capacity. Assigning one slice variable to another copies just three machine words.

Further reading: Go slices: usage and internals (blog.golang.org)