olavloite
commented
1 month ago Possibly relevant changes between 0.37.0 and 0.38.0:
com.google.cloud:libraries-bomupgraded from 26.44.0 to 26.47.0- The upgrade of libraries-bom means:
com.google.cloud:google-cloud-spannerbumped from 6.72.0 to 6.74.1 - v0.38.0 added support for shutdown modes SMART, FAST, and IMMEDIATE and added shutdown handlers.
- v0.38.0 added support for the open-source Golang migrate project. These changes only add a detection mechanism for the project, and a some simple query workarounds.
Possibly relevant changes between google-cloud-spanner 6.72.0 and 6.74.1:
- Cancel queries if the client is closed while queries are still running: https://github.com/googleapis/java-spanner/issues/3276
- Set the core pool size to 1 for the multiplexed session maintainer: https://github.com/googleapis/java-spanner/issues/3314
One interesting difference in the thread dumps:
- Both the broken thread dumps contain this entry:
"grpc-transport-17440" #18151 [18152] daemon prio=5 os_prio=0 cpu=4.50ms elapsed=8555.78s tid=0x00007dd26801e650 nid=18152 waiting on condition [0x00007dd26d5f9000]
java.lang.Thread.State: TIMED_WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@21.0.4/Native Method)
- parking to wait for <0x00000000caf17060> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(java.base@21.0.4/Unknown Source)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@21.0.4/Unknown Source)
at java.util.concurrent.LinkedBlockingQueue.poll(java.base@21.0.4/Unknown Source)
at com.google.cloud.spanner.GrpcStreamIterator.computeNext(GrpcStreamIterator.java:107)
at com.google.cloud.spanner.GrpcStreamIterator.computeNext(GrpcStreamIterator.java:35)
at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:145)
at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:140)
at com.google.cloud.spanner.ResumableStreamIterator.computeNext(ResumableStreamIterator.java:246)
at com.google.cloud.spanner.ResumableStreamIterator.computeNext(ResumableStreamIterator.java:55)
at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:145)
at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:140)
at com.google.cloud.spanner.GrpcValueIterator.ensureReady(GrpcValueIterator.java:134)
at com.google.cloud.spanner.GrpcValueIterator.getMetadata(GrpcValueIterator.java:110)
at com.google.cloud.spanner.GrpcResultSet.next(GrpcResultSet.java:81)
at com.google.cloud.spanner.SessionPool$PooledSession.keepAlive(SessionPool.java:1804)
at com.google.cloud.spanner.SessionPool$PooledSession.access$4900(SessionPool.java:1588)
at com.google.cloud.spanner.SessionPool$PoolMaintainer.keepAliveSessions(SessionPool.java:2133)
at com.google.cloud.spanner.SessionPool$PoolMaintainer.maintainPool(SessionPool.java:2066)
at com.google.cloud.spanner.SessionPool$PoolMaintainer$$Lambda/0x00007dd34a31fd40.run(Unknown Source)
at java.util.concurrent.Executors$RunnableAdapter.call(java.base@21.0.4/Unknown Source)
at java.util.concurrent.FutureTask.runAndReset(java.base@21.0.4/Unknown Source)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(java.base@21.0.4/Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@21.0.4/Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@21.0.4/Unknown Source)
at java.lang.Thread.runWith(java.base@21.0.4/Unknown Source)
at java.lang.Thread.run(java.base@21.0.4/Unknown Source)None of the working thread dumps contain this entry. This stack dump comes from the keep-alive queries in the normal session pool. Note that this should be unrelated to the change to the core pool size for maintaining multiplexed sessions, as that is a completely separate part of the code, and only sounds/look the same due to the names.
The thread dump seems to indicate that the keep-alive query is stuck while waiting for results to be returned from Spanner for a simple SELECT 1 query.
Current Behavior
Beginning in versions 0.38.0 and 0.39.0, we've randomly observed the following error from PGAdapter:
The deadline of ~55 seconds is expected since we run
SET statement_timeout = 55000;on every Read query to prevent Spanner from running queries longer than necessary.When a PGAdapter instance enters this unstable state, it seems some connections in the pool are tainted while others work just fine. We can run
psqlagainst a faulted instance and run simple queries (e.g.select * from table limit 1;) successfully a few times, but it will stall randomly and eventually time out with thewaiting_for_connectionerror. This stall occurs without astatement_timeoutset as well, we just won't see the error come through as it's attempting to run indefinitely.We have also seen this on write statements (e.g. UPDATE, INSERT) albeit with a lower timeout, 30 seconds, which does seem to match Spanner gRPC configuration defaults.
Reproducing the error state is quite difficult since we get all sorts of traffic to each pod and it only seems to manifest itself against one or two pods out of 120 at a time. It will generally occur 24 hours after a new Deployment, but sometimes will show up in as little as a few hours.
Reverting to version 0.37.0 fixes this behavior (so far at least).
Context (Environment)
Environment Variables: JDK_JAVA_OPTIONS = "-Xmx1600M -Xms1600M -XshowSettings:vm"