Merge #146432

146432: kvclient: add request record summary to write buffer tracing  r=yuzefovich a=stevendanna

This might help someone understand why the batch ultimately sent to KV
is incongruous with trace entries added by the SQL layer.

Epic: none

Release note: None

Co-authored-by: Steven Danna <[email protected]>

Author: craig[bot]

pkg/cli/clisqlshell/sql.go

@@ -2169,17 +2169,21 @@ func (c *cliState) doRunStatements(nextState cliStateEnum) cliStateEnum {
 			// shell.
 		} else {
 			traceType := ""
+			compact := ""
 			if strings.Contains(c.iCtx.autoTrace, "kv") {
 				traceType = "kv"
 			}
+			if strings.Contains(c.iCtx.autoTrace, "compact") {
+				compact = "COMPACT"
+			}
 			if err := c.runWithInterruptableCtx(func(ctx context.Context) error {
 				defer c.maybeFlushOutput()
 				return c.sqlExecCtx.RunQueryAndFormatResults(ctx,
 					c.conn,
 					c.iCtx.queryOutput, // query output
 					c.iCtx.stdout,      // timings
 					c.iCtx.stderr,      // errors
-					clisqlclient.MakeQuery(fmt.Sprintf("SHOW %s TRACE FOR SESSION", traceType)))
+					clisqlclient.MakeQuery(fmt.Sprintf("SHOW %s %s TRACE FOR SESSION", compact, traceType)))
 			}); err != nil {
 				clierror.OutputError(c.iCtx.stderr, err, true /*showSeverity*/, false /*verbose*/)
 				if c.exitErr == nil {

pkg/kv/kvclient/kvcoord/txn_interceptor_write_buffer.go

@@ -8,8 +8,10 @@ package kvcoord
 import (
 	"context"
 	"encoding/binary"
+	"fmt"
 	"slices"
 	"sort"
+	"strings"
 	"unsafe"
 
 	"github.com/cockroachdb/cockroach/pkg/kv/kvnemesis/kvnemesisutil"
@@ -249,6 +251,12 @@ func (twb *txnWriteBuffer) SendLocked(
 		return nil, pErr
 	}
 
+	if log.ExpensiveLogEnabled(ctx, 2) {
+		if summary := rr.Summary(); summary != "" {
+			log.VEventf(ctx, 2, "txn write buffer modified the batch; %s", summary)
+		}
+	}
+
 	if len(transformedBa.Requests) == 0 {
 		// Lower layers (the DistSender and the KVServer) do not expect/handle empty
 		// batches. If all requests in the batch can be handled locally, and we're
@@ -1195,6 +1203,40 @@ func (rr requestRecords) Empty() bool {
 	return len(rr) == 0
 }
 
+// Summary returns a string summarizing the modifications made to the original
+// batch that generated this set of request records. An empty string indicates
+// that the original batch was not modified.
+func (rr requestRecords) Summary() string {
+	fullyBuffered := make(map[kvpb.Method]int)
+	transformed := make(map[kvpb.Method]int)
+	for _, rec := range rr {
+		if rec.stripped {
+			fullyBuffered[rec.origRequest.Method()]++
+		} else if rec.transformed {
+			transformed[rec.origRequest.Method()]++
+		}
+	}
+	if len(fullyBuffered) == 0 && len(transformed) == 0 {
+		return ""
+	}
+	b := &strings.Builder{}
+	sep := ""
+	if len(fullyBuffered) > 0 {
+		b.WriteString("fully buffered:")
+		for method, count := range fullyBuffered {
+			fmt.Fprintf(b, " %s:%d", method, count)
+		}
+		sep = "; "
+	}
+	if len(transformed) > 0 {
+		fmt.Fprintf(b, "%stransformed:", sep)
+		for method, count := range transformed {
+			fmt.Fprintf(b, " %s:%d", method, count)
+		}
+	}
+	return b.String()
+}
+
 // addToBuffer adds a write to the given key to the buffer.
 func (twb *txnWriteBuffer) addToBuffer(
 	key roachpb.Key, val roachpb.Value, seq enginepb.TxnSeq, kvNemSeq kvnemesisutil.Container,

pkg/sql/conn_executor_exec.go

@@ -4101,6 +4101,8 @@ func (ex *connExecutor) enableTracing(modes []string) error {
 			traceKV = true
 		case "cluster":
 			recordingType = tracingpb.RecordingVerbose
+		case "compact":
+			// compact modifies the output format.
 		default:
 			return pgerror.Newf(pgcode.Syntax,
 				"set tracing: unknown mode %q", s)

pkg/sql/logictest/testdata/logic_test/buffered_writes

@@ -479,3 +479,32 @@ query II
 SELECT pk,v FROM t5 WHERE pk = 1
 ----
 1  1
+
+subtest tracing
+
+statement ok
+CREATE TABLE t6 (pk INT PRIMARY KEY, v INT, FAMILY (pk, v), INDEX (v), INDEX ((v+5)))
+
+statement ok
+BEGIN
+
+statement ok
+SET TRACING = "on"
+
+statement ok
+INSERT INTO t6 VALUES (1,1)
+
+# This assertion depends on write buffering not being disabled because
+# of the version or transaction isolation level. Skip configurations
+# that result in buffered writes being disabled.
+skipif config local-read-committed local-repeatable-read local-mixed-24.3 local-mixed-25.1
+query T
+SELECT message FROM [SHOW TRACE FOR SESSION] WHERE location LIKE '%write_buffer.go%'
+----
+txn write buffer modified the batch; fully buffered: Put:2; transformed: ConditionalPut:1
+
+statement ok
+SET TRACING = "off"
+
+statement ok
+COMMIT