trace_test.go

Documentation: runtime/trace

		 1  // Copyright 2014 The Go Authors. All rights reserved.
		 2  // Use of this source code is governed by a BSD-style
		 3  // license that can be found in the LICENSE file.
		 4  
		 5  package trace_test
		 6  
		 7  import (
		 8  	"bytes"
		 9  	"flag"
		10  	"internal/race"
		11  	"internal/trace"
		12  	"io"
		13  	"net"
		14  	"os"
		15  	"runtime"
		16  	. "runtime/trace"
		17  	"strconv"
		18  	"sync"
		19  	"testing"
		20  	"time"
		21  )
		22  
		23  var (
		24  	saveTraces = flag.Bool("savetraces", false, "save traces collected by tests")
		25  )
		26  
		27  // TestEventBatch tests Flush calls that happen during Start
		28  // don't produce corrupted traces.
		29  func TestEventBatch(t *testing.T) {
		30  	if race.Enabled {
		31  		t.Skip("skipping in race mode")
		32  	}
		33  	if IsEnabled() {
		34  		t.Skip("skipping because -test.trace is set")
		35  	}
		36  	if testing.Short() {
		37  		t.Skip("skipping in short mode")
		38  	}
		39  	// During Start, bunch of records are written to reflect the current
		40  	// snapshot of the program, including state of each goroutines.
		41  	// And some string constants are written to the trace to aid trace
		42  	// parsing. This test checks Flush of the buffer occurred during
		43  	// this process doesn't cause corrupted traces.
		44  	// When a Flush is called during Start is complicated
		45  	// so we test with a range of number of goroutines hoping that one
		46  	// of them triggers Flush.
		47  	// This range was chosen to fill up a ~64KB buffer with traceEvGoCreate
		48  	// and traceEvGoWaiting events (12~13bytes per goroutine).
		49  	for g := 4950; g < 5050; g++ {
		50  		n := g
		51  		t.Run("G="+strconv.Itoa(n), func(t *testing.T) {
		52  			var wg sync.WaitGroup
		53  			wg.Add(n)
		54  
		55  			in := make(chan bool, 1000)
		56  			for i := 0; i < n; i++ {
		57  				go func() {
		58  					<-in
		59  					wg.Done()
		60  				}()
		61  			}
		62  			buf := new(bytes.Buffer)
		63  			if err := Start(buf); err != nil {
		64  				t.Fatalf("failed to start tracing: %v", err)
		65  			}
		66  
		67  			for i := 0; i < n; i++ {
		68  				in <- true
		69  			}
		70  			wg.Wait()
		71  			Stop()
		72  
		73  			_, err := trace.Parse(buf, "")
		74  			if err == trace.ErrTimeOrder {
		75  				t.Skipf("skipping trace: %v", err)
		76  			}
		77  
		78  			if err != nil {
		79  				t.Fatalf("failed to parse trace: %v", err)
		80  			}
		81  		})
		82  	}
		83  }
		84  
		85  func TestTraceStartStop(t *testing.T) {
		86  	if IsEnabled() {
		87  		t.Skip("skipping because -test.trace is set")
		88  	}
		89  	buf := new(bytes.Buffer)
		90  	if err := Start(buf); err != nil {
		91  		t.Fatalf("failed to start tracing: %v", err)
		92  	}
		93  	Stop()
		94  	size := buf.Len()
		95  	if size == 0 {
		96  		t.Fatalf("trace is empty")
		97  	}
		98  	time.Sleep(100 * time.Millisecond)
		99  	if size != buf.Len() {
	 100  		t.Fatalf("trace writes after stop: %v -> %v", size, buf.Len())
	 101  	}
	 102  	saveTrace(t, buf, "TestTraceStartStop")
	 103  }
	 104  
	 105  func TestTraceDoubleStart(t *testing.T) {
	 106  	if IsEnabled() {
	 107  		t.Skip("skipping because -test.trace is set")
	 108  	}
	 109  	Stop()
	 110  	buf := new(bytes.Buffer)
	 111  	if err := Start(buf); err != nil {
	 112  		t.Fatalf("failed to start tracing: %v", err)
	 113  	}
	 114  	if err := Start(buf); err == nil {
	 115  		t.Fatalf("succeed to start tracing second time")
	 116  	}
	 117  	Stop()
	 118  	Stop()
	 119  }
	 120  
	 121  func TestTrace(t *testing.T) {
	 122  	if IsEnabled() {
	 123  		t.Skip("skipping because -test.trace is set")
	 124  	}
	 125  	buf := new(bytes.Buffer)
	 126  	if err := Start(buf); err != nil {
	 127  		t.Fatalf("failed to start tracing: %v", err)
	 128  	}
	 129  	Stop()
	 130  	saveTrace(t, buf, "TestTrace")
	 131  	_, err := trace.Parse(buf, "")
	 132  	if err == trace.ErrTimeOrder {
	 133  		t.Skipf("skipping trace: %v", err)
	 134  	}
	 135  	if err != nil {
	 136  		t.Fatalf("failed to parse trace: %v", err)
	 137  	}
	 138  }
	 139  
	 140  func parseTrace(t *testing.T, r io.Reader) ([]*trace.Event, map[uint64]*trace.GDesc) {
	 141  	res, err := trace.Parse(r, "")
	 142  	if err == trace.ErrTimeOrder {
	 143  		t.Skipf("skipping trace: %v", err)
	 144  	}
	 145  	if err != nil {
	 146  		t.Fatalf("failed to parse trace: %v", err)
	 147  	}
	 148  	gs := trace.GoroutineStats(res.Events)
	 149  	for goid := range gs {
	 150  		// We don't do any particular checks on the result at the moment.
	 151  		// But still check that RelatedGoroutines does not crash, hang, etc.
	 152  		_ = trace.RelatedGoroutines(res.Events, goid)
	 153  	}
	 154  	return res.Events, gs
	 155  }
	 156  
	 157  func testBrokenTimestamps(t *testing.T, data []byte) {
	 158  	// On some processors cputicks (used to generate trace timestamps)
	 159  	// produce non-monotonic timestamps. It is important that the parser
	 160  	// distinguishes logically inconsistent traces (e.g. missing, excessive
	 161  	// or misordered events) from broken timestamps. The former is a bug
	 162  	// in tracer, the latter is a machine issue.
	 163  	// So now that we have a consistent trace, test that (1) parser does
	 164  	// not return a logical error in case of broken timestamps
	 165  	// and (2) broken timestamps are eventually detected and reported.
	 166  	trace.BreakTimestampsForTesting = true
	 167  	defer func() {
	 168  		trace.BreakTimestampsForTesting = false
	 169  	}()
	 170  	for i := 0; i < 1e4; i++ {
	 171  		_, err := trace.Parse(bytes.NewReader(data), "")
	 172  		if err == trace.ErrTimeOrder {
	 173  			return
	 174  		}
	 175  		if err != nil {
	 176  			t.Fatalf("failed to parse trace: %v", err)
	 177  		}
	 178  	}
	 179  }
	 180  
	 181  func TestTraceStress(t *testing.T) {
	 182  	if runtime.GOOS == "js" {
	 183  		t.Skip("no os.Pipe on js")
	 184  	}
	 185  	if IsEnabled() {
	 186  		t.Skip("skipping because -test.trace is set")
	 187  	}
	 188  	if testing.Short() {
	 189  		t.Skip("skipping in -short mode")
	 190  	}
	 191  
	 192  	var wg sync.WaitGroup
	 193  	done := make(chan bool)
	 194  
	 195  	// Create a goroutine blocked before tracing.
	 196  	wg.Add(1)
	 197  	go func() {
	 198  		<-done
	 199  		wg.Done()
	 200  	}()
	 201  
	 202  	// Create a goroutine blocked in syscall before tracing.
	 203  	rp, wp, err := os.Pipe()
	 204  	if err != nil {
	 205  		t.Fatalf("failed to create pipe: %v", err)
	 206  	}
	 207  	defer func() {
	 208  		rp.Close()
	 209  		wp.Close()
	 210  	}()
	 211  	wg.Add(1)
	 212  	go func() {
	 213  		var tmp [1]byte
	 214  		rp.Read(tmp[:])
	 215  		<-done
	 216  		wg.Done()
	 217  	}()
	 218  	time.Sleep(time.Millisecond) // give the goroutine above time to block
	 219  
	 220  	buf := new(bytes.Buffer)
	 221  	if err := Start(buf); err != nil {
	 222  		t.Fatalf("failed to start tracing: %v", err)
	 223  	}
	 224  
	 225  	procs := runtime.GOMAXPROCS(10)
	 226  	time.Sleep(50 * time.Millisecond) // test proc stop/start events
	 227  
	 228  	go func() {
	 229  		runtime.LockOSThread()
	 230  		for {
	 231  			select {
	 232  			case <-done:
	 233  				return
	 234  			default:
	 235  				runtime.Gosched()
	 236  			}
	 237  		}
	 238  	}()
	 239  
	 240  	runtime.GC()
	 241  	// Trigger GC from malloc.
	 242  	n := int(1e3)
	 243  	if isMemoryConstrained() {
	 244  		// Reduce allocation to avoid running out of
	 245  		// memory on the builder - see issue/12032.
	 246  		n = 512
	 247  	}
	 248  	for i := 0; i < n; i++ {
	 249  		_ = make([]byte, 1<<20)
	 250  	}
	 251  
	 252  	// Create a bunch of busy goroutines to load all Ps.
	 253  	for p := 0; p < 10; p++ {
	 254  		wg.Add(1)
	 255  		go func() {
	 256  			// Do something useful.
	 257  			tmp := make([]byte, 1<<16)
	 258  			for i := range tmp {
	 259  				tmp[i]++
	 260  			}
	 261  			_ = tmp
	 262  			<-done
	 263  			wg.Done()
	 264  		}()
	 265  	}
	 266  
	 267  	// Block in syscall.
	 268  	wg.Add(1)
	 269  	go func() {
	 270  		var tmp [1]byte
	 271  		rp.Read(tmp[:])
	 272  		<-done
	 273  		wg.Done()
	 274  	}()
	 275  
	 276  	// Test timers.
	 277  	timerDone := make(chan bool)
	 278  	go func() {
	 279  		time.Sleep(time.Millisecond)
	 280  		timerDone <- true
	 281  	}()
	 282  	<-timerDone
	 283  
	 284  	// A bit of network.
	 285  	ln, err := net.Listen("tcp", "127.0.0.1:0")
	 286  	if err != nil {
	 287  		t.Fatalf("listen failed: %v", err)
	 288  	}
	 289  	defer ln.Close()
	 290  	go func() {
	 291  		c, err := ln.Accept()
	 292  		if err != nil {
	 293  			return
	 294  		}
	 295  		time.Sleep(time.Millisecond)
	 296  		var buf [1]byte
	 297  		c.Write(buf[:])
	 298  		c.Close()
	 299  	}()
	 300  	c, err := net.Dial("tcp", ln.Addr().String())
	 301  	if err != nil {
	 302  		t.Fatalf("dial failed: %v", err)
	 303  	}
	 304  	var tmp [1]byte
	 305  	c.Read(tmp[:])
	 306  	c.Close()
	 307  
	 308  	go func() {
	 309  		runtime.Gosched()
	 310  		select {}
	 311  	}()
	 312  
	 313  	// Unblock helper goroutines and wait them to finish.
	 314  	wp.Write(tmp[:])
	 315  	wp.Write(tmp[:])
	 316  	close(done)
	 317  	wg.Wait()
	 318  
	 319  	runtime.GOMAXPROCS(procs)
	 320  
	 321  	Stop()
	 322  	saveTrace(t, buf, "TestTraceStress")
	 323  	trace := buf.Bytes()
	 324  	parseTrace(t, buf)
	 325  	testBrokenTimestamps(t, trace)
	 326  }
	 327  
	 328  // isMemoryConstrained reports whether the current machine is likely
	 329  // to be memory constrained.
	 330  // This was originally for the openbsd/arm builder (Issue 12032).
	 331  // TODO: move this to testenv? Make this look at memory? Look at GO_BUILDER_NAME?
	 332  func isMemoryConstrained() bool {
	 333  	if runtime.GOOS == "plan9" {
	 334  		return true
	 335  	}
	 336  	switch runtime.GOARCH {
	 337  	case "arm", "mips", "mipsle":
	 338  		return true
	 339  	}
	 340  	return false
	 341  }
	 342  
	 343  // Do a bunch of various stuff (timers, GC, network, etc) in a separate goroutine.
	 344  // And concurrently with all that start/stop trace 3 times.
	 345  func TestTraceStressStartStop(t *testing.T) {
	 346  	if runtime.GOOS == "js" {
	 347  		t.Skip("no os.Pipe on js")
	 348  	}
	 349  	if IsEnabled() {
	 350  		t.Skip("skipping because -test.trace is set")
	 351  	}
	 352  	defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(8))
	 353  	outerDone := make(chan bool)
	 354  
	 355  	go func() {
	 356  		defer func() {
	 357  			outerDone <- true
	 358  		}()
	 359  
	 360  		var wg sync.WaitGroup
	 361  		done := make(chan bool)
	 362  
	 363  		wg.Add(1)
	 364  		go func() {
	 365  			<-done
	 366  			wg.Done()
	 367  		}()
	 368  
	 369  		rp, wp, err := os.Pipe()
	 370  		if err != nil {
	 371  			t.Errorf("failed to create pipe: %v", err)
	 372  			return
	 373  		}
	 374  		defer func() {
	 375  			rp.Close()
	 376  			wp.Close()
	 377  		}()
	 378  		wg.Add(1)
	 379  		go func() {
	 380  			var tmp [1]byte
	 381  			rp.Read(tmp[:])
	 382  			<-done
	 383  			wg.Done()
	 384  		}()
	 385  		time.Sleep(time.Millisecond)
	 386  
	 387  		go func() {
	 388  			runtime.LockOSThread()
	 389  			for {
	 390  				select {
	 391  				case <-done:
	 392  					return
	 393  				default:
	 394  					runtime.Gosched()
	 395  				}
	 396  			}
	 397  		}()
	 398  
	 399  		runtime.GC()
	 400  		// Trigger GC from malloc.
	 401  		n := int(1e3)
	 402  		if isMemoryConstrained() {
	 403  			// Reduce allocation to avoid running out of
	 404  			// memory on the builder.
	 405  			n = 512
	 406  		}
	 407  		for i := 0; i < n; i++ {
	 408  			_ = make([]byte, 1<<20)
	 409  		}
	 410  
	 411  		// Create a bunch of busy goroutines to load all Ps.
	 412  		for p := 0; p < 10; p++ {
	 413  			wg.Add(1)
	 414  			go func() {
	 415  				// Do something useful.
	 416  				tmp := make([]byte, 1<<16)
	 417  				for i := range tmp {
	 418  					tmp[i]++
	 419  				}
	 420  				_ = tmp
	 421  				<-done
	 422  				wg.Done()
	 423  			}()
	 424  		}
	 425  
	 426  		// Block in syscall.
	 427  		wg.Add(1)
	 428  		go func() {
	 429  			var tmp [1]byte
	 430  			rp.Read(tmp[:])
	 431  			<-done
	 432  			wg.Done()
	 433  		}()
	 434  
	 435  		runtime.GOMAXPROCS(runtime.GOMAXPROCS(1))
	 436  
	 437  		// Test timers.
	 438  		timerDone := make(chan bool)
	 439  		go func() {
	 440  			time.Sleep(time.Millisecond)
	 441  			timerDone <- true
	 442  		}()
	 443  		<-timerDone
	 444  
	 445  		// A bit of network.
	 446  		ln, err := net.Listen("tcp", "127.0.0.1:0")
	 447  		if err != nil {
	 448  			t.Errorf("listen failed: %v", err)
	 449  			return
	 450  		}
	 451  		defer ln.Close()
	 452  		go func() {
	 453  			c, err := ln.Accept()
	 454  			if err != nil {
	 455  				return
	 456  			}
	 457  			time.Sleep(time.Millisecond)
	 458  			var buf [1]byte
	 459  			c.Write(buf[:])
	 460  			c.Close()
	 461  		}()
	 462  		c, err := net.Dial("tcp", ln.Addr().String())
	 463  		if err != nil {
	 464  			t.Errorf("dial failed: %v", err)
	 465  			return
	 466  		}
	 467  		var tmp [1]byte
	 468  		c.Read(tmp[:])
	 469  		c.Close()
	 470  
	 471  		go func() {
	 472  			runtime.Gosched()
	 473  			select {}
	 474  		}()
	 475  
	 476  		// Unblock helper goroutines and wait them to finish.
	 477  		wp.Write(tmp[:])
	 478  		wp.Write(tmp[:])
	 479  		close(done)
	 480  		wg.Wait()
	 481  	}()
	 482  
	 483  	for i := 0; i < 3; i++ {
	 484  		buf := new(bytes.Buffer)
	 485  		if err := Start(buf); err != nil {
	 486  			t.Fatalf("failed to start tracing: %v", err)
	 487  		}
	 488  		time.Sleep(time.Millisecond)
	 489  		Stop()
	 490  		saveTrace(t, buf, "TestTraceStressStartStop")
	 491  		trace := buf.Bytes()
	 492  		parseTrace(t, buf)
	 493  		testBrokenTimestamps(t, trace)
	 494  	}
	 495  	<-outerDone
	 496  }
	 497  
	 498  func TestTraceFutileWakeup(t *testing.T) {
	 499  	if IsEnabled() {
	 500  		t.Skip("skipping because -test.trace is set")
	 501  	}
	 502  	buf := new(bytes.Buffer)
	 503  	if err := Start(buf); err != nil {
	 504  		t.Fatalf("failed to start tracing: %v", err)
	 505  	}
	 506  
	 507  	defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(8))
	 508  	c0 := make(chan int, 1)
	 509  	c1 := make(chan int, 1)
	 510  	c2 := make(chan int, 1)
	 511  	const procs = 2
	 512  	var done sync.WaitGroup
	 513  	done.Add(4 * procs)
	 514  	for p := 0; p < procs; p++ {
	 515  		const iters = 1e3
	 516  		go func() {
	 517  			for i := 0; i < iters; i++ {
	 518  				runtime.Gosched()
	 519  				c0 <- 0
	 520  			}
	 521  			done.Done()
	 522  		}()
	 523  		go func() {
	 524  			for i := 0; i < iters; i++ {
	 525  				runtime.Gosched()
	 526  				<-c0
	 527  			}
	 528  			done.Done()
	 529  		}()
	 530  		go func() {
	 531  			for i := 0; i < iters; i++ {
	 532  				runtime.Gosched()
	 533  				select {
	 534  				case c1 <- 0:
	 535  				case c2 <- 0:
	 536  				}
	 537  			}
	 538  			done.Done()
	 539  		}()
	 540  		go func() {
	 541  			for i := 0; i < iters; i++ {
	 542  				runtime.Gosched()
	 543  				select {
	 544  				case <-c1:
	 545  				case <-c2:
	 546  				}
	 547  			}
	 548  			done.Done()
	 549  		}()
	 550  	}
	 551  	done.Wait()
	 552  
	 553  	Stop()
	 554  	saveTrace(t, buf, "TestTraceFutileWakeup")
	 555  	events, _ := parseTrace(t, buf)
	 556  	// Check that (1) trace does not contain EvFutileWakeup events and
	 557  	// (2) there are no consecutive EvGoBlock/EvGCStart/EvGoBlock events
	 558  	// (we call runtime.Gosched between all operations, so these would be futile wakeups).
	 559  	gs := make(map[uint64]int)
	 560  	for _, ev := range events {
	 561  		switch ev.Type {
	 562  		case trace.EvFutileWakeup:
	 563  			t.Fatalf("found EvFutileWakeup event")
	 564  		case trace.EvGoBlockSend, trace.EvGoBlockRecv, trace.EvGoBlockSelect:
	 565  			if gs[ev.G] == 2 {
	 566  				t.Fatalf("goroutine %v blocked on %v at %v right after start",
	 567  					ev.G, trace.EventDescriptions[ev.Type].Name, ev.Ts)
	 568  			}
	 569  			if gs[ev.G] == 1 {
	 570  				t.Fatalf("goroutine %v blocked on %v at %v while blocked",
	 571  					ev.G, trace.EventDescriptions[ev.Type].Name, ev.Ts)
	 572  			}
	 573  			gs[ev.G] = 1
	 574  		case trace.EvGoStart:
	 575  			if gs[ev.G] == 1 {
	 576  				gs[ev.G] = 2
	 577  			}
	 578  		default:
	 579  			delete(gs, ev.G)
	 580  		}
	 581  	}
	 582  }
	 583  
	 584  func saveTrace(t *testing.T, buf *bytes.Buffer, name string) {
	 585  	if !*saveTraces {
	 586  		return
	 587  	}
	 588  	if err := os.WriteFile(name+".trace", buf.Bytes(), 0600); err != nil {
	 589  		t.Errorf("failed to write trace file: %s", err)
	 590  	}
	 591  }
	 592
View as plain text