Skip to content

Commit c3a0aaa

Browse files
BenWhiteheadBenWhitehead
committed
chore: fixup elapsed reporting in retry related messages
Update Backoff so that it doesn't assume the returned backoff is fully consumed, instead expect that to be included in the provided `elapsed` value if/when called again. Update backoff tests to pass the previous backoff result into the next call. Update DefaultRetryContext to track elapsed time since last recordError invocation separately from the last time the context was reset. Update RetryContextTest to have new assertions for the fixed elapsed durations.
1 parent fac7839 commit c3a0aaa

7 files changed

Lines changed: 175 additions & 59 deletions

File tree

‎google-cloud-storage/src/main/java/com/google/cloud/storage/Backoff.java‎

Lines changed: 5 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -87,33 +87,23 @@ BackoffResult nextBackoff(Duration elapsed) {
8787
checkArgument(
8888
Durations.gtEq(elapsed, ZERO), "elapsed must be >= PT0S (%s >= %s)", elapsed, ZERO);
8989
Duration cumulativeAndElapsed = cumulativeBackoff.plus(elapsed);
90+
cumulativeBackoff = cumulativeAndElapsed;
9091
if (Durations.gtEq(cumulativeAndElapsed, timeout)) {
91-
cumulativeBackoff = cumulativeAndElapsed;
9292
return BackoffResults.EXHAUSTED;
9393
}
94-
9594
Duration nextDelay =
9695
Duration.ofNanos(Math.round(previousBackoff.toNanos() * retryDelayMultiplier));
9796
if (Durations.eq(nextDelay, ZERO)) {
9897
nextDelay = initialBackoff;
9998
}
10099
Duration nextBackoffWithJitter = jitterer.jitter(nextDelay);
101-
Duration cappedBackoff = Durations.min(nextBackoffWithJitter, maxBackoff);
102-
cumulativeBackoff = cumulativeAndElapsed.plus(cappedBackoff);
100+
Duration remainingUtilTimeout = timeout.minus(cumulativeAndElapsed);
101+
Duration cappedBackoff = Durations.min(nextBackoffWithJitter, maxBackoff, remainingUtilTimeout);
103102
previousBackoff = cappedBackoff;
104103

105104
return BackoffDuration.of(cappedBackoff);
106105
}
107106

