tracing: add ChildrenMetadata to String and JSON traces

pkg/server/node_tenant.go

@@ -43,27 +43,6 @@ func redactRecordingForTenant(tenID roachpb.TenantID, rec tracingpb.Recording) e
 					"recording has non-redactable span with the Message field set: %s", sp)
 			}
 			record.Message = record.Message.Redact()
-
-			// For compatibility with old versions, also redact DeprecatedFields.
-			for k := range record.DeprecatedFields {
-				field := &record.DeprecatedFields[k]
-				if field.Key != tracingpb.LogMessageField {
-					// We don't have any of these fields, but let's not take any
-					// chances (our dependencies might slip them in).
-					field.Value = TraceRedactedMarker
-					continue
-				}
-				if !sp.RedactableLogs {
-					// If we're handling a span that originated from an (early patch
-					// release) 22.1 node, all the containing information will be
-					// stripped. Note that this is not the common path here, as most
-					// information in the trace will be from the local node, which
-					// always creates redactable logs.
-					field.Value = TraceRedactedMarker
-					continue
-				}
-				field.Value = field.Value.Redact()
-			}
 		}
 	}
 	return nil

pkg/util/tracing/crdbspan.go

@@ -678,10 +678,6 @@ func (s *crdbSpan) record(msg redact.RedactableString) {
 	logRecord := &tracingpb.LogRecord{
 		Time:    now,
 		Message: msg,
-		// Compatibility with 21.2.
-		DeprecatedFields: []tracingpb.LogRecord_Field{
-			{Key: tracingpb.LogMessageField, Value: msg},
-		},
 	}
 
 	s.recordInternal(logRecord, &s.mu.recording.logs)

pkg/util/tracing/span_test.go

@@ -105,6 +105,8 @@ func TestRecordingString(t *testing.T) {
 
 	require.NoError(t, CheckRecording(rec, `
 		=== operation:root _verbose:1
+		[remote child]
+		[local child]
 		event:root 1
 			=== operation:remote child _verbose:1
 			event:remote child 1
@@ -124,7 +126,7 @@ func TestRecordingString(t *testing.T) {
 		timeSincePrev:       "0.000ms",
 		text:                "=== operation:root _verbose:1",
 	}, l)
-	l, err = parseLine(lines[1])
+	l, err = parseLine(lines[3])
 	require.Equal(t, traceLine{
 		timeSinceTraceStart: "1.000ms",
 		timeSincePrev:       "1.000ms",
@@ -183,6 +185,7 @@ func TestRecordingInRecording(t *testing.T) {
 
 	require.NoError(t, CheckRecording(childRec, `
 		=== operation:child _verbose:1
+		[grandchild]
 			=== operation:grandchild _verbose:1
 		`))
 }
@@ -208,6 +211,7 @@ func TestImportRemoteRecording(t *testing.T) {
 			if verbose {
 				require.NoError(t, CheckRecording(sp.FinishAndGetRecording(tracingpb.RecordingVerbose), `
 				=== operation:root _verbose:1
+				[child]
 					=== operation:child _verbose:1
 					event:&Int32Value{Value:4,XXX_unrecognized:[],}
 					event:foo
@@ -216,6 +220,7 @@ func TestImportRemoteRecording(t *testing.T) {
 			} else {
 				require.NoError(t, CheckRecording(sp.FinishAndGetRecording(tracingpb.RecordingStructured), `
 				=== operation:root
+				[child]
 				structured:{"@type":"type.googleapis.com/google.protobuf.Int32Value","value":4}
 	`))
 			}
@@ -844,6 +849,7 @@ func TestOpenChildIncludedRecording(t *testing.T) {
 	rec := parent.FinishAndGetRecording(tracingpb.RecordingVerbose)
 	require.NoError(t, CheckRecording(rec, `
 		=== operation:parent _verbose:1
+		[child]
 			=== operation:child _unfinished:1 _verbose:1
 	`))
 	child.Finish()

pkg/util/tracing/test_utils.go

@@ -15,6 +15,7 @@ import (
 	"regexp"
 	"sort"
 	"strings"
+	"time"
 
 	"github.com/cockroachdb/cockroach/pkg/util/tracing/tracingpb"
 	"github.com/cockroachdb/errors"
@@ -165,6 +166,7 @@ func CheckRecordedSpans(rec tracingpb.Recording, expected string) error {
 //
 //       if err := CheckRecording(sp.GetRecording(), `
 //           === operation:root
+//           [childrenMetadata]
 //           event:root 1
 //               === operation:remote child
 //               event:remote child 1
@@ -186,19 +188,50 @@ func CheckRecording(rec tracingpb.Recording, expected string) error {
 		// 	 After  |  "event:root 1"
 		re := regexp.MustCompile(`.*s.*s\s{4}`)
 		rec = string(re.ReplaceAll([]byte(rec), nil))
-		// 4. Change all tabs to four spaces.
+		// 4. Strip out all the metadata from each ChildrenMetadata entry.
+		//
+		// 	 Before |  [operation: {Count:<count>, Duration:<duration>}]
+		// 	 After  |  [operation]
+		re = regexp.MustCompile(`:.*]`)
+		rec = string(re.ReplaceAll([]byte(rec), []byte("]")))
+		// 5. Change all tabs to four spaces.
 		rec = strings.ReplaceAll(rec, "\t", "    ")
-		// 5. Compute the outermost indentation.
+		// 6. Compute the outermost indentation.
 		indent := strings.Repeat(" ", len(rec)-len(strings.TrimLeft(rec, " ")))
-		// 6. Outdent each line by that amount.
+		// 7. Outdent each line by that amount.
 		var lines []string
 		for _, line := range strings.Split(rec, "\n") {
 			lines = append(lines, strings.TrimPrefix(line, indent))
 		}
-		// 6. Stitch everything together.
+		// 8. Stitch everything together.
 		return strings.Join(lines, "\n")
 	}
 
+	sortChildrenMetadataByName := func(m map[string]tracingpb.OperationMetadata) {
+		// Sort the OperationMetadata of s' children alphabetically.
+		childrenMetadata := make([]tracingpb.OperationAndMetadata, 0, len(m))
+		for operation, metadata := range m {
+			childrenMetadata = append(childrenMetadata,
+				tracingpb.OperationAndMetadata{Operation: operation, Metadata: metadata})
+		}
+		sort.Slice(childrenMetadata, func(i, j int) bool {
+			return childrenMetadata[i].Operation < childrenMetadata[j].Operation
+		})
+
+		for i, cm := range childrenMetadata {
+			metadata := m[cm.Operation]
+			metadata.Duration = time.Duration(float64(i) * time.Second.Seconds())
+			m[cm.Operation] = metadata
+		}
+	}
+
+	// ChildrenMetadata are sorted in descending order of duration when returned.
+	// To ensure a stable sort in tests, we set the durations to sort in an
+	// alphabetical descending order.
+	for i := range rec {
+		sortChildrenMetadataByName(rec[i].ChildrenMetadata)
+	}
+
 	exp := normalize(expected)
 	got := normalize(rec.String())
 	if got != exp {

pkg/util/tracing/tracingpb/BUILD.bazel

@@ -13,6 +13,7 @@ go_library(
     importpath = "github.com/cockroachdb/cockroach/pkg/util/tracing/tracingpb",
     visibility = ["//visibility:public"],
     deps = [
+        "//pkg/util/humanizeutil",
         "//pkg/util/protoutil",
         "@com_github_cockroachdb_errors//:errors",
         "@com_github_cockroachdb_redact//:redact",

pkg/util/tracing/tracingpb/recorded_span.go

@@ -15,6 +15,7 @@ import (
 	"strings"
 	"time"
 
+	"github.com/cockroachdb/cockroach/pkg/util/humanizeutil"
 	"github.com/cockroachdb/redact"
 	types "github.com/gogo/protobuf/types"
 )
@@ -82,17 +83,6 @@ func (l LogRecord) Msg() redact.RedactableString {
 	if l.Message != "" {
 		return l.Message
 	}
-
-	// Compatibility with 21.2: look at l.DeprecatedFields.
-	for _, f := range l.DeprecatedFields {
-		key := f.Key
-		if key == LogMessageField {
-			return f.Value
-		}
-		if key == "error" {
-			return redact.Sprintf("error: %s", f.Value)
-		}
-	}
 	return ""
 }
 
@@ -128,3 +118,18 @@ func (m OperationMetadata) Combine(other OperationMetadata) OperationMetadata {
 	m.Duration += other.Duration
 	return m
 }
+
+var _ redact.SafeFormatter = OperationMetadata{}
+
+func (m OperationMetadata) String() string {
+	return redact.StringWithoutMarkers(m)
+}
+
+// SafeFormat implements redact.SafeFormatter.
+func (m OperationMetadata) SafeFormat(s redact.SafePrinter, _ rune) {
+	s.Printf("{count: %d, duration %s", m.Count, humanizeutil.Duration(m.Duration))
+	if m.ContainsUnfinished {
+		s.Printf(", unfinished")
+	}
+	s.Print("}")
+}

pkg/util/tracing/tracingpb/recorded_span.proto

@@ -27,12 +27,10 @@ message LogRecord {
     string key = 1;
     string value = 2 [(gogoproto.nullable) = false, (gogoproto.customtype) = "github.com/cockroachdb/redact.RedactableString"];
   }
-  // Fields with values converted to strings. In 22.1, the `message` field
-  // contains the log message, and this field is only used for compatibility
-  // with 21.2 nodes.
-  repeated Field deprecated_fields = 2 [(gogoproto.nullable) = false];
   // The log message.
   string message = 3 [(gogoproto.nullable) = false, (gogoproto.customtype) = "github.com/cockroachdb/redact.RedactableString"];
+
+  reserved 2;
 }
 
 // StructuredRecord is a structured message recorded in a traced span.
@@ -46,6 +44,8 @@ message StructuredRecord {
 // OperationMetadata captures information corresponding to the operation that
 // a span is started with.
 message OperationMetadata {
+  option (gogoproto.goproto_stringer) = false;
+
   // Duration represents the total time spent by spans tracing the operation.
   int64 duration = 1 [(gogoproto.casttype) = "time.Duration"];
   // Count represents the number of spans tracing the operation.
@@ -179,5 +179,6 @@ message NormalizedSpan {
                                         (gogoproto.stdduration) = true];
   repeated LogRecord logs = 5 [(gogoproto.nullable) = false];
   repeated StructuredRecord structured_records = 7 [(gogoproto.nullable) = false];
+  map<string, OperationMetadata> children_metadata = 9 [(gogoproto.nullable) = false];
   repeated NormalizedSpan children = 6 [(gogoproto.nullable) = false];
 }

pkg/util/tracing/tracingpb/recording.go

@@ -14,6 +14,7 @@ import (
 	"encoding/json"
 	"fmt"
 	"regexp"
+	"sort"
 	"strconv"
 	"strings"
 	"time"
@@ -225,6 +226,13 @@ func (r Recording) FindSpan(operation string) (RecordedSpan, bool) {
 	return RecordedSpan{}, false
 }
 
+// OperationAndMetadata contains information about a tracing span operation and
+// its corresponding metadata.
+type OperationAndMetadata struct {
+	Operation string
+	Metadata  OperationMetadata
+}
+
 // visitSpan returns the log messages for sp, and all of sp's children.
 //
 // All messages from a Span are kept together. Sibling spans are ordered within
@@ -271,6 +279,21 @@ func (r Recording) visitSpan(sp RecordedSpan, depth int) []traceLogData {
 		// ref - this entries timeSincePrev will be computed when we merge it into the parent
 		time.Time{}))
 
+	// Sort the OperationMetadata of s' children in descending order of duration.
+	childrenMetadata := make([]OperationAndMetadata, 0, len(sp.ChildrenMetadata))
+	for operation, metadata := range sp.ChildrenMetadata {
+		childrenMetadata = append(childrenMetadata,
+			OperationAndMetadata{operation, metadata})
+	}
+	sort.Slice(childrenMetadata, func(i, j int) bool {
+		return childrenMetadata[i].Metadata.Duration > childrenMetadata[j].Metadata.Duration
+	})
+	for _, c := range childrenMetadata {
+		var sb redact.StringBuilder
+		sb.Printf("[%s: %s]", redact.SafeString(c.Operation), c.Metadata.String())
+		ownLogs = append(ownLogs, conv(sb.RedactableString(), sp.StartTime, time.Time{}))
+	}
+
 	for _, l := range sp.Logs {
 		lastLog := ownLogs[len(ownLogs)-1]
 		var sb redact.StringBuilder

pkg/util/tracing/utils.go

@@ -40,6 +40,7 @@ func normalizeSpan(s tracingpb.RecordedSpan, trace tracingpb.Recording) tracingp
 	n.TagGroups = s.TagGroups
 	n.Logs = s.Logs
 	n.StructuredRecords = s.StructuredRecords
+	n.ChildrenMetadata = s.ChildrenMetadata
 
 	for _, ss := range trace {
 		if ss.ParentSpanID != s.SpanID {