From ee28f8770cee2fdf369810291625c7ac140655a9 Mon Sep 17 00:00:00 2001 From: Yahor Yuzefovich Date: Mon, 13 May 2024 15:22:17 -0700 Subject: [PATCH] kvstreamer: improve logging a bit 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). Release note: None --- pkg/kv/kvclient/kvstreamer/requests_provider.go | 11 ++++++----- pkg/kv/kvclient/kvstreamer/streamer.go | 14 +++++++------- 2 files changed, 13 insertions(+), 12 deletions(-) diff --git a/pkg/kv/kvclient/kvstreamer/requests_provider.go b/pkg/kv/kvclient/kvstreamer/requests_provider.go index 353dc096c82b..d3dac9a4ee5c 100644 --- a/pkg/kv/kvclient/kvstreamer/requests_provider.go +++ b/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, ) } diff --git a/pkg/kv/kvclient/kvstreamer/streamer.go b/pkg/kv/kvclient/kvstreamer/streamer.go index 3a5cad3be2ae..4372770e0b88 100644 --- a/pkg/kv/kvclient/kvstreamer/streamer.go +++ b/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")