cmd/trace: add user log event in the task-oriented trace view

Also append stack traces to task create/end slices.

R=go1.11

Change-Id: I2adb342e92b36d30bee2860393618eb4064450cf
Reviewed-on: https://go-review.googlesource.com/90220
Reviewed-by: Heschi Kreinick <heschi@google.com>

src/cmd/trace/annotations.go

@@ -850,6 +850,17 @@ func asMillisecond(d time.Duration) float64 {
 	return float64(d.Nanoseconds()) / 1e6
 }
 
+func formatUserLog(ev *trace.Event) string {
+	k, v := ev.SArgs[0], ev.SArgs[1]
+	if k == "" {
+		return v
+	}
+	if v == "" {
+		return k
+	}
+	return fmt.Sprintf("%v=%v", k, v)
+}
+
 func describeEvent(ev *trace.Event) string {
 	switch ev.Type {
 	case trace.EvGoCreate:
@@ -857,11 +868,7 @@ func describeEvent(ev *trace.Event) string {
 	case trace.EvGoEnd, trace.EvGoStop:
 		return "goroutine stopped"
 	case trace.EvUserLog:
-		if k, v := ev.SArgs[0], ev.SArgs[1]; k == "" {
+		return formatUserLog(ev)
-			return v
-		} else {
-			return fmt.Sprintf("%v=%v", k, v)
-		}
 	case trace.EvUserSpan:
 		if ev.Args[1] == 0 {
 			duration := "unknown"

src/cmd/trace/trace.go

@@ -544,12 +544,12 @@ func generateTrace(params *traceParams) (ViewerData, error) {
 			if ctx.mode != defaultTraceview {
 				continue
 			}
-			ctx.emitInstant(ev, "proc start")
+			ctx.emitInstant(ev, "proc start", "")
 		case trace.EvProcStop:
 			if ctx.mode != defaultTraceview {
 				continue
 			}
-			ctx.emitInstant(ev, "proc stop")
+			ctx.emitInstant(ev, "proc stop", "")
 		case trace.EvGCStart:
 			ctx.emitSlice(ev, "GC")
 		case trace.EvGCDone:
@@ -605,9 +605,15 @@ func generateTrace(params *traceParams) (ViewerData, error) {
 		case trace.EvGoUnblock:
 			ctx.emitArrow(ev, "unblock")
 		case trace.EvGoSysCall:
-			ctx.emitInstant(ev, "syscall")
+			ctx.emitInstant(ev, "syscall", "")
 		case trace.EvGoSysExit:
 			ctx.emitArrow(ev, "sysexit")
+		case trace.EvUserLog:
+			ctx.emitInstant(ev, formatUserLog(ev), "user event")
+		case trace.EvUserTaskCreate:
+			ctx.emitInstant(ev, "task start", "user event")
+		case trace.EvUserTaskEnd:
+			ctx.emitInstant(ev, "task end", "user event")
 		}
 		// Emit any counter updates.
 		ctx.emitThreadCounters(ev)
@@ -649,8 +655,18 @@ func generateTrace(params *traceParams) (ViewerData, error) {
 			taskName := fmt.Sprintf("Task %s(%d)", task.name, task.id)
 			ctx.emit(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: taskRow, Arg: &NameArg{"Tasks"}})
 			ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: taskRow, Arg: &SortIndexArg{-3}})
-			ctx.emit(&ViewerEvent{Category: "task", Name: taskName, Phase: "b", Time: float64(task.firstTimestamp()) / 1e3, Tid: taskRow, ID: task.id, Cname: "bad"})
+			tBegin := &ViewerEvent{Category: "task", Name: taskName, Phase: "b", Time: float64(task.firstTimestamp()) / 1e3, Tid: taskRow, ID: task.id, Cname: "bad"}
-			ctx.emit(&ViewerEvent{Category: "task", Name: taskName, Phase: "e", Time: float64(task.lastTimestamp()) / 1e3, Tid: taskRow, ID: task.id, Cname: "bad"})
+			if task.create != nil {
+				tBegin.Stack = ctx.stack(task.create.Stk)
+			}
+			ctx.emit(tBegin)
+
+			tEnd := &ViewerEvent{Category: "task", Name: taskName, Phase: "e", Time: float64(task.lastTimestamp()) / 1e3, Tid: taskRow, ID: task.id, Cname: "bad"}
+			if task.end != nil {
+				tEnd.Stack = ctx.stack(task.end.Stk)
+			}
+			ctx.emit(tEnd)
+
 			// Spans
 			for _, s := range task.spans {
 				ctx.emitSpan(s)
@@ -818,7 +834,7 @@ func (ctx *traceContext) emitThreadCounters(ev *trace.Event) {
 	ctx.prevThreadStats = ctx.threadStats
 }
 
-func (ctx *traceContext) emitInstant(ev *trace.Event, name string) {
+func (ctx *traceContext) emitInstant(ev *trace.Event, name, category string) {
 	var arg interface{}
 	if ev.Type == trace.EvProcStart {
 		type Arg struct {
@@ -826,7 +842,15 @@ func (ctx *traceContext) emitInstant(ev *trace.Event, name string) {
 		}
 		arg = &Arg{ev.Args[0]}
 	}
-	ctx.emit(&ViewerEvent{Name: name, Phase: "I", Scope: "t", Time: ctx.time(ev), Tid: ctx.proc(ev), Stack: ctx.stack(ev.Stk), Arg: arg})
+	ctx.emit(&ViewerEvent{
+		Name:     name,
+		Category: category,
+		Phase:    "I",
+		Scope:    "t",
+		Time:     ctx.time(ev),
+		Tid:      ctx.proc(ev),
+		Stack:    ctx.stack(ev.Stk),
+		Arg:      arg})
 }
 
 func (ctx *traceContext) emitArrow(ev *trace.Event, name string) {
@@ -842,7 +866,7 @@ func (ctx *traceContext) emitArrow(ev *trace.Event, name string) {
 	if ev.P == trace.NetpollP || ev.P == trace.TimerP || ev.P == trace.SyscallP {
 		// Trace-viewer discards arrows if they don't start/end inside of a slice or instant.
 		// So emit a fake instant at the start of the arrow.
-		ctx.emitInstant(&trace.Event{P: ev.P, Ts: ev.Ts}, "unblock")
+		ctx.emitInstant(&trace.Event{P: ev.P, Ts: ev.Ts}, "unblock", "")
 	}
 
 	ctx.arrowSeq++