Spanner: Add trace+timeout for waiting for sessions by olavloite · Pull Request #5703 · googleapis/google-cloud-java

olavloite · 2019-07-08T16:45:39Z

Adds a trace for waiting for a session from the session pool. The maximum wait time is default 30 seconds, and this time can be changed through SessionPoolOptions#setBlockForSessionTimeoutMillis(long).

kolea2 · 2019-07-08T19:09:29Z


 private PooledSession take() throws SpannerException {
- SessionOrError s = Uninterruptibles.takeUninterruptibly(waiter);
+ SessionOrError s = takeUninterruptiblyWithTimeout();


how come this needs to change?

The Uninterruptibles.takeUninterruptibly(waiter) will block indefinitely if the resource pool is exhausted because of a session leak. In order to be able to log that a session request is blocked, we need a trigger that will end the trace span and do the actual logging. That is what this timeout does.
This timeout is currently also propagated to the user as a DEADLINE_EXCEEDED SpannerException. We could choose to handle this internally and retry the session request after logging the timeout. That would retain the current behavior where the application will potentially block indefinitely in case of a session leak. My opinion is however that it would be better to propagate this error to the user in order to give the user more information on what is going on.

kolea2 · 2019-07-08T19:11:02Z

 this.writeSessionsFraction = builder.writeSessionsFraction;
 this.actionOnExhaustion = builder.actionOnExhaustion;
 this.actionOnSessionNotFound = builder.actionOnSessionNotFound;
+ this.waitForSessionTimeoutMillis = builder.blockForSessionTimeoutMillis;


can we make these variables all 'wait...' or all 'block..'

Changed to 'wait...'.

codecov · 2019-07-09T07:34:03Z

Codecov Report

Merging #5703 into master will increase coverage by 0.71%.
The diff coverage is n/a.

@@ Coverage Diff @@## master #5703 +/- ##
============================================
+ Coverage 46.71% 47.43% +0.71% - Complexity 24630 27180 +2550 
============================================
Files 2351 2522 +171 Lines 256127 274264 +18137 Branches 29325 31355 +2030 ============================================
+ Hits 119650 130089 +10439 - Misses 127558 134565 +7007 - Partials 8919 9610 +691

Impacted Files	Coverage Δ	Complexity Δ
...n/java/com/google/cloud/bigquery/BigQueryImpl.java	`66.78% <0%> (-13.22%)`	`57% <0%> (ø)`
.../java/com/google/cloud/testing/CommandWrapper.java	`87.87% <0%> (-9.1%)`	`13% <0%> (ø)`
...a/com/google/cloud/firestore/FirestoreOptions.java	`36.97% <0%> (-7.82%)`	`7% <0%> (ø)`
.../cloud/datastore/testing/LocalDatastoreHelper.java	`80.59% <0%> (-4.48%)`	`17% <0%> (ø)`
...ud/storage/contrib/nio/testing/FakeStorageRpc.java	`60.94% <0%> (-3.65%)`	`44% <0%> (+2%)`
...toring/v3/stub/NotificationChannelServiceStub.java	`7.69% <0%> (-2.31%)`	`1% <0%> (ø)`
...itoring/v3/NotificationChannelServiceSettings.java	`12.28% <0%> (-2.31%)`	`2% <0%> (ø)`
.../cloud/compute/v1/InsertTargetPoolHttpRequest.java	`22.08% <0%> (-1.85%)`	`8% <0%> (-1%)`
...able/gaxx/reframing/ReframingResponseObserver.java	`88.99% <0%> (-1.84%)`	`29% <0%> (-1%)`
...c/main/java/com/google/cloud/logging/SinkInfo.java	`82.03% <0%> (-1.78%)`	`19% <0%> (-2%)`
... and 713 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update c5d709c...7681477. Read the comment docs.

songy23 · 2019-08-13T17:44:54Z

- throw newSpannerException(s.e);
+ long currentTimeout = options.getInitialWaitForSessionTimeoutMillis();
+ while (true) {
+ Tracer tracer = Tracing.getTracer();


Nit: tracer can be made a private static field.

songy23 · 2019-08-13T17:49:43Z

+ <groupId>io.opencensus</groupId>
+ <artifactId>opencensus-impl</artifactId>
+ <version>${opencensus.version}</version>
+ <scope>test</scope>


This should be runtime only.

Changed to runtime.

songy23 · 2019-08-13T17:52:35Z

+ // End the span with status DEADLINE_EXCEEDED and retry.
+ tracer
+ .getCurrentSpan()
+ .end(EndSpanOptions.builder().setStatus(Status.DEADLINE_EXCEEDED).build());


Suggested change
.end(EndSpanOptions.builder().setStatus(Status.DEADLINE_EXCEEDED).build());
.setStatus(Status.DEADLINE_EXCEEDED);
You don't need to end the span here. When scope is closed, span will be ended automatically. See https://github.com/census-instrumentation/opencensus-java/blob/916adcbaba580cb223cb37ca34cf1f902903ede9/api/src/main/java/io/opencensus/trace/CurrentSpanUtils.java#L97-L103.

songy23 · 2019-08-13T17:53:12Z

+ if (s.e != null) {
+ throw newSpannerException(s.e);
+ }
+ tracer.getCurrentSpan().end();


Same here. You don't need to call this explicitly.

skuruppu · 2019-08-14T05:58:02Z

+ long currentTimeout = options.getInitialWaitForSessionTimeoutMillis();
+ while (true) {
+ Tracer tracer = Tracing.getTracer();
+ Scope waitScope = tracer.spanBuilder(WAIT_FOR_SESSION).startScopedSpan();


The standard way to create a scoped span is in a try block and then you don't explicitly have to close the scope [example].

Changed to try-with-resources block.

skuruppu · 2019-08-14T06:00:14Z

+ SessionOrError s = pollUninterruptiblyWithTimeout(currentTimeout);
+ if (s == null) {
+ // End the span with status DEADLINE_EXCEEDED and retry.
+ tracer


Instead of creating a span each time pollUninterruptiblyWithTimeout() is called, an alternative is to create a single span in take() then each time around the loop, add a trace annotation to indicate that the operation timed out. You can also add attributes to the annotation and which gives you the option to record the current timeout at each failure [example].
There might be a good reason why you chose to do multiple spans and I'd like to understand it.

The reason that I chose to create multiple spans, is that the take() method may block indefinitely, which would mean that the span would never be ended. Does a span that never ends, but that does add a trace annotation every 30 seconds, get flushed and sent to the server each time an annotation is added? If so, then I agree that having a single span in the take() would be the better solution. But to my (limited) knowledge of OpenCensus, the span needs to be closed before it is flushed.

I checked with @g-easy and you're right. The span will never be flushed if take() can block indefinitely so your implementation is the only way to get the trace information in this case.

skuruppu · 2019-08-14T06:01:10Z

+ if (s == null) {
+ // End the span with status DEADLINE_EXCEEDED and retry.
+ tracer
+ .getCurrentSpan()


[nit] Here and below, instead of calling tracer.getCurrentSpan() repeatedly, you can save it in a variable above all the if/else logic.

After the other changes after the review, the number of calls to tracer.getCurrentSpan() is now reduced to two, and both are only called if an exception occurs, so I would prefer to keep these two calls. But I agree with you that in the previous version of the code, that would have been better.

skuruppu · 2019-08-14T06:03:16Z

+ @Override
+ public void export(Collection<SpanData> spanDataList) {
+ for (SpanData sd : spanDataList) {
+ if (sd.getStatus() == Status.DEADLINE_EXCEEDED) {


Should this counter only be incremented for spans that match WAIT_FOR_SESSION?

Agree, that makes the test case less prone to false failures.

skuruppu · 2019-08-14T06:04:03Z

+ // finish.
+ checkedOutSession.close();
+ fut.get();
+ executor.shutdown();


close() and shutdown() should be done in a finally as we should be cleaning up regardless of whether the timeout happened or not.

process review comments

skuruppu

Thanks @olavloite for making the changes. This PR looks good from my perspective but I'll let @kolea2 do the final approval.

stale

skuruppu

@kolea2 gave me the go ahead to approve this change.

olavloite · 2019-08-16T07:12:08Z

@kolea2 Apparently, GitHub requires your explicit approval of this PR to allow merging :-)

add trace+timeout for waiting for sessions
34d51c4

olavloite requested a review from a teamJuly 8, 2019 16:45

googlebot added the cla: yes This human has signed the Contributor License Agreement. label Jul 8, 2019

kolea2 reviewed Jul 8, 2019
View reviewed changes

kolea2 previously requested changes Jul 8, 2019
View reviewed changes

change 'block' to 'wait'
727ee3f

olavloite requested a review from kolea2 July 12, 2019 15:41

olavloite added 4 commits July 16, 2019 11:33

session pool should block instead of propagate timeout
9cda674

allow more than 1 timeout per request in case of slow env
4632375

ran formatter
c32f233

removed unused import that was not removed by formatter
1a1dad2

chingor13 assigned kolea2 Jul 30, 2019

songy23 reviewed Aug 13, 2019
View reviewed changes

skuruppu reviewed Aug 14, 2019
View reviewed changes

olavloite added 3 commits August 14, 2019 09:13

tracer can be private static field
b2fb5e5
process review comments

only assert exports if there is an actual export component loaded
d21e078

increase timeout to avoid flakiness on slow envs
7681477

skuruppu reviewed Aug 15, 2019
View reviewed changes

skuruppu approved these changes Aug 16, 2019
View reviewed changes

olavloite requested review from kolea2 and removed request for kolea2 August 16, 2019 07:10

olavloite removed the request for review from kolea2 August 20, 2019 08:28

olavloite merged commit 9bfc925 into googleapis:masterAug 26, 2019

kolea2 mentioned this pull request Aug 28, 2019
Release google-cloud-java v0.107.0 #6188
Merged

	.end(EndSpanOptions.builder().setStatus(Status.DEADLINE_EXCEEDED).build());
	.setStatus(Status.DEADLINE_EXCEEDED);

Uh oh!

Conversation

olavloite commented Jul 8, 2019

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

codecovBot commented Jul 9, 2019• edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

skuruppu left a comment

Choose a reason for hiding this comment

Uh oh!

skuruppu left a comment

Choose a reason for hiding this comment

Uh oh!

olavloite commented Aug 16, 2019

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

codecovBot commented Jul 9, 2019•
edited
Loading