Spanner: Add trace+timeout for waiting for sessions #5703

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

...e-cloud-clients/google-cloud-spanner/src/main/java/com/google/cloud/spanner/SessionPool.java


    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

...-clients/google-cloud-spanner/src/main/java/com/google/cloud/spanner/SessionPoolOptions.java

    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

...e-cloud-clients/google-cloud-spanner/src/main/java/com/google/cloud/spanner/SessionPool.java

-        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

google-cloud-clients/google-cloud-spanner/pom.xml

+      <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

...e-cloud-clients/google-cloud-spanner/src/main/java/com/google/cloud/spanner/SessionPool.java

+            // 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

...e-cloud-clients/google-cloud-spanner/src/main/java/com/google/cloud/spanner/SessionPool.java

+            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

...e-cloud-clients/google-cloud-spanner/src/main/java/com/google/cloud/spanner/SessionPool.java

+      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

...e-cloud-clients/google-cloud-spanner/src/main/java/com/google/cloud/spanner/SessionPool.java

+          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

...e-cloud-clients/google-cloud-spanner/src/main/java/com/google/cloud/spanner/SessionPool.java

+          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

...oud-clients/google-cloud-spanner/src/test/java/com/google/cloud/spanner/SessionPoolTest.java

+          @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

...oud-clients/google-cloud-spanner/src/test/java/com/google/cloud/spanner/SessionPoolTest.java

+        // 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 team as a code owner July 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:master Aug 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);

Spanner: Add trace+timeout for waiting for sessions #5703

Spanner: Add trace+timeout for waiting for sessions #5703

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!

codecov bot 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

codecov bot commented Jul 9, 2019 •

edited

Loading