Reading from a non-existent database causes the client to send many BatchCreateSessions RPCs

[sebright]

I noticed that reads to a non-existent database can be very slow to fail. I looked into the issue further and found that the client continues to send BatchCreateSessions RPCs after the read fails, so the additional BatchCreateSessions RPCs may be the cause of the slowness.

google-cloud-spanner: 3.1.2 and HEAD
grpc-java: 1.34.0

Reproducing slow reads

When I ran this test, the reads started out taking about 300 milliseconds. After five minutes, the logging showed that the reads had slowed down to about ten seconds.

import com.google.cloud.spanner.DatabaseId;
import com.google.cloud.spanner.InstanceConfigId;
import com.google.cloud.spanner.InstanceId;
import com.google.cloud.spanner.InstanceInfo;
import com.google.cloud.spanner.Key;
import com.google.cloud.spanner.Spanner;
import com.google.cloud.spanner.SpannerOptions;
import java.time.Duration;
import java.time.Instant;
import java.util.Arrays;
import java.util.logging.Level;
import java.util.logging.Logger;
import org.junit.Test;

public class BatchCreateSessionsTest {
  private static final Logger logger = Logger.getLogger(BatchCreateSessionsTest.class.getName());

  @Test
  public void testBatchCreateSessions() throws Exception {
    Spanner spanner = SpannerOptions.getDefaultInstance().getService();
    String projectId = spanner.getOptions().getProjectId();
    InstanceId instanceId = InstanceId.of(projectId, "my-instance");
    InstanceConfigId instanceConfigId = InstanceConfigId.of(projectId, "regional-us-central1");
    spanner
        .getInstanceAdminClient()
        .createInstance(
            InstanceInfo.newBuilder(instanceId)
                .setInstanceConfigId(instanceConfigId)
                .setDisplayName("my-instance")
                .setNodeCount(1)
                .build())
        .get();
    DatabaseId databaseId = DatabaseId.of(instanceId, "my-database");

    while (true) {
      Instant start = Instant.now();
      try {
        spanner
            .getDatabaseClient(databaseId)
            .singleUse()
            .readRow("MyTable", Key.of(0), Arrays.asList("MyColumn"));
      } catch (Exception e) {
        logger.log(Level.INFO, e.getMessage());
      } finally {
        Instant end = Instant.now();
        logger.log(Level.INFO, "Duration: " + Duration.between(start, end));
      }
    }
  }
}

Reproducing excessive calls to BatchCreateSessions

I initially noticed the high rate of BatchCreateSessions RPCs in OpenCensus RPC stats. However, I simplified the reproduction to avoid OpenCensus and issue #202 by instead adding a log statement before

java-spanner/google-cloud-spanner/src/main/java/com/google/cloud/spanner/SessionClient.java

Line 296 in 90ad9d6

List<com.google.spanner.v1.Session> sessions =

. Then I modified the test case above with this diff:

@@ -30,21 +30,18 @@ public class BatchCreateSessionsTest {
                 .setNodeCount(1)
                 .build())
         .get();
     DatabaseId databaseId = DatabaseId.of(instanceId, "my-database");
 
-    while (true) {
-      Instant start = Instant.now();
+    for (int i = 0; i < 2; i++) {
       try {
         spanner
             .getDatabaseClient(databaseId)
             .singleUse()
             .readRow("MyTable", Key.of(0), Arrays.asList("MyColumn"));
       } catch (Exception e) {
         logger.log(Level.INFO, e.getMessage());
-      } finally {
-        Instant end = Instant.now();
-        logger.log(Level.INFO, "Duration: " + Duration.between(start, end));
       }
     }
+    Thread.sleep(300_000);
   }
 }

The output seems to show that the client sends one BatchCreateSessions RPC every ten seconds for each failed read:

Running BatchCreateSessionsTest
Jan 04, 2021 10:14:37 PM com.google.auth.oauth2.DefaultCredentialsProvider warnAboutProblematicCredentials
WARNING: Your application has authenticated using end user credentials from Google Cloud SDK. We recommend that most server applications use service accounts instead. If your application continues to use end user credentials from Cloud SDK, you might receive a "quota exceeded" or "API not enabled" error. For more information about service accounts, see https://cloud.google.com/docs/authentication/.
Jan 04, 2021 10:14:58 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=25
Jan 04, 2021 10:14:58 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=25
Jan 04, 2021 10:14:58 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=25
Jan 04, 2021 10:14:58 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=25
Jan 04, 2021 10:14:59 PM BatchCreateSessionsTest testBatchCreateSessions
INFO: NOT_FOUND: com.google.api.gax.rpc.NotFoundException: io.grpc.StatusRuntimeException: NOT_FOUND: Database not found: projects/<project-id>/instances/my-instance/databases/my-database
resource_type: "type.googleapis.com/google.spanner.admin.database.v1.Database"
resource_name: "projects/<project-id>/instances/my-instance/databases/my-database"
description: "Database does not exist."

Jan 04, 2021 10:14:59 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=25
Jan 04, 2021 10:14:59 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=25
Jan 04, 2021 10:14:59 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=25
Jan 04, 2021 10:14:59 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=25
Jan 04, 2021 10:14:59 PM BatchCreateSessionsTest testBatchCreateSessions
INFO: NOT_FOUND: com.google.api.gax.rpc.NotFoundException: io.grpc.StatusRuntimeException: NOT_FOUND: Database not found: projects/<project-id>/instances/my-instance/databases/my-database
resource_type: "type.googleapis.com/google.spanner.admin.database.v1.Database"
resource_name: "projects/<project-id>/instances/my-instance/databases/my-database"
description: "Database does not exist."

Jan 04, 2021 10:15:08 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=100
Jan 04, 2021 10:15:09 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=100
Jan 04, 2021 10:15:18 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=100
Jan 04, 2021 10:15:19 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=100
Jan 04, 2021 10:15:28 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=100
Jan 04, 2021 10:15:29 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=100
Jan 04, 2021 10:15:38 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=100
Jan 04, 2021 10:15:39 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=100
Jan 04, 2021 10:15:48 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=100
Jan 04, 2021 10:15:49 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=100
Jan 04, 2021 10:15:58 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=100
Jan 04, 2021 10:15:59 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=100
Jan 04, 2021 10:16:08 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=100
Jan 04, 2021 10:16:09 PM com.google.cloud.spanner.SessionClient internalBatchCreateSessions
INFO: Calling BatchCreateSessions with sessionCount=100
...

[sebright]

@thiagotnunes Thanks for the fix!