github.com/megatontech/mynoteforgo@v0.0.0-20200507084910-5d0c6ea6e890/源码/cmd/trace/annotations_test.go (about) 1 // Copyright 2018 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 // +build !js 6 7 package main 8 9 import ( 10 "bytes" 11 "context" 12 "flag" 13 "fmt" 14 traceparser "internal/trace" 15 "io/ioutil" 16 "reflect" 17 "runtime/debug" 18 "runtime/trace" 19 "sort" 20 "sync" 21 "testing" 22 "time" 23 ) 24 25 var saveTraces = flag.Bool("savetraces", false, "save traces collected by tests") 26 27 func TestOverlappingDuration(t *testing.T) { 28 cases := []struct { 29 start0, end0, start1, end1 int64 30 want time.Duration 31 }{ 32 { 33 1, 10, 11, 20, 0, 34 }, 35 { 36 1, 10, 5, 20, 5 * time.Nanosecond, 37 }, 38 { 39 1, 10, 2, 8, 6 * time.Nanosecond, 40 }, 41 } 42 43 for _, tc := range cases { 44 s0, e0, s1, e1 := tc.start0, tc.end0, tc.start1, tc.end1 45 if got := overlappingDuration(s0, e0, s1, e1); got != tc.want { 46 t.Errorf("overlappingDuration(%d, %d, %d, %d)=%v; want %v", s0, e0, s1, e1, got, tc.want) 47 } 48 if got := overlappingDuration(s1, e1, s0, e0); got != tc.want { 49 t.Errorf("overlappingDuration(%d, %d, %d, %d)=%v; want %v", s1, e1, s0, e0, got, tc.want) 50 } 51 } 52 } 53 54 // prog0 starts three goroutines. 55 // 56 // goroutine 1: taskless region 57 // goroutine 2: starts task0, do work in task0.region0, starts task1 which ends immediately. 58 // goroutine 3: do work in task0.region1 and task0.region2, ends task0 59 func prog0() { 60 ctx := context.Background() 61 62 var wg sync.WaitGroup 63 64 wg.Add(1) 65 go func() { // goroutine 1 66 defer wg.Done() 67 trace.WithRegion(ctx, "taskless.region", func() { 68 trace.Log(ctx, "key0", "val0") 69 }) 70 }() 71 72 wg.Add(1) 73 go func() { // goroutine 2 74 defer wg.Done() 75 ctx, task := trace.NewTask(ctx, "task0") 76 trace.WithRegion(ctx, "task0.region0", func() { 77 wg.Add(1) 78 go func() { // goroutine 3 79 defer wg.Done() 80 defer task.End() 81 trace.WithRegion(ctx, "task0.region1", func() { 82 trace.WithRegion(ctx, "task0.region2", func() { 83 trace.Log(ctx, "key2", "val2") 84 }) 85 trace.Log(ctx, "key1", "val1") 86 }) 87 }() 88 }) 89 ctx2, task2 := trace.NewTask(ctx, "task1") 90 trace.Log(ctx2, "key3", "val3") 91 task2.End() 92 }() 93 wg.Wait() 94 } 95 96 func TestAnalyzeAnnotations(t *testing.T) { 97 // TODO: classify taskless regions 98 99 // Run prog0 and capture the execution trace. 100 if err := traceProgram(t, prog0, "TestAnalyzeAnnotations"); err != nil { 101 t.Fatalf("failed to trace the program: %v", err) 102 } 103 104 res, err := analyzeAnnotations() 105 if err != nil { 106 t.Fatalf("failed to analyzeAnnotations: %v", err) 107 } 108 109 // For prog0, we expect 110 // - task with name = "task0", with three regions. 111 // - task with name = "task1", with no region. 112 wantTasks := map[string]struct { 113 complete bool 114 goroutines int 115 regions []string 116 }{ 117 "task0": { 118 complete: true, 119 goroutines: 2, 120 regions: []string{"task0.region0", "", "task0.region1", "task0.region2"}, 121 }, 122 "task1": { 123 complete: true, 124 goroutines: 1, 125 }, 126 } 127 128 for _, task := range res.tasks { 129 want, ok := wantTasks[task.name] 130 if !ok { 131 t.Errorf("unexpected task: %s", task) 132 continue 133 } 134 if task.complete() != want.complete || len(task.goroutines) != want.goroutines || !reflect.DeepEqual(regionNames(task), want.regions) { 135 t.Errorf("got task %v; want %+v", task, want) 136 } 137 138 delete(wantTasks, task.name) 139 } 140 if len(wantTasks) > 0 { 141 t.Errorf("no more tasks; want %+v", wantTasks) 142 } 143 144 wantRegions := []string{ 145 "", // an auto-created region for the goroutine 3 146 "taskless.region", 147 "task0.region0", 148 "task0.region1", 149 "task0.region2", 150 } 151 var gotRegions []string 152 for regionID := range res.regions { 153 gotRegions = append(gotRegions, regionID.Type) 154 } 155 156 sort.Strings(wantRegions) 157 sort.Strings(gotRegions) 158 if !reflect.DeepEqual(gotRegions, wantRegions) { 159 t.Errorf("got regions %q, want regions %q", gotRegions, wantRegions) 160 } 161 } 162 163 // prog1 creates a task hierarchy consisting of three tasks. 164 func prog1() { 165 ctx := context.Background() 166 ctx1, task1 := trace.NewTask(ctx, "task1") 167 defer task1.End() 168 trace.WithRegion(ctx1, "task1.region", func() { 169 ctx2, task2 := trace.NewTask(ctx1, "task2") 170 defer task2.End() 171 trace.WithRegion(ctx2, "task2.region", func() { 172 ctx3, task3 := trace.NewTask(ctx2, "task3") 173 defer task3.End() 174 trace.WithRegion(ctx3, "task3.region", func() { 175 }) 176 }) 177 }) 178 } 179 180 func TestAnalyzeAnnotationTaskTree(t *testing.T) { 181 // Run prog1 and capture the execution trace. 182 if err := traceProgram(t, prog1, "TestAnalyzeAnnotationTaskTree"); err != nil { 183 t.Fatalf("failed to trace the program: %v", err) 184 } 185 186 res, err := analyzeAnnotations() 187 if err != nil { 188 t.Fatalf("failed to analyzeAnnotations: %v", err) 189 } 190 tasks := res.tasks 191 192 // For prog0, we expect 193 // - task with name = "", with taskless.region in regions. 194 // - task with name = "task0", with three regions. 195 wantTasks := map[string]struct { 196 parent string 197 children []string 198 regions []string 199 }{ 200 "task1": { 201 parent: "", 202 children: []string{"task2"}, 203 regions: []string{"task1.region"}, 204 }, 205 "task2": { 206 parent: "task1", 207 children: []string{"task3"}, 208 regions: []string{"task2.region"}, 209 }, 210 "task3": { 211 parent: "task2", 212 children: nil, 213 regions: []string{"task3.region"}, 214 }, 215 } 216 217 for _, task := range tasks { 218 want, ok := wantTasks[task.name] 219 if !ok { 220 t.Errorf("unexpected task: %s", task) 221 continue 222 } 223 delete(wantTasks, task.name) 224 225 if parentName(task) != want.parent || 226 !reflect.DeepEqual(childrenNames(task), want.children) || 227 !reflect.DeepEqual(regionNames(task), want.regions) { 228 t.Errorf("got %v; want %+v", task, want) 229 } 230 } 231 232 if len(wantTasks) > 0 { 233 t.Errorf("no more tasks; want %+v", wantTasks) 234 } 235 } 236 237 // prog2 starts two tasks; "taskWithGC" that overlaps with GC 238 // and "taskWithoutGC" that doesn't. In order to run this reliably, 239 // the caller needs to set up to prevent GC from running automatically. 240 // prog2 returns the upper-bound gc time that overlaps with the first task. 241 func prog2() (gcTime time.Duration) { 242 ch := make(chan bool) 243 ctx1, task := trace.NewTask(context.Background(), "taskWithGC") 244 trace.WithRegion(ctx1, "taskWithGC.region1", func() { 245 go func() { 246 defer trace.StartRegion(ctx1, "taskWithGC.region2").End() 247 <-ch 248 }() 249 s := time.Now() 250 debug.FreeOSMemory() // task1 affected by gc 251 gcTime = time.Since(s) 252 close(ch) 253 }) 254 task.End() 255 256 ctx2, task2 := trace.NewTask(context.Background(), "taskWithoutGC") 257 trace.WithRegion(ctx2, "taskWithoutGC.region1", func() { 258 // do nothing. 259 }) 260 task2.End() 261 return gcTime 262 } 263 264 func TestAnalyzeAnnotationGC(t *testing.T) { 265 err := traceProgram(t, func() { 266 oldGC := debug.SetGCPercent(10000) // gc, and effectively disable GC 267 defer debug.SetGCPercent(oldGC) 268 prog2() 269 }, "TestAnalyzeAnnotationGC") 270 if err != nil { 271 t.Fatalf("failed to trace the program: %v", err) 272 } 273 274 res, err := analyzeAnnotations() 275 if err != nil { 276 t.Fatalf("failed to analyzeAnnotations: %v", err) 277 } 278 279 // Check collected GC Start events are all sorted and non-overlapping. 280 lastTS := int64(0) 281 for i, ev := range res.gcEvents { 282 if ev.Type != traceparser.EvGCStart { 283 t.Errorf("unwanted event in gcEvents: %v", ev) 284 } 285 if i > 0 && lastTS > ev.Ts { 286 t.Errorf("overlapping GC events:\n%d: %v\n%d: %v", i-1, res.gcEvents[i-1], i, res.gcEvents[i]) 287 } 288 if ev.Link != nil { 289 lastTS = ev.Link.Ts 290 } 291 } 292 293 // Check whether only taskWithGC reports overlapping duration. 294 for _, task := range res.tasks { 295 got := task.overlappingGCDuration(res.gcEvents) 296 switch task.name { 297 case "taskWithoutGC": 298 if got != 0 { 299 t.Errorf("%s reported %v as overlapping GC time; want 0: %v", task.name, got, task) 300 } 301 case "taskWithGC": 302 upperBound := task.duration() 303 // TODO(hyangah): a tighter upper bound is gcTime, but 304 // use of it will make the test flaky due to the issue 305 // described in golang.org/issue/16755. Tighten the upper 306 // bound when the issue with the timestamp computed 307 // based on clockticks is resolved. 308 if got <= 0 || got > upperBound { 309 t.Errorf("%s reported %v as overlapping GC time; want (0, %v):\n%v", task.name, got, upperBound, task) 310 buf := new(bytes.Buffer) 311 fmt.Fprintln(buf, "GC Events") 312 for _, ev := range res.gcEvents { 313 fmt.Fprintf(buf, " %s -> %s\n", ev, ev.Link) 314 } 315 fmt.Fprintln(buf, "Events in Task") 316 for i, ev := range task.events { 317 fmt.Fprintf(buf, " %d: %s\n", i, ev) 318 } 319 320 t.Logf("\n%s", buf) 321 } 322 } 323 } 324 } 325 326 // traceProgram runs the provided function while tracing is enabled, 327 // parses the captured trace, and sets the global trace loader to 328 // point to the parsed trace. 329 // 330 // If savetraces flag is set, the captured trace will be saved in the named file. 331 func traceProgram(t *testing.T, f func(), name string) error { 332 t.Helper() 333 buf := new(bytes.Buffer) 334 if err := trace.Start(buf); err != nil { 335 return err 336 } 337 f() 338 trace.Stop() 339 340 saveTrace(buf, name) 341 res, err := traceparser.Parse(buf, name+".faketrace") 342 if err == traceparser.ErrTimeOrder { 343 t.Skipf("skipping due to golang.org/issue/16755: %v", err) 344 } else if err != nil { 345 return err 346 } 347 348 swapLoaderData(res, err) 349 return nil 350 } 351 352 func regionNames(task *taskDesc) (ret []string) { 353 for _, s := range task.regions { 354 ret = append(ret, s.Name) 355 } 356 return ret 357 } 358 359 func parentName(task *taskDesc) string { 360 if task.parent != nil { 361 return task.parent.name 362 } 363 return "" 364 } 365 366 func childrenNames(task *taskDesc) (ret []string) { 367 for _, s := range task.children { 368 ret = append(ret, s.name) 369 } 370 return ret 371 } 372 373 func swapLoaderData(res traceparser.ParseResult, err error) { 374 // swap loader's data. 375 parseTrace() // fool loader.once. 376 377 loader.res = res 378 loader.err = err 379 380 analyzeGoroutines(nil) // fool gsInit once. 381 gs = traceparser.GoroutineStats(res.Events) 382 383 } 384 385 func saveTrace(buf *bytes.Buffer, name string) { 386 if !*saveTraces { 387 return 388 } 389 if err := ioutil.WriteFile(name+".trace", buf.Bytes(), 0600); err != nil { 390 panic(fmt.Errorf("failed to write trace file: %v", err)) 391 } 392 }