Merge cockroachdb#124090

124090: kvstreamer: improve logging a bit r=yuzefovich a=yuzefovich

This commit adjusts the logging for each `singleRangeBatch` to include the number of scans inside of it (we only included the number of gets previously). It also drops the bitmap for whether the scans were started (this doesn't seem that useful - `positions` slice kinda implicitly has that information).

Additionally, it includes the TargetBytes limit that each BatchRequest was issued with into an existing log message (we have this information down at the KV level too, but it makes things easier when grepping from streamer logs specifically).

Informs: https://github.com/cockroachlabs/support/issues/2945.
Epic: None

Release note: None

Co-authored-by: Yahor Yuzefovich <yahor@cockroachlabs.com>

pkg/kv/kvclient/kvstreamer/requests_provider.go

@@ -188,6 +188,7 @@ func (r singleRangeBatch) String() string {
 	// We try to limit the size based on the number of requests ourselves, so
 	// this is just a sane upper-bound.
 	maxBytes := 10 << 10 /* 10KiB */
+	numScansInReqs := int64(len(r.reqs)) - r.numGetsInReqs
 	if len(r.reqs) > 10 {
 		// To keep the size of this log message relatively small, if we have
 		// more than 10 requests, then we only include the information about the
@@ -199,17 +200,17 @@ func (r singleRangeBatch) String() string {
 			subIdx = fmt.Sprintf("%v...%v", r.subRequestIdx[:headEndIdx], r.subRequestIdx[tailStartIdx:])
 		}
 		return fmt.Sprintf(
-			"{reqs:%v...%v pos:%v...%v subIdx:%s start:%v gets:%v reserved:%v overhead:%v minTarget:%v}",
+			"{reqs:%v...%v pos:%v...%v subIdx:%s gets:%v scans:%v reserved:%v overhead:%v minTarget:%v}",
 			kvpb.TruncatedRequestsString(r.reqs[:headEndIdx], maxBytes),
 			kvpb.TruncatedRequestsString(r.reqs[tailStartIdx:], maxBytes),
-			r.positions[:headEndIdx], r.positions[tailStartIdx:],
-			subIdx, r.isScanStarted, r.numGetsInReqs, r.reqsReservedBytes, r.overheadAccountedFor, r.minTargetBytes,
+			r.positions[:headEndIdx], r.positions[tailStartIdx:], subIdx, r.numGetsInReqs,
+			numScansInReqs, r.reqsReservedBytes, r.overheadAccountedFor, r.minTargetBytes,
 		)
 	}
 	return fmt.Sprintf(
-		"{reqs:%v pos:%v subIdx:%v start:%v gets:%v reserved:%v overhead:%v minTarget:%v}",
+		"{reqs:%v pos:%v subIdx:%v gets:%v scans:%v reserved:%v overhead:%v minTarget:%v}",
 		kvpb.TruncatedRequestsString(r.reqs, maxBytes), r.positions, r.subRequestIdx,
-		r.isScanStarted, r.numGetsInReqs, r.reqsReservedBytes, r.overheadAccountedFor, r.minTargetBytes,
+		r.numGetsInReqs, numScansInReqs, r.reqsReservedBytes, r.overheadAccountedFor, r.minTargetBytes,
 	)
 }
 

pkg/kv/kvclient/kvstreamer/streamer.go

@@ -1490,6 +1490,13 @@ func (w *workerCoordinator) performRequestAsync(
 
 			// Finally, process the results and add the ResumeSpans to be
 			// processed as well.
+			log.VEventf(ctx, 2,
+				"responses:%d targetBytes:%d {footprint:%v overhead:%v resumeMem:%v gets:%v scans:%v incpGets:%v "+
+					"incpScans:%v startedScans:%v kvs:%v}",
+				len(br.Responses), targetBytes, fp.memoryFootprintBytes, fp.responsesOverhead,
+				fp.resumeReqsMemUsage, fp.numGetResults, fp.numScanResults, fp.numIncompleteGets,
+				fp.numIncompleteScans, fp.numStartedScans, fp.kvPairsRead,
+			)
 			processSingleRangeResponse(ctx, w.s, req, br, fp)
 		}); err != nil {
 		// The new goroutine for the request wasn't spun up, so we have to
@@ -1635,13 +1642,6 @@ func processSingleRangeResults(
 	br *kvpb.BatchResponse,
 	fp singleRangeBatchResponseFootprint,
 ) {
-	log.VEventf(ctx, 2,
-		"responses:%d {footprint:%v overhead:%v resumeMem:%v gets:%v scans:%v incpGets:%v "+
-			"incpScans:%v startedScans:%v kvs:%v}",
-		len(br.Responses), fp.memoryFootprintBytes, fp.responsesOverhead, fp.resumeReqsMemUsage,
-		fp.numGetResults, fp.numScanResults, fp.numIncompleteGets, fp.numIncompleteScans,
-		fp.numStartedScans, fp.kvPairsRead,
-	)
 	// If there are no results, this function has nothing to do.
 	if !fp.hasResults() {
 		log.VEvent(ctx, 2, "no results")