Merge #153816

153816: kvprober: log traced planning query r=iskettaneh a=iskettaneh

This commit adds a cluster setting
kv.prober.log_tracing_on_plan_failure.enabled. If enabled, along with kv.prober.tracing.enabled, the read/write probers will log the traced planning query (targetting Meta2) if there is an error in the planning phase.

Example of the output log: 

```
E250919 20:38:53.527962 2486 2@kv/kvprober/kvprober.go:385 ⋮ [T1,Vsystem,n1,kvprober] 985  can't make a plan: failed to get meta2 rows: operation "db.Scan" timed out after 1ms (given timeout 1ms): aborted in DistSender: result 
is ambiguous: context deadline exceeded, recorded trace:      0.000ms      0.000ms    === operation:read probe gid:2486 _verbose:‹1› node:‹1› kvprober:
E250919 20:38:53.527962 2486 2@kv/kvprober/kvprober.go:385 ⋮ [T1,Vsystem,n1,kvprober] 985 +     0.000ms      0.000ms    [kvprober.meta2-scan: {count: 1, duration 1ms}]
E250919 20:38:53.527962 2486 2@kv/kvprober/kvprober.go:385 ⋮ [T1,Vsystem,n1,kvprober] 985 +     0.000ms      0.000ms    [dist sender send: {count: 1, duration 1ms}]
E250919 20:38:53.527962 2486 2@kv/kvprober/kvprober.go:385 ⋮ [T1,Vsystem,n1,kvprober] 985 +     0.050ms      0.050ms    event:kv/kvprober/planner.go:223 [n1,kvprober] Meta2 start scan
E250919 20:38:53.527962 2486 2@kv/kvprober/kvprober.go:385 ⋮ [T1,Vsystem,n1,kvprober] 985 +     0.069ms      0.019ms        === operation:kvprober.meta2-scan gid:2486 _verbose:‹1› node:‹1› kvprober:
E250919 20:38:53.527962 2486 2@kv/kvprober/kvprober.go:385 ⋮ [T1,Vsystem,n1,kvprober] 985 +     0.069ms      0.000ms        [dist sender send: {count: 1, duration 1ms}]
E250919 20:38:53.527962 2486 2@kv/kvprober/kvprober.go:385 ⋮ [T1,Vsystem,n1,kvprober] 985 +     0.081ms      0.012ms            === operation:dist sender send gid:2486 _verbose:‹1› node:‹1› kvprober:
E250919 20:38:53.527962 2486 2@kv/kvprober/kvprober.go:385 ⋮ [T1,Vsystem,n1,kvprober] 985 +     0.118ms      0.037ms            event:kv/kvclient/kvcoord/range_iter.go:183 [n1,kvprober] querying next range at /Meta2/Table/106/1
/‹-5113857622831569008›/‹NULL›
E250919 20:38:53.527962 2486 2@kv/kvprober/kvprober.go:385 ⋮ [T1,Vsystem,n1,kvprober] 985 +     0.161ms      0.043ms            event:kv/kvclient/kvcoord/range_iter.go:220 [n1,kvprober] key: /Meta2/Table/106/1/‹-511385762283156
9008›/‹NULL›, desc: r1:/{Min-System/NodeLiveness} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=4]
E250919 20:38:53.527962 2486 2@kv/kvprober/kvprober.go:385 ⋮ [T1,Vsystem,n1,kvprober] 985 +     0.200ms      0.039ms            event:kv/kvclient/kvcoord/dist_sender.go:2662 [n1,kvprober] r1: sending batch ‹1 Scan› to (n3,s3):3
E250919 20:38:53.527962 2486 2@kv/kvprober/kvprober.go:385 ⋮ [T1,Vsystem,n1,kvprober] 985 +     0.214ms      0.014ms            event:rpc/nodedialer/nodedialer.go:230 [n1,kvprober] sending request to ‹10.142.0.124:26257›
E250919 20:38:53.527962 2486 2@kv/kvprober/kvprober.go:385 ⋮ [T1,Vsystem,n1,kvprober] 985 +     0.224ms      0.010ms            event:kv/kvclient/kvcoord/transport.go:210 [n1,kvprober] ‹sending batch request›
E250919 20:38:53.527962 2486 2@kv/kvprober/kvprober.go:385 ⋮ [T1,Vsystem,n1,kvprober] 985 +     1.175ms      0.951ms            event:kv/kvclient/kvcoord/transport.go:212 [n1,kvprober] ‹received batch response›
E250919 20:38:53.527962 2486 2@kv/kvprober/kvprober.go:385 ⋮ [T1,Vsystem,n1,kvprober] 985 +     1.277ms      0.102ms            event:kv/kvclient/kvcoord/dist_sender.go:2813 [n1,kvprober] RPC error: ba: ‹Scan [/Meta2/Table/106/
1/-5113857622831569008/NULL,/Meta2/"\xff\xff\x00"), [max_span_request_keys: 100], [target_bytes: 0]› RPC error: context deadline exceeded
E250919 20:38:53.527962 2486 2@kv/kvprober/kvprober.go:385 ⋮ [T1,Vsystem,n1,kvprober] 985 +     1.303ms      0.026ms            event:kv/kvclient/kvcoord/dist_sender.go:3137 [n1,kvprober] context deadline exceeded
E250919 20:38:53.527962 2486 2@kv/kvprober/kvprober.go:385 ⋮ [T1,Vsystem,n1,kvprober] 985 +     1.366ms      0.063ms            event:kv/kvclient/kvcoord/dist_sender.go:2331 [n1,kvprober] replace error context deadline exceeded
 with aborted in DistSender: result is ambiguous: context deadline exceeded
```

