profiling

Author: davecheney

2-benchmarking/examples/benchfib/wrong_test.go

@@ -0,0 +1,24 @@
+package fib
+
+import "testing"
+
+// START OMIT
+func Fib(n int) int {
+	a, b := 0, 1
+	for i := 0; i < n; i++ {
+		a, b = b, a+b
+	}
+	return a
+}
+
+func BenchmarkFibWrong(b *testing.B) {
+	Fib(b.N)
+}
+
+func BenchmarkFibWrong2(b *testing.B) {
+	for n := 0; n < b.N; n++ {
+		Fib(n)
+	}
+}
+
+// END OMIT

2-benchmarking/examples/benchmark.go

@@ -0,0 +1,8 @@
+package q
+
+func BenchmarkRead(b *testing.B) {
+	b.ReportAllocs() // HL
+	for n := 0; n < b.N; n++ {
+		// function under test
+	}
+}

2-benchmarking/examples/fib/fib_test.go

@@ -0,0 +1,45 @@
+package fib
+
+import "testing"
+
+// STARTFIB OMIT
+// Fib computes the n'th number in the Fibonacci series.
+func Fib(n int) int {
+	switch n {
+	case 0:
+		return 0
+	case 1:
+		return 1
+	case 2:
+		return 1
+	default:
+		return Fib(n-1) + Fib(n-2)
+	}
+}
+
+// ENDFIB OMIT
+
+// STARTBENCH OMIT
+func BenchmarkFib20(b *testing.B) {
+	for n := 0; n < b.N; n++ {
+		Fib(20) // run the Fib function b.N times
+	}
+}
+
+func BenchmarkFib1(b *testing.B) {
+	for n := 0; n < b.N; n++ {
+		Fib(1)
+	}
+}
+
+// ENDBENCH OMIT
+
+func TestFib(t *testing.T) {
+	fibs := []int{0, 1, 1, 2, 3, 5, 8, 13, 21}
+	for n, want := range fibs {
+		got := Fib(n)
+		if want != got {
+			t.Errorf("Fib(%d): want %d, got %d", n, want, got)
+		}
+	}
+}

2-benchmarking/examples/popcnt/popcnt2_test.go

@@ -0,0 +1,26 @@
+// +build ignore
+
+package main
+
+import "testing"
+
+const m1 = 0x5555555555555555
+const m2 = 0x3333333333333333
+const m4 = 0x0f0f0f0f0f0f0f0f
+const h01 = 0x0101010101010101
+
+func popcnt(x uint64) int {
+	x -= (x >> 1) & m1
+	x = (x & m2) + ((x >> 2) & m2)
+	x = (x + (x >> 4)) & m4
+	return int((x * h01) >> 56)
+}
+
+// START OMIT
+func BenchmarkPopcnt(b *testing.B) {
+	for i := 0; i < b.N; i++ {
+		// optimised away
+	}
+}
+
+// END OMIT

2-benchmarking/examples/popcnt/popcnt_test.go

@@ -0,0 +1,24 @@
+package main
+
+import "testing"
+
+// START OMIT
+const m1 = 0x5555555555555555
+const m2 = 0x3333333333333333
+const m4 = 0x0f0f0f0f0f0f0f0f
+const h01 = 0x0101010101010101
+
+func popcnt(x uint64) uint64 {
+	x -= (x >> 1) & m1
+	x = (x & m2) + ((x >> 2) & m2)
+	x = (x + (x >> 4)) & m4
+	return (x * h01) >> 56
+}
+
+func BenchmarkPopcnt(b *testing.B) {
+	for i := 0; i < b.N; i++ {
+		popcnt(uint64(i))
+	}
+}
+
+// END OMIT

2-benchmarking/examples/reset.go

@@ -0,0 +1,24 @@
+package q
+
+// START1 OMIT
+func BenchmarkExpensive(b *testing.B) {
+	boringAndExpensiveSetup()
+	b.ResetTimer() // HL
+	for n := 0; n < b.N; n++ {
+		// function under test
+	}
+}
+
+// END1 OMIT
+
+// START2 OMIT
+func BenchmarkComplicated(b *testing.B) {
+	for n := 0; n < b.N; n++ {
+		b.StopTimer() // HL
+		complicatedSetup()
+		b.StartTimer() // HL
+		// function under test
+	}
+}
+
+// END2 OMIT

3-profiling/1-profiling.md

@@ -264,27 +264,86 @@ By inserting a `bufio.Reader` between the input file and `readbyte` will
 
 _Exercise_: Compare the times of this revised program to `wc`. How close is it? Take a profile and see what remains.
 
-
 ## Memory profiling
 
