Merge #128698

128698: retry: trace on retry backoff r=nvanbenschoten a=nvanbenschoten

This commit adds tracing to `retry.Next`, to assist in understanding the backoff behavior of retry loops. This is useful for debugging, where we otherwise see unexplained delays. It looks like the following in traces:

```
2024-08-09 18:10:33.341503+00 | 00:00:00.001306 | retrying after 43.936507ms  | [n1,client=[::1]:52944,hostnossl,user=root,txn=e7011024] | kv/kvclient/kvcoord/dist_sender.go:3081  | dist sender send | 9
2024-08-09 18:10:33.388118+00 | 00:00:00.047921 | retrying after 45.678614ms  | [n1,client=[::1]:52944,hostnossl,user=root,txn=e7011024] | kv/kvclient/kvcoord/dist_sender.go:2135  | dist sender send | 9
2024-08-09 18:10:33.437466+00 | 00:00:00.097269 | retrying after 89.902637ms  | [n1,client=[::1]:52944,hostnossl,user=root,txn=e7011024] | kv/kvclient/kvcoord/dist_sender.go:2135  | dist sender send | 9
2024-08-09 18:10:33.531346+00 | 00:00:00.191149 | retrying after 226.616186ms | [n1,client=[::1]:52944,hostnossl,user=root,txn=e7011024] | kv/kvclient/kvcoord/dist_sender.go:2135  | dist sender send | 9
2024-08-09 18:10:33.761593+00 | 00:00:00.421396 | retrying after 347.621605ms | [n1,client=[::1]:52944,hostnossl,user=root,txn=e7011024] | kv/kvclient/kvcoord/dist_sender.go:2135  | dist sender send | 9
2024-08-09 18:10:34.112724+00 | 00:00:00.772527 | retrying after 841.913917ms | [n1,client=[::1]:52944,hostnossl,user=root,txn=e7011024] | kv/kvclient/kvcoord/dist_sender.go:2135  | dist sender send | 9
2024-08-09 18:10:34.958975+00 | 00:00:01.618778 | retrying after 959.158772ms | [n1,client=[::1]:52944,hostnossl,user=root,txn=e7011024] | kv/kvclient/kvcoord/dist_sender.go:2135  | dist sender send | 9
2024-08-09 18:10:35.924476+00 | 00:00:02.584279 | retrying after 1.138820334s | [n1,client=[::1]:52944,hostnossl,user=root,txn=e7011024] | kv/kvclient/kvcoord/dist_sender.go:2135  | dist sender send | 9
2024-08-09 18:10:37.073436+00 | 00:00:03.733239 | retrying after 1.054426075s | [n1,client=[::1]:52944,hostnossl,user=root,txn=e7011024] | kv/kvclient/kvcoord/dist_sender.go:2135  | dist sender send | 9
2024-08-09 18:10:38.132316+00 | 00:00:04.792119 | retrying after 919.413404ms | [n1,client=[::1]:52944,hostnossl,user=root,txn=e7011024] | kv/kvclient/kvcoord/dist_sender.go:2135  | dist sender send | 9
2024-08-09 18:10:39.055159+00 | 00:00:05.714962 | retrying after 1.100328812s | [n1,client=[::1]:52944,hostnossl,user=root,txn=e7011024] | kv/kvclient/kvcoord/dist_sender.go:2135  | dist sender send | 9
2024-08-09 18:10:40.159483+00 | 00:00:06.819286 | retrying after 1.120451316s | [n1,client=[::1]:52944,hostnossl,user=root,txn=e7011024] | kv/kvclient/kvcoord/dist_sender.go:2135  | dist sender send | 9
```

Epic: None
Release note: None

Co-authored-by: Nathan VanBenschoten <nvanbenschoten@gmail.com>

Author: craig[bot]

pkg/util/retry/BUILD.bazel

@@ -6,6 +6,7 @@ go_library(
     importpath = "github.com/cockroachdb/cockroach/pkg/util/retry",
     visibility = ["//visibility:public"],
     deps = [
+        "//pkg/util/log",
         "//pkg/util/timeutil",
         "@com_github_cockroachdb_errors//:errors",
     ],

pkg/util/retry/retry.go

@@ -16,6 +16,7 @@ import (
 	"math/rand"
 	"time"
 
+	"github.com/cockroachdb/cockroach/pkg/util/log"
 	"github.com/cockroachdb/cockroach/pkg/util/timeutil"
 	"github.com/cockroachdb/errors"
 )
@@ -35,7 +36,7 @@ type Options struct {
 // backoff retry loop.
 type Retry struct {
 	opts           Options
-	ctxDoneChan    <-chan struct{}
+	ctx            context.Context
 	currentAttempt int
 	isReset        bool
 }
@@ -66,7 +67,7 @@ func StartWithCtx(ctx context.Context, opts Options) Retry {
 
 	var r Retry
 	r.opts = opts
-	r.ctxDoneChan = ctx.Done()
+	r.ctx = ctx
 	r.mustReset()
 	return r
 }
@@ -81,7 +82,7 @@ func (r *Retry) Reset() {
 	select {
 	case <-r.opts.Closer:
 		// When the closer has fired, you can't keep going.
-	case <-r.ctxDoneChan:
+	case <-r.ctx.Done():
 		// When the context was canceled, you can't keep going.
 	default:
 		r.mustReset()
@@ -125,13 +126,17 @@ func (r *Retry) Next() bool {
 	}
 
 	// Wait before retry.
+	d := r.retryIn()
+	if d > 0 {
+		log.VEventfDepth(r.ctx, 1 /* depth */, 2 /* level */, "will retry after %s", d)
+	}
 	select {
-	case <-time.After(r.retryIn()):
+	case <-time.After(d):
 		r.currentAttempt++
 		return true
 	case <-r.opts.Closer:
 		return false
-	case <-r.ctxDoneChan:
+	case <-r.ctx.Done():
 		return false
 	}
 }