Epic: None

Release note: None

Co-authored-by: Ibrahim Kettaneh <[email protected]>

Author: craig[bot]

pkg/kv/kvprober/kvprober.go

@@ -368,6 +368,7 @@ func (p *Prober) readProbeImpl(ctx context.Context, ops proberOpsI, txns proberT
 	var probeCtx = ctx
 
 	isTracingEnabled := tracingEnabled.Get(&p.settings.SV)
+	logTracingOnPlanFailureEnabled := isTracingEnabled && logTracingOnPlanFailureEnabled.Get(&p.settings.SV)
 	if isTracingEnabled {
 		probeCtx, finishAndGetRecording = tracing.ContextWithRecordingSpan(ctx, p.tracer, "read probe")
 	}
@@ -380,7 +381,11 @@ func (p *Prober) readProbeImpl(ctx context.Context, ops proberOpsI, txns proberT
 		if errorIsExpectedDuringNormalOperation(err) {
 			log.Health.Warningf(ctx, "making a plan failed with expected error: %v", err)
 		} else {
-			log.Health.Errorf(ctx, "can't make a plan: %v", err)
+			if logTracingOnPlanFailureEnabled {
+				log.Health.Errorf(ctx, "can't make a plan: %v, recorded trace: %s", err, finishAndGetRecording())
+			} else {
+				log.Health.Errorf(ctx, "can't make a plan: %v", err)
+			}
 			p.metrics.ProbePlanFailures.Inc(1)
 		}
 		return
@@ -453,6 +458,7 @@ func (p *Prober) writeProbeImpl(ctx context.Context, ops proberOpsI, txns prober
 	var probeCtx = ctx
 
 	isTracingEnabled := tracingEnabled.Get(&p.settings.SV)
+	logTracingOnPlanFailureEnabled := isTracingEnabled && logTracingOnPlanFailureEnabled.Get(&p.settings.SV)
 	if isTracingEnabled {
 		probeCtx, finishAndGetRecording = tracing.ContextWithRecordingSpan(ctx, p.tracer, "write probe")
 	}
@@ -467,7 +473,11 @@ func (p *Prober) writeProbeImpl(ctx context.Context, ops proberOpsI, txns prober
 		if errorIsExpectedDuringNormalOperation(err) {
 			log.Health.Warningf(ctx, "making a plan failed with expected error: %v", err)
 		} else {
-			log.Health.Errorf(ctx, "can't make a plan: %v", err)
+			if logTracingOnPlanFailureEnabled {
+				log.Health.Errorf(ctx, "can't make a plan: %v, recorded trace: %s", err, finishAndGetRecording())
+			} else {
+				log.Health.Errorf(ctx, "can't make a plan: %v", err)
+			}
 			p.metrics.ProbePlanFailures.Inc(1)
 		}
 		return

pkg/kv/kvprober/settings.go

@@ -136,3 +136,10 @@ var tracingEnabled = settings.RegisterBoolSetting(
 	"whether the KV prober should collect traces, in order to log info about"+
 		"leaseholders of ranges probed",
 	false)
+
+var logTracingOnPlanFailureEnabled = settings.RegisterBoolSetting(
+	settings.ApplicationLevel,
+	"kv.prober.log_tracing_on_plan_failure.enabled",
+	"whether the KV prober should print log traces when planning fails; "+
+		"requires kv.prober.tracing.enabled to be set to true",
+	false)