-The output of a memory profile can be similarly visualised.
+The new `words` profile suggests that something is allocating inside the `readbyte` function. We can use pprof to investigate.
+```go
+defer profile.Start(profile.MemProfile).Stop()
+```
+Then run the program as usual
+```
+% go run main2.go moby.txt
+2018/08/25 14:41:15 profile: memory profiling enabled (rate 4096), /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile312088211/mem.pprof
+"moby.txt": 181275 words
+2018/08/25 14:41:15 profile: memory profiling disabled, /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile312088211/mem.pprof
+```
+
+![memprof](/Users/dfc/devel/gophercon2018-performance-tuning-workshop/3-profiling/images/memprof.png)
+
+As we suspected the allocation was coming from `readbyte` -- this wasn't that complicated, readbyte is three lines long:
+```go
+func readbyte(r io.Reader) (rune, error) {
+        var buf [1]byte // allocation is here
+        _, err := r.Read(buf[:])
+        return rune(buf[0]), err
+}
+```
+We'll talk about why this is happening in more detail in the next section, but for the moment what we see is every call to readbyte is allocating a new one byte long _array_ and that array is being allocated on the heap.
+
+_Exercise_: What are some ways we can avoid this? Try them and use CPU and memory profiling to prove it.
 
-    % go build -gcflags='-memprofile=/tmp/m.p'
-    % go tool pprof --alloc_objects -svg $(go tool -n compile) /tmp/m.p > alloc_objects.svg
-    % go tool pprof --inuse_objects -svg $(go tool -n compile) /tmp/m.p > inuse_objects.svg
+### Alloc objects vs. inuse objects
 
-Memory profiles come in two varieties
+Memory profiles come in two varieties, named after their `go tool pprof` flags
 
-- Alloc objects reports the call site where each allocation was made
+- `-alloc_objects` reports the call site where each allocation was made
+- `-inuse_objects` reports the call site where an allocation was made _iff_ it was reachable at the end of the profile
 
-!(allocated objects)[images/alloc_objects.svg]
+To demonstrate this, here is a contrived program which will allocate a bunch of memory in a controlled manner.
+```go
+// ensure y is live beyond the end of main.
+var y []byte
 
-- Inuse objects reports the call site where an allocation was made _iff_ it was reachable at the end of the profile
+func main() {
+        defer profile.Start(profile.MemProfile, profile.MemProfileRate(1)).Stop()
+        y = allocate(100000)
+        runtime.GC()
+}
 
-.link images/inuse_objects.svg
+// allocate allocates count byte slices and returns the first slice allocated.
+func allocate(count int) []byte {
+        var x [][]byte
+        for i := 0; i < count; i++ {
+                x = append(x, makeByteSlice())
+        }
+        return x[0]
+}
 
-DEMO: `examples/inuseallocs`
+// makeByteSlice returns a byte slice of a random length in the range [0, 16384).
+func makeByteSlice() []byte {
+        return make([]byte, rand.Intn(1<<14))
+}
+```
+The program is annotation with the `profile` package, and we set the memory profile rate  to `1`--that is, record a stack trace for every allocation. This is slows down the program a lot, but you'll see why in a minute.
+```
+% go run main.go
+2018/08/25 15:22:05 profile: memory profiling enabled (rate 1), /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile730812803/mem.pprof
+2018/08/25 15:22:05 profile: memory profiling disabled, /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile730812803/mem.pprof
+```
+Lets look at the graph of allocated objects, this is the default, and shows the call graphs that lead to the allocation of every object during the profile.
+```
+% go tool pprof -web -alloc_objects /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile891268605/mem.pprof
+```
+
+![alloc_objects](images/alloc_objects.png)
+
+Not surprisingly more than 99% of the allocations were inside `makeByteSlice`. Now lets look at the same profile using `-inuse_objects`
+```
+% go tool pprof -web -inuse_objects /var/folders/by/3gf34_z95zg05cyj744_vhx40000gn/T/profile891268605/mem.pprof
+```
 
+![inuse_objects](images/inuse_objects.png)
+What we see is not the objects that were _allocated_ during the profile, but the objects that remain _in use_, at the time the profile was taken -- this ignores the stack trace for objects which have been reclaimed by the garbage collector.
 ## Block profiling (example)
 
 Here is a visualisation of a block profile:

3-profiling/examples/inuseallocs/main.go

@@ -1,4 +1,4 @@
-// A simple example to demonstrate the difference between alloc_count and inuse_count
+// A simple example to demonstrate the difference between alloc_objects and inuse_objects
 package main
 
 import (
@@ -8,24 +8,25 @@ import (
 	"github.com/pkg/profile"
 )
 
-const count = 100000
-
+// ensure y is live beyond the end of main.
 var y []byte
 
 func main() {
 	defer profile.Start(profile.MemProfile, profile.MemProfileRate(1)).Stop()
-	y = allocate()
+	y = allocate(100000)
 	runtime.GC()
 }
 
-func allocate() []byte {
+// allocate allocates count byte slices and returns the first slice allocated.
+func allocate(count int) []byte {
 	var x [][]byte
 	for i := 0; i < count; i++ {
 		x = append(x, makeByteSlice())
 	}
 	return x[0]
 }
 
+// makeByteSlice returns a byte slice of a random length in the range [0, 16384).
 func makeByteSlice() []byte {
-	return make([]byte, rand.Intn(2^14))
+	return make([]byte, rand.Intn(1<<14))
 }

3-profiling/examples/words/main2.go

@@ -7,9 +7,12 @@ import (
 	"log"
 	"os"
 	"unicode"
+
+	"github.com/pkg/profile"
 )
 
 func main() {
+	defer profile.Start(profile.MemProfile).Stop()
 	f, err := os.Open(os.Args[1])
 	if err != nil {
 		log.Fatalf("could not open file %q: %v", os.Args[1], err)