...
Run Format

Source file src/runtime/trace/trace_test.go

Documentation: runtime/trace

  // Copyright 2014 The Go Authors. All rights reserved.
  // Use of this source code is governed by a BSD-style
  // license that can be found in the LICENSE file.
  
  package trace_test
  
  import (
  	"bytes"
  	"flag"
  	"internal/trace"
  	"io"
  	"io/ioutil"
  	"net"
  	"os"
  	"runtime"
  	. "runtime/trace"
  	"sync"
  	"testing"
  	"time"
  )
  
  var (
  	saveTraces = flag.Bool("savetraces", false, "save traces collected by tests")
  )
  
  func TestTraceStartStop(t *testing.T) {
  	buf := new(bytes.Buffer)
  	if err := Start(buf); err != nil {
  		t.Fatalf("failed to start tracing: %v", err)
  	}
  	Stop()
  	size := buf.Len()
  	if size == 0 {
  		t.Fatalf("trace is empty")
  	}
  	time.Sleep(100 * time.Millisecond)
  	if size != buf.Len() {
  		t.Fatalf("trace writes after stop: %v -> %v", size, buf.Len())
  	}
  	saveTrace(t, buf, "TestTraceStartStop")
  }
  
  func TestTraceDoubleStart(t *testing.T) {
  	Stop()
  	buf := new(bytes.Buffer)
  	if err := Start(buf); err != nil {
  		t.Fatalf("failed to start tracing: %v", err)
  	}
  	if err := Start(buf); err == nil {
  		t.Fatalf("succeed to start tracing second time")
  	}
  	Stop()
  	Stop()
  }
  
  func TestTrace(t *testing.T) {
  	buf := new(bytes.Buffer)
  	if err := Start(buf); err != nil {
  		t.Fatalf("failed to start tracing: %v", err)
  	}
  	Stop()
  	saveTrace(t, buf, "TestTrace")
  	_, err := trace.Parse(buf, "")
  	if err == trace.ErrTimeOrder {
  		t.Skipf("skipping trace: %v", err)
  	}
  	if err != nil {
  		t.Fatalf("failed to parse trace: %v", err)
  	}
  }
  
  func parseTrace(t *testing.T, r io.Reader) ([]*trace.Event, map[uint64]*trace.GDesc) {
  	events, err := trace.Parse(r, "")
  	if err == trace.ErrTimeOrder {
  		t.Skipf("skipping trace: %v", err)
  	}
  	if err != nil {
  		t.Fatalf("failed to parse trace: %v", err)
  	}
  	gs := trace.GoroutineStats(events)
  	for goid := range gs {
  		// We don't do any particular checks on the result at the moment.
  		// But still check that RelatedGoroutines does not crash, hang, etc.
  		_ = trace.RelatedGoroutines(events, goid)
  	}
  	return events, gs
  }
  
  func testBrokenTimestamps(t *testing.T, data []byte) {
  	// On some processors cputicks (used to generate trace timestamps)
  	// produce non-monotonic timestamps. It is important that the parser
  	// distinguishes logically inconsistent traces (e.g. missing, excessive
  	// or misordered events) from broken timestamps. The former is a bug
  	// in tracer, the latter is a machine issue.
  	// So now that we have a consistent trace, test that (1) parser does
  	// not return a logical error in case of broken timestamps
  	// and (2) broken timestamps are eventually detected and reported.
  	trace.BreakTimestampsForTesting = true
  	defer func() {
  		trace.BreakTimestampsForTesting = false
  	}()
  	for i := 0; i < 1e4; i++ {
  		_, err := trace.Parse(bytes.NewReader(data), "")
  		if err == trace.ErrTimeOrder {
  			return
  		}
  		if err != nil {
  			t.Fatalf("failed to parse trace: %v", err)
  		}
  	}
  }
  
  func TestTraceStress(t *testing.T) {
  	var wg sync.WaitGroup
  	done := make(chan bool)
  
  	// Create a goroutine blocked before tracing.
  	wg.Add(1)
  	go func() {
  		<-done
  		wg.Done()
  	}()
  
  	// Create a goroutine blocked in syscall before tracing.
  	rp, wp, err := os.Pipe()
  	if err != nil {
  		t.Fatalf("failed to create pipe: %v", err)
  	}
  	defer func() {
  		rp.Close()
  		wp.Close()
  	}()
  	wg.Add(1)
  	go func() {
  		var tmp [1]byte
  		rp.Read(tmp[:])
  		<-done
  		wg.Done()
  	}()
  	time.Sleep(time.Millisecond) // give the goroutine above time to block
  
  	buf := new(bytes.Buffer)
  	if err := Start(buf); err != nil {
  		t.Fatalf("failed to start tracing: %v", err)
  	}
  
  	procs := runtime.GOMAXPROCS(10)
  	time.Sleep(50 * time.Millisecond) // test proc stop/start events
  
  	go func() {
  		runtime.LockOSThread()
  		for {
  			select {
  			case <-done:
  				return
  			default:
  				runtime.Gosched()
  			}
  		}
  	}()
  
  	runtime.GC()
  	// Trigger GC from malloc.
  	n := int(1e3)
  	if runtime.GOOS == "openbsd" && runtime.GOARCH == "arm" {
  		// Reduce allocation to avoid running out of
  		// memory on the builder - see issue/12032.
  		n = 512
  	}
  	for i := 0; i < n; i++ {
  		_ = make([]byte, 1<<20)
  	}
  
  	// Create a bunch of busy goroutines to load all Ps.
  	for p := 0; p < 10; p++ {
  		wg.Add(1)
  		go func() {
  			// Do something useful.
  			tmp := make([]byte, 1<<16)
  			for i := range tmp {
  				tmp[i]++
  			}
  			_ = tmp
  			<-done
  			wg.Done()
  		}()
  	}
  
  	// Block in syscall.
  	wg.Add(1)
  	go func() {
  		var tmp [1]byte
  		rp.Read(tmp[:])
  		<-done
  		wg.Done()
  	}()
  
  	// Test timers.
  	timerDone := make(chan bool)
  	go func() {
  		time.Sleep(time.Millisecond)
  		timerDone <- true
  	}()
  	<-timerDone
  
  	// A bit of network.
  	ln, err := net.Listen("tcp", "127.0.0.1:0")
  	if err != nil {
  		t.Fatalf("listen failed: %v", err)
  	}
  	defer ln.Close()
  	go func() {
  		c, err := ln.Accept()
  		if err != nil {
  			return
  		}
  		time.Sleep(time.Millisecond)
  		var buf [1]byte
  		c.Write(buf[:])
  		c.Close()
  	}()
  	c, err := net.Dial("tcp", ln.Addr().String())
  	if err != nil {
  		t.Fatalf("dial failed: %v", err)
  	}
  	var tmp [1]byte
  	c.Read(tmp[:])
  	c.Close()
  
  	go func() {
  		runtime.Gosched()
  		select {}
  	}()
  
  	// Unblock helper goroutines and wait them to finish.
  	wp.Write(tmp[:])
  	wp.Write(tmp[:])
  	close(done)
  	wg.Wait()
  
  	runtime.GOMAXPROCS(procs)
  
  	Stop()
  	saveTrace(t, buf, "TestTraceStress")
  	trace := buf.Bytes()
  	parseTrace(t, buf)
  	testBrokenTimestamps(t, trace)
  }
  
  // Do a bunch of various stuff (timers, GC, network, etc) in a separate goroutine.
  // And concurrently with all that start/stop trace 3 times.
  func TestTraceStressStartStop(t *testing.T) {
  	defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(8))
  	outerDone := make(chan bool)
  
  	go func() {
  		defer func() {
  			outerDone <- true
  		}()
  
  		var wg sync.WaitGroup
  		done := make(chan bool)
  
  		wg.Add(1)
  		go func() {
  			<-done
  			wg.Done()
  		}()
  
  		rp, wp, err := os.Pipe()
  		if err != nil {
  			t.Errorf("failed to create pipe: %v", err)
  			return
  		}
  		defer func() {
  			rp.Close()
  			wp.Close()
  		}()
  		wg.Add(1)
  		go func() {
  			var tmp [1]byte
  			rp.Read(tmp[:])
  			<-done
  			wg.Done()
  		}()
  		time.Sleep(time.Millisecond)
  
  		go func() {
  			runtime.LockOSThread()
  			for {
  				select {
  				case <-done:
  					return
  				default:
  					runtime.Gosched()
  				}
  			}
  		}()
  
  		runtime.GC()
  		// Trigger GC from malloc.
  		n := int(1e3)
  		if runtime.GOOS == "openbsd" && runtime.GOARCH == "arm" {
  			// Reduce allocation to avoid running out of
  			// memory on the builder - see issue/12032.
  			n = 512
  		}
  		for i := 0; i < n; i++ {
  			_ = make([]byte, 1<<20)
  		}
  
  		// Create a bunch of busy goroutines to load all Ps.
  		for p := 0; p < 10; p++ {
  			wg.Add(1)
  			go func() {
  				// Do something useful.
  				tmp := make([]byte, 1<<16)
  				for i := range tmp {
  					tmp[i]++
  				}
  				_ = tmp
  				<-done
  				wg.Done()
  			}()
  		}
  
  		// Block in syscall.
  		wg.Add(1)
  		go func() {
  			var tmp [1]byte
  			rp.Read(tmp[:])
  			<-done
  			wg.Done()
  		}()
  
  		runtime.GOMAXPROCS(runtime.GOMAXPROCS(1))
  
  		// Test timers.
  		timerDone := make(chan bool)
  		go func() {
  			time.Sleep(time.Millisecond)
  			timerDone <- true
  		}()
  		<-timerDone
  
  		// A bit of network.
  		ln, err := net.Listen("tcp", "127.0.0.1:0")
  		if err != nil {
  			t.Errorf("listen failed: %v", err)
  			return
  		}
  		defer ln.Close()
  		go func() {
  			c, err := ln.Accept()
  			if err != nil {
  				return
  			}
  			time.Sleep(time.Millisecond)
  			var buf [1]byte
  			c.Write(buf[:])
  			c.Close()
  		}()
  		c, err := net.Dial("tcp", ln.Addr().String())
  		if err != nil {
  			t.Errorf("dial failed: %v", err)
  			return
  		}
  		var tmp [1]byte
  		c.Read(tmp[:])
  		c.Close()
  
  		go func() {
  			runtime.Gosched()
  			select {}
  		}()
  
  		// Unblock helper goroutines and wait them to finish.
  		wp.Write(tmp[:])
  		wp.Write(tmp[:])
  		close(done)
  		wg.Wait()
  	}()
  
  	for i := 0; i < 3; i++ {
  		buf := new(bytes.Buffer)
  		if err := Start(buf); err != nil {
  			t.Fatalf("failed to start tracing: %v", err)
  		}
  		time.Sleep(time.Millisecond)
  		Stop()
  		saveTrace(t, buf, "TestTraceStressStartStop")
  		trace := buf.Bytes()
  		parseTrace(t, buf)
  		testBrokenTimestamps(t, trace)
  	}
  	<-outerDone
  }
  
  func TestTraceFutileWakeup(t *testing.T) {
  	buf := new(bytes.Buffer)
  	if err := Start(buf); err != nil {
  		t.Fatalf("failed to start tracing: %v", err)
  	}
  
  	defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(8))
  	c0 := make(chan int, 1)
  	c1 := make(chan int, 1)
  	c2 := make(chan int, 1)
  	const procs = 2
  	var done sync.WaitGroup
  	done.Add(4 * procs)
  	for p := 0; p < procs; p++ {
  		const iters = 1e3
  		go func() {
  			for i := 0; i < iters; i++ {
  				runtime.Gosched()
  				c0 <- 0
  			}
  			done.Done()
  		}()
  		go func() {
  			for i := 0; i < iters; i++ {
  				runtime.Gosched()
  				<-c0
  			}
  			done.Done()
  		}()
  		go func() {
  			for i := 0; i < iters; i++ {
  				runtime.Gosched()
  				select {
  				case c1 <- 0:
  				case c2 <- 0:
  				}
  			}
  			done.Done()
  		}()
  		go func() {
  			for i := 0; i < iters; i++ {
  				runtime.Gosched()
  				select {
  				case <-c1:
  				case <-c2:
  				}
  			}
  			done.Done()
  		}()
  	}
  	done.Wait()
  
  	Stop()
  	saveTrace(t, buf, "TestTraceFutileWakeup")
  	events, _ := parseTrace(t, buf)
  	// Check that (1) trace does not contain EvFutileWakeup events and
  	// (2) there are no consecutive EvGoBlock/EvGCStart/EvGoBlock events
  	// (we call runtime.Gosched between all operations, so these would be futile wakeups).
  	gs := make(map[uint64]int)
  	for _, ev := range events {
  		switch ev.Type {
  		case trace.EvFutileWakeup:
  			t.Fatalf("found EvFutileWakeup event")
  		case trace.EvGoBlockSend, trace.EvGoBlockRecv, trace.EvGoBlockSelect:
  			if gs[ev.G] == 2 {
  				t.Fatalf("goroutine %v blocked on %v at %v right after start",
  					ev.G, trace.EventDescriptions[ev.Type].Name, ev.Ts)
  			}
  			if gs[ev.G] == 1 {
  				t.Fatalf("goroutine %v blocked on %v at %v while blocked",
  					ev.G, trace.EventDescriptions[ev.Type].Name, ev.Ts)
  			}
  			gs[ev.G] = 1
  		case trace.EvGoStart:
  			if gs[ev.G] == 1 {
  				gs[ev.G] = 2
  			}
  		default:
  			delete(gs, ev.G)
  		}
  	}
  }
  
  func saveTrace(t *testing.T, buf *bytes.Buffer, name string) {
  	if !*saveTraces {
  		return
  	}
  	if err := ioutil.WriteFile(name+".trace", buf.Bytes(), 0600); err != nil {
  		t.Errorf("failed to write trace file: %s", err)
  	}
  }
  

View as plain text