feat(spanner): enable long running transaction clean up (#8969)
* feat(spanner): enable long running txn clean up with default as WARN
* feat(spanner): remove mutex that does not exist in main branch
* feat(spanner): update tests
* feat(spanner): comment update
diff --git a/spanner/README.md b/spanner/README.md
index 54fbbc9..04757e9 100644
--- a/spanner/README.md
+++ b/spanner/README.md
@@ -31,4 +31,86 @@
if err != nil {
log.Fatal(err)
}
+```
+
+### Session Leak
+A `Client` object of the Client Library has a limit on the number of maximum sessions. For example the
+default value of `MaxOpened`, which is the maximum number of sessions allowed by the session pool in the
+Golang Client Library, is 400. You can configure these values at the time of
+creating a `Client` by passing custom `SessionPoolConfig` as part of `ClientConfig`. When all the sessions are checked
+out of the session pool, every new transaction has to wait until a session is returned to the pool.
+If a session is never returned to the pool (hence causing a session leak), the transactions will have to wait
+indefinitely and your application will be blocked.
+
+#### Common Root Causes
+The most common reason for session leaks in the Golang client library are:
+1. Not stopping a `RowIterator` that is returned by `Query`, `Read` and other methods. Always use `RowIterator.Stop()` to ensure that the `RowIterator` is always closed.
+2. Not closing a `ReadOnlyTransaction` when you no longer need it. Always call `ReadOnlyTransaction.Close()` after use, to ensure that the `ReadOnlyTransaction` is always closed.
+
+As shown in the example below, the `txn.Close()` statement releases the session after it is complete.
+If you fail to call `txn.Close()`, the session is not released back to the pool. The recommended way is to use `defer` as shown below.
+```go
+client, err := spanner.NewClient(ctx, "projects/P/instances/I/databases/D")
+if err != nil {
+ log.Fatal(err)
+}
+txn := client.ReadOnlyTransaction()
+defer txn.Close()
+```
+
+#### Debugging and Resolving Session Leaks
+
+##### Logging inactive transactions
+This option logs warnings when you have exhausted >95% of your session pool. It is enabled by default.
+This could mean two things; either you need to increase the max sessions in your session pool (as the number
+of queries run using the client side database object is greater than your session pool can serve), or you may
+have a session leak. To help debug which transactions may be causing this session leak, the logs will also contain stack traces of
+transactions which have been running longer than expected if `TrackSessionHandles` under `SessionPoolConfig` is enabled.
+
+```go
+sessionPoolConfig := spanner.SessionPoolConfig{
+ TrackSessionHandles: true,
+ InactiveTransactionRemovalOptions: spanner.InactiveTransactionRemovalOptions{
+ ActionOnInactiveTransaction: spanner.Warn,
+ },
+}
+client, err := spanner.NewClientWithConfig(
+ ctx, database, spanner.ClientConfig{SessionPoolConfig: sessionPoolConfig},
+)
+if err != nil {
+ log.Fatal(err)
+}
+defer client.Close()
+
+// Example Log message to warn presence of long running transactions
+// session <session-info> checked out of pool at <session-checkout-time> is long running due to possible session leak for goroutine
+// <Stack Trace of transaction>
+
+```
+
+##### Automatically clean inactive transactions
+When the option to automatically clean inactive transactions is enabled, the client library will automatically detect
+problematic transactions that are running for a very long time (thus causing session leaks) and close them.
+The session will be removed from the pool and be replaced by a new session. To dig deeper into which transactions are being
+closed, you can check the logs to see the stack trace of the transactions which might be causing these leaks and further
+debug them.
+
+```go
+sessionPoolConfig := spanner.SessionPoolConfig{
+ TrackSessionHandles: true,
+ InactiveTransactionRemovalOptions: spanner.InactiveTransactionRemovalOptions{
+ ActionOnInactiveTransaction: spanner.WarnAndClose,
+ },
+}
+client, err := spanner.NewClientWithConfig(
+ ctx, database, spanner.ClientConfig{SessionPoolConfig: sessionPoolConfig},
+)
+if err != nil {
+log.Fatal(err)
+}
+defer client.Close()
+
+// Example Log message for when transaction is recycled
+// session <session-info> checked out of pool at <session-checkout-time> is long running and will be removed due to possible session leak for goroutine
+// <Stack Trace of transaction>
```
\ No newline at end of file
diff --git a/spanner/client_test.go b/spanner/client_test.go
index f35b8ff..c6e180a 100644
--- a/spanner/client_test.go
+++ b/spanner/client_test.go
@@ -216,7 +216,7 @@
MinOpened: 1,
MaxOpened: 1,
InactiveTransactionRemovalOptions: InactiveTransactionRemovalOptions{
- actionOnInactiveTransaction: WarnAndClose,
+ ActionOnInactiveTransaction: WarnAndClose,
},
},
})
@@ -1044,7 +1044,7 @@
MinOpened: 1,
MaxOpened: 1,
InactiveTransactionRemovalOptions: InactiveTransactionRemovalOptions{
- actionOnInactiveTransaction: WarnAndClose,
+ ActionOnInactiveTransaction: WarnAndClose,
idleTimeThreshold: 300 * time.Millisecond,
},
},
@@ -1507,7 +1507,7 @@
MinOpened: 1,
MaxOpened: 1,
InactiveTransactionRemovalOptions: InactiveTransactionRemovalOptions{
- actionOnInactiveTransaction: WarnAndClose,
+ ActionOnInactiveTransaction: WarnAndClose,
},
},
})
@@ -1560,7 +1560,7 @@
MinOpened: 1,
MaxOpened: 1,
InactiveTransactionRemovalOptions: InactiveTransactionRemovalOptions{
- actionOnInactiveTransaction: WarnAndClose,
+ ActionOnInactiveTransaction: WarnAndClose,
idleTimeThreshold: 300 * time.Millisecond,
},
},
@@ -1660,7 +1660,7 @@
MinOpened: 1,
MaxOpened: 1,
InactiveTransactionRemovalOptions: InactiveTransactionRemovalOptions{
- actionOnInactiveTransaction: WarnAndClose,
+ ActionOnInactiveTransaction: WarnAndClose,
},
},
})
@@ -4232,7 +4232,7 @@
MaxOpened: 1,
healthCheckSampleInterval: 10 * time.Millisecond, // maintainer runs every 10ms
InactiveTransactionRemovalOptions: InactiveTransactionRemovalOptions{
- actionOnInactiveTransaction: WarnAndClose,
+ ActionOnInactiveTransaction: WarnAndClose,
executionFrequency: 15 * time.Millisecond, // check long-running sessions every 15ms
},
},
diff --git a/spanner/session.go b/spanner/session.go
index c23f665..11c47e5 100644
--- a/spanner/session.go
+++ b/spanner/session.go
@@ -59,9 +59,9 @@
// InactiveTransactionRemovalOptions has configurations for action on long-running transactions.
type InactiveTransactionRemovalOptions struct {
- // actionOnInactiveTransaction is the configuration to choose action for inactive transactions.
+ // ActionOnInactiveTransaction is the configuration to choose action for inactive transactions.
// It can be one of Warn, Close, WarnAndClose.
- actionOnInactiveTransaction ActionOnInactiveTransactionKind
+ ActionOnInactiveTransaction ActionOnInactiveTransactionKind
// long-running transactions will be cleaned up if utilisation is
// greater than the below value.
usedSessionsRatioThreshold float64
@@ -505,7 +505,7 @@
HealthCheckWorkers: 10,
HealthCheckInterval: healthCheckIntervalMins * time.Minute,
InactiveTransactionRemovalOptions: InactiveTransactionRemovalOptions{
- actionOnInactiveTransaction: NoAction, // Make default to Warn from NoAction later
+ ActionOnInactiveTransaction: Warn,
executionFrequency: 2 * time.Minute,
idleTimeThreshold: 60 * time.Minute,
usedSessionsRatioThreshold: 0.95,
@@ -635,8 +635,8 @@
if config.healthCheckSampleInterval == 0 {
config.healthCheckSampleInterval = time.Minute
}
- if config.actionOnInactiveTransaction == actionUnspecified {
- config.actionOnInactiveTransaction = DefaultSessionPoolConfig.actionOnInactiveTransaction
+ if config.ActionOnInactiveTransaction == actionUnspecified {
+ config.ActionOnInactiveTransaction = DefaultSessionPoolConfig.ActionOnInactiveTransaction
}
if config.idleTimeThreshold == 0 {
config.idleTimeThreshold = DefaultSessionPoolConfig.idleTimeThreshold
@@ -726,15 +726,15 @@
sh.mu.Lock()
diff := time.Now().Sub(sh.lastUseTime)
if !sh.eligibleForLongRunning && diff.Seconds() >= p.idleTimeThreshold.Seconds() {
- if (p.actionOnInactiveTransaction == Warn || p.actionOnInactiveTransaction == WarnAndClose) && !sh.isSessionLeakLogged {
- if p.actionOnInactiveTransaction == Warn {
+ if (p.ActionOnInactiveTransaction == Warn || p.ActionOnInactiveTransaction == WarnAndClose) && !sh.isSessionLeakLogged {
+ if p.ActionOnInactiveTransaction == Warn {
if sh.stack != nil {
logf(p.sc.logger, "session %s checked out of pool at %s is long running due to possible session leak for goroutine: \n%s", sh.session.getID(), sh.checkoutTime.Format(time.RFC3339), sh.stack)
} else {
logf(p.sc.logger, "session %s checked out of pool at %s is long running due to possible session leak for goroutine: \nEnable SessionPoolConfig.TrackSessionHandles to get stack trace associated with the session", sh.session.getID(), sh.checkoutTime.Format(time.RFC3339))
}
sh.isSessionLeakLogged = true
- } else if p.actionOnInactiveTransaction == WarnAndClose {
+ } else if p.ActionOnInactiveTransaction == WarnAndClose {
if sh.stack != nil {
logf(p.sc.logger, "session %s checked out of pool at %s is long running and will be removed due to possible session leak for goroutine: \n%s", sh.session.getID(), sh.checkoutTime.Format(time.RFC3339), sh.stack)
} else {
@@ -742,7 +742,7 @@
}
}
}
- if p.actionOnInactiveTransaction == WarnAndClose || p.actionOnInactiveTransaction == Close {
+ if p.ActionOnInactiveTransaction == WarnAndClose || p.ActionOnInactiveTransaction == Close {
longRunningSessions = append(longRunningSessions, sh)
}
}
@@ -760,7 +760,7 @@
p.mu.Unlock()
// destroy long-running sessions
- if p.actionOnInactiveTransaction == WarnAndClose || p.actionOnInactiveTransaction == Close {
+ if p.ActionOnInactiveTransaction == WarnAndClose || p.ActionOnInactiveTransaction == Close {
var leakedSessionsRemovedCount uint64
for _, sh := range longRunningSessions {
// removes inner session out of the pool to reduce the probability of two processes trying
@@ -895,7 +895,7 @@
// sessions being checked out of the pool.
func (p *sessionPool) newSessionHandle(s *session) (sh *sessionHandle) {
sh = &sessionHandle{session: s, checkoutTime: time.Now(), lastUseTime: time.Now()}
- if p.TrackSessionHandles || p.actionOnInactiveTransaction == Warn || p.actionOnInactiveTransaction == WarnAndClose || p.actionOnInactiveTransaction == Close {
+ if p.TrackSessionHandles || p.ActionOnInactiveTransaction == Warn || p.ActionOnInactiveTransaction == WarnAndClose || p.ActionOnInactiveTransaction == Close {
p.mu.Lock()
sh.trackedSessionHandle = p.trackedSessionHandles.PushBack(sh)
p.mu.Unlock()
@@ -1513,7 +1513,7 @@
// task to remove or log sessions which are unexpectedly long-running
if now.After(hc.pool.InactiveTransactionRemovalOptions.lastExecutionTime.Add(hc.pool.executionFrequency)) {
- if hc.pool.actionOnInactiveTransaction == Warn || hc.pool.actionOnInactiveTransaction == WarnAndClose || hc.pool.actionOnInactiveTransaction == Close {
+ if hc.pool.ActionOnInactiveTransaction == Warn || hc.pool.ActionOnInactiveTransaction == WarnAndClose || hc.pool.ActionOnInactiveTransaction == Close {
hc.pool.removeLongRunningSessions()
}
hc.pool.InactiveTransactionRemovalOptions.lastExecutionTime = now
diff --git a/spanner/session_test.go b/spanner/session_test.go
index a90f46f..43d4517 100644
--- a/spanner/session_test.go
+++ b/spanner/session_test.go
@@ -416,7 +416,7 @@
MinOpened: 0,
MaxOpened: 1,
InactiveTransactionRemovalOptions: InactiveTransactionRemovalOptions{
- actionOnInactiveTransaction: WarnAndClose,
+ ActionOnInactiveTransaction: WarnAndClose,
},
TrackSessionHandles: true,
},
@@ -489,7 +489,7 @@
MaxOpened: 3,
healthCheckSampleInterval: 10 * time.Millisecond, // maintainer runs every 10ms
InactiveTransactionRemovalOptions: InactiveTransactionRemovalOptions{
- actionOnInactiveTransaction: WarnAndClose,
+ ActionOnInactiveTransaction: WarnAndClose,
executionFrequency: 15 * time.Millisecond, // check long-running sessions every 20ms
},
},
@@ -560,7 +560,7 @@
MinOpened: 1,
MaxOpened: 3,
InactiveTransactionRemovalOptions: InactiveTransactionRemovalOptions{
- actionOnInactiveTransaction: WarnAndClose,
+ ActionOnInactiveTransaction: WarnAndClose,
},
},
})
@@ -628,7 +628,7 @@
MinOpened: 1,
MaxOpened: 3,
InactiveTransactionRemovalOptions: InactiveTransactionRemovalOptions{
- actionOnInactiveTransaction: Warn,
+ ActionOnInactiveTransaction: Warn,
},
},
})
@@ -715,7 +715,7 @@
MaxOpened: 3,
incStep: 1,
InactiveTransactionRemovalOptions: InactiveTransactionRemovalOptions{
- actionOnInactiveTransaction: WarnAndClose,
+ ActionOnInactiveTransaction: WarnAndClose,
},
},
})
@@ -774,7 +774,7 @@
MinOpened: 1,
MaxOpened: 3,
InactiveTransactionRemovalOptions: InactiveTransactionRemovalOptions{
- actionOnInactiveTransaction: Warn,
+ ActionOnInactiveTransaction: Warn,
},
},
})
@@ -842,7 +842,7 @@
MinOpened: 1,
MaxOpened: 3,
InactiveTransactionRemovalOptions: InactiveTransactionRemovalOptions{
- actionOnInactiveTransaction: Warn,
+ ActionOnInactiveTransaction: Warn,
},
},
})
