runtime/trace: implement annotation API

This implements the annotation API proposed in golang.org/cl/63274.

traceString is updated to protect the string map with trace.stringsLock
because the assumption that traceString is called by a single goroutine
(either at the beginning of tracing and at the end of tracing when
dumping all the symbols and function names) is no longer true.

traceString is used by the annotation apis (NewContext, StartSpan, Log)
to register frequently appearing strings (task and span names, and log
keys) after this change.

NewContext -> one or two records (EvString, EvUserTaskCreate)
end function -> one record (EvUserTaskEnd)
StartSpan -> one or two records (EvString, EvUserSpan)
span end function -> one or two records (EvString, EvUserSpan)
Log -> one or two records (EvString, EvUserLog)

EvUserLog record is of the typical record format written by traceEvent
except that it is followed by bytes that represents the value string.

In addition to runtime/trace change, this change includes
corresponding changes in internal/trace to parse the new record types.

Future work to improve efficiency:
  More efficient unique task id generation instead of atomic. (per-P
  counter).
  Instead of a centralized trace.stringsLock, consider using per-P
  string cache or something more efficient.

R=go1.11

Change-Id: Iec9276c6c51e5be441ccd52dec270f1e3b153970
Reviewed-on: https://go-review.googlesource.com/71690
Reviewed-by: Austin Clements <austin@google.com>

2 files changed, 94 insertions, 3 deletions

diff --git a/src/runtime/trace/annotation.go b/src/runtime/trace/annotation.go
index f34ec25f53..be92d52af8 100644
--- a/src/runtime/trace/annotation.go
+++ b/src/runtime/trace/annotation.go
@@ -72,9 +72,11 @@ type task struct {
 	// TODO(hyangah): record parent id?
 }
 
+var lastTaskID uint64 = 0 // task id issued last time
+
 func newID() uint64 {
-	// TODO(hyangah): implement
-	return 0
+	// TODO(hyangah): use per-P cache
+	return atomic.AddUint64(&lastTaskID, 1)
 }
 
 var bgTask = task{id: uint64(0)}
@@ -90,7 +92,10 @@ func Log(ctx context.Context, category, message string) {
 // Logf is like Log, but the value is formatted using the specified format spec.
 func Logf(ctx context.Context, category, format string, args ...interface{}) {
 	if IsEnabled() {
-		Log(ctx, category, fmt.Sprintf(format, args...))
+		// Ideally this should be just Log, but that will
+		// add one more frame in the stack trace.
+		id := fromContext(ctx).id
+		userLog(id, category, fmt.Sprintf(format, args...))
 	}
 }
 
diff --git a/src/runtime/trace/annotation_test.go b/src/runtime/trace/annotation_test.go
new file mode 100644
index 0000000000..c54eae3a96
--- /dev/null
+++ b/src/runtime/trace/annotation_test.go
@@ -0,0 +1,86 @@
+package trace_test
+
+import (
+	"bytes"
+	"context"
+	"internal/trace"
+	"reflect"
+	. "runtime/trace"
+	"sync"
+	"testing"
+)
+
+func TestUserTaskSpan(t *testing.T) {
+	bgctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+
+	// TODO(hyangah): test pre-existing spans don't cause troubles
+
+	buf := new(bytes.Buffer)
+	if err := Start(buf); err != nil {
+		t.Fatalf("failed to start tracing: %v", err)
+	}
+
+	// Beginning of traced execution
+	var wg sync.WaitGroup
+	ctx, end := NewContext(bgctx, "task0") // EvUserTaskCreate("task0")
+	wg.Add(1)
+	go func() {
+		defer wg.Done()
+		defer end() // EvUserTaskEnd("span0")
+
+		WithSpan(ctx, "span0", func(ctx context.Context) {
+			// EvUserSpanCreate("span0", start)
+			Log(ctx, "key0", "0123456789abcdef") // EvUserLog("task0", "key0", "0....f")
+			// EvUserSpan("span0", end)
+		})
+	}()
+	wg.Wait()
+	// End of traced execution
+	Stop()
+	saveTrace(t, buf, "TestUserTaskSpan")
+	res, err := trace.Parse(buf, "")
+	if err != nil {
+		t.Fatalf("Parse failed: %v", err)
+	}
+
+	// Check whether we see all user annotation related records in order
+	type testData struct {
+		typ  byte
+		strs []string
+		args []uint64
+	}
+
+	var got []testData
+	tasks := map[uint64]string{}
+	for _, e := range res.Events {
+		t.Logf("%s", e)
+		switch e.Type {
+		case trace.EvUserTaskCreate:
+			taskName := e.SArgs[0]
+			got = append(got, testData{trace.EvUserTaskCreate, []string{taskName}, nil})
+			tasks[e.Args[0]] = taskName
+		case trace.EvUserLog:
+			key, val := e.SArgs[0], e.SArgs[1]
+			taskName := tasks[e.Args[0]]
+			got = append(got, testData{trace.EvUserLog, []string{taskName, key, val}, nil})
+		case trace.EvUserTaskEnd:
+			taskName := tasks[e.Args[0]]
+			got = append(got, testData{trace.EvUserTaskEnd, []string{taskName}, nil})
+		case trace.EvUserSpan:
+			taskName := tasks[e.Args[0]]
+			spanName := e.SArgs[0]
+			got = append(got, testData{trace.EvUserSpan, []string{taskName, spanName}, []uint64{e.Args[1]}})
+		}
+	}
+	want := []testData{
+		{trace.EvUserTaskCreate, []string{"task0"}, nil},
+		{trace.EvUserSpan, []string{"task0", "span0"}, []uint64{0}},
+		{trace.EvUserLog, []string{"task0", "key0", "0123456789abcdef"}, nil},
+		{trace.EvUserSpan, []string{"task0", "span0"}, []uint64{1}},
+		{trace.EvUserTaskEnd, []string{"task0"}, nil},
+	}
+	if !reflect.DeepEqual(got, want) {
+		t.Errorf("Got user span related events %+v\nwant: %+v", got, want)
+	}
+}