108-
/**
109-
* If a backoff is interrupted (usually because of another error from a higher level), record how
110-
* much of the backoff actually happened.
111-
*/
112-
void backoffInterrupted(Duration consumedBackoff) {
113-
Duration unconsumedBackoff = previousBackoff.minus(consumedBackoff);
114-
cumulativeBackoff = cumulativeBackoff.minus(unconsumedBackoff);
115-
}
116-
117107
/**
118108
* Reset all state.
119109
*
@@ -158,12 +148,13 @@ public int hashCode() {
158148
@Override
159149
public String toString() {
160150
return MoreObjects.toStringHelper(this)
151+
.add("previousBackoff", previousBackoff)
152+
.add("cumulativeBackoff", cumulativeBackoff)
161153
.add("initialBackoff", initialBackoff)
162154
.add("maxBackoff", maxBackoff)
163155
.add("timeout", timeout)
164156
.add("retryDelayMultiplier", retryDelayMultiplier)
165157
.add("jitterer", jitterer)
166-
.add("cumulativeBackoff", cumulativeBackoff)
167158
.toString();
168159
}
169160

‎google-cloud-storage/src/main/java/com/google/cloud/storage/DefaultRetryContext.java‎

Lines changed: 13 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,7 @@
2626
import java.time.Duration;
2727
import java.util.LinkedList;
2828
import java.util.List;
29+
import java.util.Locale;
2930
import java.util.concurrent.ScheduledExecutorService;
3031
import java.util.concurrent.ScheduledFuture;
3132
import java.util.concurrent.TimeUnit;
@@ -41,6 +42,7 @@ final class DefaultRetryContext implements RetryContext {
4142
private final ReentrantLock lock;
4243

4344
private List<Throwable> failures;
45+
private long lastReset;
4446
private long lastRecordedErrorNs;
4547
@Nullable private BackoffResult lastBackoffResult;
4648
@Nullable private ScheduledFuture<?> pendingBackoff;
@@ -57,7 +59,8 @@ final class DefaultRetryContext implements RetryContext {
5759
Backoff.from(retryingDependencies.getRetrySettings()).setJitterer(jitterer).build();
5860
this.lock = new ReentrantLock();
5961
this.failures = new LinkedList<>();
60-
this.lastRecordedErrorNs = retryingDependencies.getClock().nanoTime();
62+
this.lastReset = retryingDependencies.getClock().nanoTime();
63+
this.lastRecordedErrorNs = this.lastReset;
6164
this.lastBackoffResult = null;
6265
this.pendingBackoff = null;
6366
}
@@ -80,7 +83,9 @@ public void reset() {
8083
if (failures.size() > 0) {
8184
failures = new LinkedList<>();
8285
}
83-
lastRecordedErrorNs = retryingDependencies.getClock().nanoTime();
86+
long now = retryingDependencies.getClock().nanoTime();
87+
lastReset = now;
88+
lastRecordedErrorNs = now;
8489
clearPendingBackoff();
8590
backoff.reset();
8691
} finally {
@@ -100,13 +105,13 @@ public <T extends Throwable> void recordError(T t, OnSuccess onSuccess, OnFailur
100105
lock.lock();
101106
try {
102107
long now = retryingDependencies.getClock().nanoTime();
103-
Duration elapsed = Duration.ofNanos(now - lastRecordedErrorNs);
108+
Duration elapsed = Duration.ofNanos(now - lastReset);
109+
Duration elapsedSinceLastRecordError = Duration.ofNanos(now - lastRecordedErrorNs);
104110
if (pendingBackoff != null && pendingBackoff.isDone()) {
105111
pendingBackoff = null;
106112
lastBackoffResult = null;
107113
} else if (pendingBackoff != null) {
108114
pendingBackoff.cancel(true);
109-
backoff.backoffInterrupted(elapsed);
110115
String message =
111116
String.format(
112117
"Previous backoff interrupted by this error (previousBackoff: %s, elapsed: %s)",
@@ -119,8 +124,7 @@ public <T extends Throwable> void recordError(T t, OnSuccess onSuccess, OnFailur
119124
maxAttempts = Integer.MAX_VALUE;
120125
}
121126
boolean shouldRetry = algorithm.shouldRetry(t, null);
122-
Duration cumulativeBackoff = backoff.getCumulativeBackoff();
123-
BackoffResult nextBackoff = backoff.nextBackoff(elapsed);
127+
BackoffResult nextBackoff = backoff.nextBackoff(elapsedSinceLastRecordError);
124128
String msgPrefix = null;
125129
if (shouldRetry && failureCount >= maxAttempts) {
126130
msgPrefix = "Operation failed to complete within attempt budget";
@@ -130,6 +134,7 @@ public <T extends Throwable> void recordError(T t, OnSuccess onSuccess, OnFailur
130134
msgPrefix = "Unretryable error";
131135
}
132136

137+
lastRecordedErrorNs = now;
133138
if (msgPrefix == null) {
134139
t.addSuppressed(BackoffComment.fromResult(nextBackoff));
135140
failures.add(t);
@@ -151,13 +156,14 @@ public <T extends Throwable> void recordError(T t, OnSuccess onSuccess, OnFailur
151156
} else {
152157
String msg =
153158
String.format(
159+
Locale.US,
154160
"%s (attempts: %d%s, elapsed: %s, nextBackoff: %s%s)%s",
155161
msgPrefix,
156162
failureCount,
157163
maxAttempts == Integer.MAX_VALUE
158164
? ""
159165
: String.format(", maxAttempts: %d", maxAttempts),
160-
cumulativeBackoff,
166+
elapsed,
161167
nextBackoff.errorString(),
162168
Durations.eq(backoff.getTimeout(), Durations.EFFECTIVE_INFINITY)
163169
? ""

‎google-cloud-storage/src/main/java/com/google/cloud/storage/Durations.java‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -48,4 +48,8 @@ static Duration min(Duration d1, Duration d2) {
4848
return d2;
4949
}
5050
}
51+
52+
static Duration min(Duration d1, Duration d2, Duration d3) {
53+
return min(min(d1, d2), d3);
54+
}
5155
}

‎google-cloud-storage/src/test/java/com/google/cloud/storage/BackoffTest.java‎

Lines changed: 63 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -48,23 +48,20 @@ public void interruptedBackoffOnlyAddsActualElapsedTimeToCumulative() {
4848
// start backoff of 2s
4949
assertThat(r1).isEqualTo(BackoffDuration.of(Duration.ofSeconds(2)));
5050
// higher level failures happens only 300ms into our 2s
51-
backoff.backoffInterrupted(Duration.ofMillis(300));
52-
53-
// record higher level failure
5451
BackoffResult r2 = backoff.nextBackoff(Duration.ofMillis(300));
5552
// backoff 4s (previous was 2s w/ 2.0 multiplier = 4s)
5653
// even though the previous backoff duration wasn't fully consumed, still use it as the basis
5754
// for the next backoff
5855
assertThat(r2).isEqualTo(BackoffDuration.of(Duration.ofSeconds(4)));
5956
// another failure 3s after the 4s backoff finished
60-
BackoffResult r3 = backoff.nextBackoff(Duration.ofSeconds(3));
57+
BackoffResult r3 = backoff.nextBackoff(Duration.ofSeconds(7));
6158
assertThat(r3).isEqualTo(BackoffDuration.of(Duration.ofSeconds(8)));
6259
// another failure 5s after the 8s backoff finished
63-
BackoffResult r4 = backoff.nextBackoff(Duration.ofSeconds(5));
60+
BackoffResult r4 = backoff.nextBackoff(Duration.ofSeconds(13));
6461
// 11s backoff because 11s is maxBackoff
6562
assertThat(r4).isEqualTo(BackoffDuration.of(Duration.ofSeconds(11)));
6663
// another failure 7s after the 11s backoff finished
67-
BackoffResult r5 = backoff.nextBackoff(Duration.ofSeconds(7));
64+
BackoffResult r5 = backoff.nextBackoff(Duration.ofSeconds(18));
6865
// at this point it has been ~39s, which is more than our timeout of 34s
6966
assertThat(r5).isEqualTo(BackoffResults.EXHAUSTED);
7067
}
@@ -73,19 +70,32 @@ public void interruptedBackoffOnlyAddsActualElapsedTimeToCumulative() {
7370
public void simple() {
7471
Backoff backoff = defaultBackoff();
7572

76-
assertThat(backoff.nextBackoff(ZERO)).isEqualTo(BackoffDuration.of(Duration.ofSeconds(2)));
77-
assertThat(backoff.nextBackoff(ZERO)).isEqualTo(BackoffDuration.of(Duration.ofSeconds(4)));
78-
assertThat(backoff.nextBackoff(ZERO)).isEqualTo(BackoffDuration.of(Duration.ofSeconds(8)));
79-
assertThat(backoff.nextBackoff(ZERO)).isEqualTo(BackoffDuration.of(Duration.ofSeconds(16)));
80-
assertThat(backoff.nextBackoff(ZERO)).isEqualTo(BackoffDuration.of(Duration.ofSeconds(32)));
81-
assertThat(backoff.nextBackoff(ZERO)).isEqualTo(BackoffDuration.of(Duration.ofSeconds(57)));
82-
assertThat(backoff.nextBackoff(ZERO)).isEqualTo(BackoffDuration.of(Duration.ofSeconds(57)));
83-
assertThat(backoff.nextBackoff(ZERO)).isEqualTo(BackoffDuration.of(Duration.ofSeconds(57)));
84-
assertThat(backoff.nextBackoff(ZERO)).isEqualTo(BackoffDuration.of(Duration.ofSeconds(57)));
85-
assertThat(backoff.nextBackoff(ZERO)).isEqualTo(BackoffDuration.of(Duration.ofSeconds(57)));
86-
assertThat(backoff.nextBackoff(ZERO)).isEqualTo(BackoffDuration.of(Duration.ofSeconds(57)));
87-
assertThat(backoff.nextBackoff(ZERO)).isEqualTo(BackoffDuration.of(Duration.ofSeconds(57)));
88-
assertThat(backoff.nextBackoff(ZERO)).isEqualTo(BackoffResults.EXHAUSTED);
73+
final BackoffResult r01 = backoff.nextBackoff(Duration.ofSeconds(2));
74+
assertThat(r01).isEqualTo(BackoffDuration.of(Duration.ofSeconds(2)));
75+
BackoffResult r02 = backoff.nextBackoff(((BackoffDuration) r01).getDuration());
76+
assertThat(r02).isEqualTo(BackoffDuration.of(Duration.ofSeconds(4)));
77+
BackoffResult r03 = backoff.nextBackoff(((BackoffDuration) r02).getDuration());
78+
assertThat(r03).isEqualTo(BackoffDuration.of(Duration.ofSeconds(8)));
79+
BackoffResult r04 = backoff.nextBackoff(((BackoffDuration) r03).getDuration());
80+
assertThat(r04).isEqualTo(BackoffDuration.of(Duration.ofSeconds(16)));
81+
BackoffResult r05 = backoff.nextBackoff(((BackoffDuration) r04).getDuration());
82+
assertThat(r05).isEqualTo(BackoffDuration.of(Duration.ofSeconds(32)));
83+
BackoffResult r06 = backoff.nextBackoff(((BackoffDuration) r05).getDuration());
84+
assertThat(r06).isEqualTo(BackoffDuration.of(Duration.ofSeconds(57)));
85+
BackoffResult r07 = backoff.nextBackoff(((BackoffDuration) r06).getDuration());
86+
assertThat(r07).isEqualTo(BackoffDuration.of(Duration.ofSeconds(57)));
87+
BackoffResult r08 = backoff.nextBackoff(((BackoffDuration) r07).getDuration());
88+
assertThat(r08).isEqualTo(BackoffDuration.of(Duration.ofSeconds(57)));
89+
BackoffResult r09 = backoff.nextBackoff(((BackoffDuration) r08).getDuration());
90+
assertThat(r09).isEqualTo(BackoffDuration.of(Duration.ofSeconds(57)));
91+
BackoffResult r10 = backoff.nextBackoff(((BackoffDuration) r09).getDuration());
92+
assertThat(r10).isEqualTo(BackoffDuration.of(Duration.ofSeconds(57)));
93+
BackoffResult r11 = backoff.nextBackoff(((BackoffDuration) r10).getDuration());
94+
assertThat(r11).isEqualTo(BackoffDuration.of(Duration.ofSeconds(57)));
95+
BackoffResult r12 = backoff.nextBackoff(((BackoffDuration) r11).getDuration());
96+
assertThat(r12).isEqualTo(BackoffDuration.of(Duration.ofSeconds(14)));
97+
BackoffResult r13 = backoff.nextBackoff(((BackoffDuration) r12).getDuration());
98+
assertThat(r13).isEqualTo(BackoffResults.EXHAUSTED);
8999
}
90100

91101
@Test
@@ -94,7 +104,7 @@ public void backoffDuration_min_of_backoff_maxBackoff_remainingFromTimeout() {
94104

95105
Duration elapsed = Duration.ofMinutes(6).plusSeconds(58);
96106
assertThat(backoff.nextBackoff(elapsed)).isEqualTo(BackoffDuration.of(Duration.ofSeconds(2)));
97-
assertThat(backoff.nextBackoff(ZERO)).isEqualTo(BackoffResults.EXHAUSTED);
107+
assertThat(backoff.nextBackoff(Duration.ofSeconds(2))).isEqualTo(BackoffResults.EXHAUSTED);
98108
}
99109

100110
@Test
@@ -121,7 +131,7 @@ public void resetWorks() {
121131

122132
assertThat(backoff.nextBackoff(Duration.ofSeconds(4)))
123133
.isEqualTo(BackoffDuration.of(Duration.ofSeconds(2)));
124-
assertThat(backoff.nextBackoff(ZERO)).isEqualTo(BackoffResults.EXHAUSTED);
134+
assertThat(backoff.nextBackoff(Duration.ofSeconds(2))).isEqualTo(BackoffResults.EXHAUSTED);
125135
backoff.reset();
126136
assertThat(backoff.nextBackoff(Duration.ofSeconds(10))).isEqualTo(BackoffResults.EXHAUSTED);
127137
}
@@ -150,7 +160,7 @@ public void onceExhaustedStaysExhaustedUntilReset() {
150160
* <p>This is primarily here to preserve behavior of {@link com.google.cloud.RetryHelper}.
151161
*/
152162
@Test
153-
public void ifANextBackoffWouldExceedTheTimeoutTheBackoffDurationShouldBeTruncated() {
163+
public void ifANextBackoffWouldExceedTheTimeoutTheBackoffDurationShouldBeTruncated_single() {
154164
Backoff backoff =
155165
Backoff.newBuilder()
156166
.setInitialBackoff(Duration.ofSeconds(2))
@@ -162,7 +172,37 @@ public void ifANextBackoffWouldExceedTheTimeoutTheBackoffDurationShouldBeTruncat
162172

163173
assertThat(backoff.nextBackoff(Duration.ofSeconds(22)))
164174
.isEqualTo(BackoffDuration.of(ofSeconds(2)));
165-
assertThat(backoff.nextBackoff(ZERO)).isEqualTo(BackoffResults.EXHAUSTED);
175+
assertThat(backoff.nextBackoff(Duration.ofSeconds(2))).isEqualTo(BackoffResults.EXHAUSTED);
176+
}
177+
178+
/**
179+
* If a next computed backoff would exceed the timeout, truncate the backoff to the amount of time
180+
* remaining until timeout.
181+
*
182+
* <p>This is primarily here to preserve behavior of {@link com.google.cloud.RetryHelper}.
183+
*/
184+
@Test
185+
public void ifANextBackoffWouldExceedTheTimeoutTheBackoffDurationShouldBeTruncated_multiple() {
186+
Duration timeout = ofSeconds(24);
187+
Backoff backoff =
188+
Backoff.newBuilder()
189+
.setInitialBackoff(Duration.ofSeconds(2))
190+
.setMaxBackoff(Duration.ofSeconds(6))
191+
.setTimeout(timeout)
192+
.setJitterer(Jitterer.noJitter())
193+
.setRetryDelayMultiplier(2.0)
194+
.build();
195+
196+
assertThat(backoff.getCumulativeBackoff()).isEqualTo(Duration.ZERO);
197+
BackoffResult r1 = backoff.nextBackoff(Duration.ofSeconds(21));
198+
assertThat(backoff.getCumulativeBackoff()).isEqualTo(Duration.ofSeconds(21));
199+
assertThat(r1).isEqualTo(BackoffDuration.of(Duration.ofSeconds(2)));
200+
BackoffResult r2 = backoff.nextBackoff(((BackoffDuration) r1).getDuration());
201+
assertThat(backoff.getCumulativeBackoff()).isEqualTo(Duration.ofSeconds(23));
202+
assertThat(r2).isEqualTo(BackoffDuration.of(Duration.ofSeconds(1)));
203+
BackoffResult r3 = backoff.nextBackoff(((BackoffDuration) r2).getDuration());
204+
assertThat(backoff.getCumulativeBackoff()).isEqualTo(Duration.ofSeconds(24));
205+
assertThat(r3).isEqualTo(BackoffResults.EXHAUSTED);
166206
}
167207

168208
@Test

‎google-cloud-storage/src/test/java/com/google/cloud/storage/DurationsTest.java‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,7 @@
2626
public final class DurationsTest {
2727

2828
private static final Duration ONE_SECOND = Duration.ofSeconds(1);
29+
private static final Duration TWO_SECONDS = Duration.ofSeconds(2);
2930

3031
@Test
3132
public void eq() throws Exception {
@@ -69,6 +70,7 @@ public void min() throws Exception {
6970
() -> assertThat(Durations.min(ZERO, ZERO)).isEqualTo(ZERO),
7071
() -> assertThat(Durations.min(ONE_SECOND, ONE_SECOND)).isEqualTo(ONE_SECOND),
7172
() -> assertThat(Durations.min(ZERO, ONE_SECOND)).isEqualTo(ZERO),
72-
() -> assertThat(Durations.min(ONE_SECOND, ZERO)).isEqualTo(ZERO));
73+
() -> assertThat(Durations.min(ONE_SECOND, ZERO)).isEqualTo(ZERO),
74+
() -> assertThat(Durations.min(ONE_SECOND, TWO_SECONDS, ZERO)).isEqualTo(ZERO));
7375
}
7476
}

0 commit comments

Comments
 (0)