blob: d315fad47179f56771961e95ea2a635470a03655 [file] [log] [blame]
// Copyright 2016 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.
//go:build !js
package main
import (
"context"
"internal/trace"
"internal/trace/traceviewer"
"internal/trace/traceviewer/format"
"io"
rtrace "runtime/trace"
"strings"
"sync"
"testing"
"time"
)
// stacks is a fake stack map populated for test.
type stacks map[uint64][]*trace.Frame
// add adds a stack with a single frame whose Fn field is
// set to the provided fname and returns a unique stack id.
func (s *stacks) add(fname string) uint64 {
if *s == nil {
*s = make(map[uint64][]*trace.Frame)
}
id := uint64(len(*s))
(*s)[id] = []*trace.Frame{{Fn: fname}}
return id
}
// TestGoroutineCount tests runnable/running goroutine counts computed by generateTrace
// remain in the valid range.
// - the counts must not be negative. generateTrace will return an error.
// - the counts must not include goroutines blocked waiting on channels or in syscall.
func TestGoroutineCount(t *testing.T) {
w := trace.NewWriter()
w.Emit(trace.EvBatch, 0, 0) // start of per-P batch event [pid, timestamp]
w.Emit(trace.EvFrequency, 1) // [ticks per second]
var s stacks
// In this test, we assume a valid trace contains EvGoWaiting or EvGoInSyscall
// event for every blocked goroutine.
// goroutine 10: blocked
w.Emit(trace.EvGoCreate, 1, 10, s.add("pkg.f1"), s.add("main.f1")) // [timestamp, new goroutine id, new stack id, stack id]
w.Emit(trace.EvGoWaiting, 1, 10) // [timestamp, goroutine id]
// goroutine 20: in syscall
w.Emit(trace.EvGoCreate, 1, 20, s.add("pkg.f2"), s.add("main.f2"))
w.Emit(trace.EvGoInSyscall, 1, 20) // [timestamp, goroutine id]
// goroutine 30: runnable
w.Emit(trace.EvGoCreate, 1, 30, s.add("pkg.f3"), s.add("main.f3"))
w.Emit(trace.EvProcStart, 2, 0) // [timestamp, thread id]
// goroutine 40: runnable->running->runnable
w.Emit(trace.EvGoCreate, 1, 40, s.add("pkg.f4"), s.add("main.f4"))
w.Emit(trace.EvGoStartLocal, 1, 40) // [timestamp, goroutine id]
w.Emit(trace.EvGoSched, 1, s.add("main.f4")) // [timestamp, stack]
res, err := trace.Parse(w, "")
if err != nil {
t.Fatalf("failed to parse test trace: %v", err)
}
res.Stacks = s // use fake stacks.
params := &traceParams{
parsed: res,
endTime: int64(1<<63 - 1),
}
// Use the default viewerDataTraceConsumer but replace
// consumeViewerEvent to intercept the ViewerEvents for testing.
c := traceviewer.ViewerDataTraceConsumer(io.Discard, 0, 1<<63-1)
c.ConsumeViewerEvent = func(ev *format.Event, _ bool) {
if ev.Name == "Goroutines" {
cnt := ev.Arg.(*format.GoroutineCountersArg)
if cnt.Runnable+cnt.Running > 2 {
t.Errorf("goroutine count=%+v; want no more than 2 goroutines in runnable/running state", cnt)
}
t.Logf("read %+v %+v", ev, cnt)
}
}
// If the counts drop below 0, generateTrace will return an error.
if err := generateTrace(params, c); err != nil {
t.Fatalf("generateTrace failed: %v", err)
}
}
func TestGoroutineFilter(t *testing.T) {
// Test that we handle state changes to selected goroutines
// caused by events on goroutines that are not selected.
var s stacks
w := trace.NewWriter()
w.Emit(trace.EvBatch, 0, 0) // start of per-P batch event [pid, timestamp]
w.Emit(trace.EvFrequency, 1) // [ticks per second]
// goroutine 10: blocked
w.Emit(trace.EvGoCreate, 1, 10, s.add("pkg.f1"), s.add("main.f1")) // [timestamp, new goroutine id, new stack id, stack id]
w.Emit(trace.EvGoWaiting, 1, 10) // [timestamp, goroutine id]
// goroutine 20: runnable->running->unblock 10
w.Emit(trace.EvGoCreate, 1, 20, s.add("pkg.f2"), s.add("main.f2"))
w.Emit(trace.EvGoStartLocal, 1, 20) // [timestamp, goroutine id]
w.Emit(trace.EvGoUnblockLocal, 1, 10, s.add("pkg.f2")) // [timestamp, goroutine id, stack]
w.Emit(trace.EvGoEnd, 1) // [timestamp]
// goroutine 10: runnable->running->block
w.Emit(trace.EvGoStartLocal, 1, 10) // [timestamp, goroutine id]
w.Emit(trace.EvGoBlock, 1, s.add("pkg.f3")) // [timestamp, stack]
res, err := trace.Parse(w, "")
if err != nil {
t.Fatalf("failed to parse test trace: %v", err)
}
res.Stacks = s // use fake stacks
params := &traceParams{
parsed: res,
endTime: int64(1<<63 - 1),
gs: map[uint64]bool{10: true},
}
c := traceviewer.ViewerDataTraceConsumer(io.Discard, 0, 1<<63-1)
if err := generateTrace(params, c); err != nil {
t.Fatalf("generateTrace failed: %v", err)
}
}
func TestPreemptedMarkAssist(t *testing.T) {
w := trace.NewWriter()
w.Emit(trace.EvBatch, 0, 0) // start of per-P batch event [pid, timestamp]
w.Emit(trace.EvFrequency, 1) // [ticks per second]
var s stacks
// goroutine 9999: running -> mark assisting -> preempted -> assisting -> running -> block
w.Emit(trace.EvGoCreate, 1, 9999, s.add("pkg.f1"), s.add("main.f1")) // [timestamp, new goroutine id, new stack id, stack id]
w.Emit(trace.EvGoStartLocal, 1, 9999) // [timestamp, goroutine id]
w.Emit(trace.EvGCMarkAssistStart, 1, s.add("main.f1")) // [timestamp, stack]
w.Emit(trace.EvGoPreempt, 1, s.add("main.f1")) // [timestamp, stack]
w.Emit(trace.EvGoStartLocal, 1, 9999) // [timestamp, goroutine id]
w.Emit(trace.EvGCMarkAssistDone, 1) // [timestamp]
w.Emit(trace.EvGoBlock, 1, s.add("main.f2")) // [timestamp, stack]
res, err := trace.Parse(w, "")
if err != nil {
t.Fatalf("failed to parse test trace: %v", err)
}
res.Stacks = s // use fake stacks
params := &traceParams{
parsed: res,
endTime: int64(1<<63 - 1),
}
c := traceviewer.ViewerDataTraceConsumer(io.Discard, 0, 1<<63-1)
marks := 0
c.ConsumeViewerEvent = func(ev *format.Event, _ bool) {
if strings.Contains(ev.Name, "MARK ASSIST") {
marks++
}
}
if err := generateTrace(params, c); err != nil {
t.Fatalf("generateTrace failed: %v", err)
}
if marks != 2 {
t.Errorf("Got %v MARK ASSIST events, want %v", marks, 2)
}
}
func TestFoo(t *testing.T) {
prog0 := func() {
ctx, task := rtrace.NewTask(context.Background(), "ohHappyDay")
rtrace.Log(ctx, "", "log before task ends")
task.End()
rtrace.Log(ctx, "", "log after task ends") // log after task ends
}
if err := traceProgram(t, prog0, "TestFoo"); err != nil {
t.Fatalf("failed to trace the program: %v", err)
}
res, err := parseTrace()
if err != nil {
t.Fatalf("failed to parse the trace: %v", err)
}
annotRes, _ := analyzeAnnotations()
var task *taskDesc
for _, t := range annotRes.tasks {
if t.name == "ohHappyDay" {
task = t
break
}
}
if task == nil {
t.Fatal("failed to locate expected task event")
}
params := &traceParams{
parsed: res,
mode: traceviewer.ModeTaskOriented,
startTime: task.firstTimestamp() - 1,
endTime: task.lastTimestamp() + 1,
tasks: []*taskDesc{task},
}
c := traceviewer.ViewerDataTraceConsumer(io.Discard, 0, 1<<63-1)
var logBeforeTaskEnd, logAfterTaskEnd bool
c.ConsumeViewerEvent = func(ev *format.Event, _ bool) {
if ev.Name == "log before task ends" {
logBeforeTaskEnd = true
}
if ev.Name == "log after task ends" {
logAfterTaskEnd = true
}
}
if err := generateTrace(params, c); err != nil {
t.Fatalf("generateTrace failed: %v", err)
}
if !logBeforeTaskEnd {
t.Error("failed to find 'log before task ends'")
}
if !logAfterTaskEnd {
t.Error("failed to find 'log after task ends'")
}
}
func TestDirectSemaphoreHandoff(t *testing.T) {
prog0 := func() {
var mu sync.Mutex
var wg sync.WaitGroup
mu.Lock()
// This is modeled after src/sync/mutex_test.go to trigger Mutex
// starvation mode, in which the goroutine that calls Unlock hands off
// both the semaphore and its remaining time slice. See issue 36186.
for i := 0; i < 2; i++ {
wg.Add(1)
go func() {
defer wg.Done()
for i := 0; i < 100; i++ {
mu.Lock()
time.Sleep(100 * time.Microsecond)
mu.Unlock()
}
}()
}
mu.Unlock()
wg.Wait()
}
if err := traceProgram(t, prog0, "TestDirectSemaphoreHandoff"); err != nil {
t.Fatalf("failed to trace the program: %v", err)
}
_, err := parseTrace()
if err != nil {
t.Fatalf("failed to parse the trace: %v", err)
}
}