From: Hana Kim <hakim@google.com>
Date: Fri, 23 Feb 2018 21:25:18 +0000 (-0500)
Subject: cmd/trace: trace error check and more logging in annotations test
X-Git-Tag: go1.11beta1~1448
X-Git-Url: http://www.git.cypherpunks.su/?a=commitdiff_plain;h=a5c987fcbb95db82ee2101a46503bc21bea1f2d9;p=gostls13.git

cmd/trace: trace error check and more logging in annotations test

This is for debugging the reported flaky tests.

Update #24081

Change-Id: Ica046928f675d69e38251a47a6f225efedce920c
Reviewed-on: https://go-review.googlesource.com/96855
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Heschi Kreinick <heschi@google.com>
---

diff --git a/src/cmd/trace/annotations_test.go b/src/cmd/trace/annotations_test.go
index e67e02b2db..539ad81ecb 100644
--- a/src/cmd/trace/annotations_test.go
+++ b/src/cmd/trace/annotations_test.go
@@ -63,7 +63,9 @@ func TestAnalyzeAnnotations(t *testing.T) {
 	// TODO: classify taskless spans
 
 	// Run prog0 and capture the execution trace.
-	traceProgram(prog0, "TestAnalyzeAnnotations")
+	if err := traceProgram(prog0, "TestAnalyzeAnnotations"); err != nil {
+		t.Fatalf("failed to trace the program: %v", err)
+	}
 
 	res, err := analyzeAnnotations()
 	if err != nil {
@@ -126,7 +128,9 @@ func prog1() {
 
 func TestAnalyzeAnnotationTaskTree(t *testing.T) {
 	// Run prog1 and capture the execution trace.
-	traceProgram(prog1, "TestAnalyzeAnnotationTaskTree")
+	if err := traceProgram(prog1, "TestAnalyzeAnnotationTaskTree"); err != nil {
+		t.Fatalf("failed to trace the program: %v", err)
+	}
 
 	res, err := analyzeAnnotations()
 	if err != nil {
@@ -208,12 +212,15 @@ func prog2() (gcTime time.Duration) {
 
 func TestAnalyzeAnnotationGC(t *testing.T) {
 	var gcTime time.Duration
-	traceProgram(func() {
+	err := traceProgram(func() {
 		oldGC := debug.SetGCPercent(10000) // gc, and effectively disable GC
 		defer debug.SetGCPercent(oldGC)
 
 		gcTime = prog2()
 	}, "TestAnalyzeAnnotationGC")
+	if err != nil {
+		t.Fatalf("failed to trace the program: %v", err)
+	}
 
 	res, err := analyzeAnnotations()
 	if err != nil {
@@ -241,6 +248,13 @@ func TestAnalyzeAnnotationGC(t *testing.T) {
 		case "taskWithGC":
 			if got <= 0 || got >= gcTime {
 				t.Errorf("%s reported %v as overlapping GC time; want (0, %v): %v", task.name, got, gcTime, task)
+				buf := new(bytes.Buffer)
+				fmt.Fprintln(buf, "GC Events")
+				for _, ev := range res.gcEvents {
+					fmt.Fprintf(buf, " %s\n", ev)
+				}
+				fmt.Fprintf(buf, "%s\n", task)
+				t.Logf("%s", buf)
 			}
 		case "taskWithoutGC":
 			if got != 0 {
@@ -264,7 +278,7 @@ func traceProgram(f func(), name string) error {
 	trace.Stop()
 
 	saveTrace(buf, name)
-	res, err := traceparser.Parse(buf, "")
+	res, err := traceparser.Parse(buf, name+".faketrace")
 	if err != nil {
 		return err
 	}