Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: enable session leaks prevention by cleaning up long-running tra… #2655

Merged
merged 6 commits into from
Nov 15, 2023
Merged
Show file tree
Hide file tree
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -348,7 +348,8 @@ static InactiveTransactionRemovalOptions.Builder newBuilder() {
}

static class Builder {
private ActionOnInactiveTransaction actionOnInactiveTransaction;
private ActionOnInactiveTransaction actionOnInactiveTransaction =
ActionOnInactiveTransaction.WARN;
private Duration executionFrequency = Duration.ofMinutes(2);
private double usedSessionsRatioThreshold = 0.95;
private Duration idleTimeThreshold = Duration.ofMinutes(60L);
Expand Down Expand Up @@ -575,7 +576,7 @@ public Builder setBlockIfPoolExhausted() {
*
* @return this builder for chaining
*/
Builder setWarnIfInactiveTransactions() {
public Builder setWarnIfInactiveTransactions() {
this.inactiveTransactionRemovalOptions =
InactiveTransactionRemovalOptions.newBuilder()
.setActionOnInactiveTransaction(ActionOnInactiveTransaction.WARN)
Expand All @@ -594,7 +595,7 @@ Builder setWarnIfInactiveTransactions() {
*
* @return this builder for chaining
*/
Builder setWarnAndCloseIfInactiveTransactions() {
public Builder setWarnAndCloseIfInactiveTransactions() {
this.inactiveTransactionRemovalOptions =
InactiveTransactionRemovalOptions.newBuilder()
.setActionOnInactiveTransaction(ActionOnInactiveTransaction.WARN_AND_CLOSE)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -129,7 +129,7 @@ public void verifyDefaultInactiveTransactionRemovalOptions() {
InactiveTransactionRemovalOptions inactiveTransactionRemovalOptions =
sessionPoolOptions.getInactiveTransactionRemovalOptions();

assertFalse(sessionPoolOptions.warnInactiveTransactions());
assertTrue(sessionPoolOptions.warnInactiveTransactions());
assertFalse(sessionPoolOptions.warnAndCloseInactiveTransactions());
assertFalse(sessionPoolOptions.closeInactiveTransactions());
assertEquals(0.95, inactiveTransactionRemovalOptions.getUsedSessionsRatioThreshold(), 0.0);
Expand Down
82 changes: 82 additions & 0 deletions session-and-channel-pool-configuration.md
Original file line number Diff line number Diff line change
Expand Up @@ -281,3 +281,85 @@ This will cause the following to happen internally in the client library:
1. The `TransactionRunner` will automatically commit the transaction if the supplied user code
finished without any errors. The `Commit` RPC that is invoked uses a thread from the default gRPC
thread pool.

### Session Leak
A Spanner object of the Client Library has a limit on the number of maximum sessions. For example the
default value of `MaxSessions` in the Java Client Library is 400. You can configure these values at the time of
Client side Database object creation by passing in the `SessionPoolOptions`. 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 a session leak is that a transaction was started by the application but
never committed or rolled back. What you should do is simply call commit on the transaction at the
end of your transaction code. Spanner has two types of transactions, read only and read-write
transactions. When we perform a read in a read-write transaction we still need to commit it.

As shown in the example below, the `try-with-resources` block releases the session after it is complete.
If you don't use `try-with-resources` block, unless you explicitly call the `close()` method on all resources
such as `ResultSet` the session is not released back to the pool. If the transaction does not run within
`try-with-resources` block and if we don't close the resources explicitly, we will have a session leak.

```java
DatabaseClient client =
spanner.getDatabaseClient(DatabaseId.of("my-project", "my-instance", "my-database"));
try (ResultSet resultSet =
client.singleUse().executeQuery(Statement.of("select col1, col2 from my_table"))) {
while (resultSet.next()) {
// use the results.
}
}
```

#### Debugging and Resolving Session Leaks

##### Logging
Enabled by default, the logging option shares warn logs when you have exhausted >95% of your session pool.
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think for java we won't have this log right so we can remove the line?

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. The logs are pushed to a destination based on
how the log exporter is configured for the host application.

Comment on lines +322 to +325
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Are we logging in the Java client? Based on the comment above, I would expect 'No'.

If we are logging: I'm pretty sure that we are not pushing those logs to any 'destination based on how the log exporter is configured'.

Copy link
Contributor Author

@arpan14 arpan14 Oct 5, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Some of the other client libraries such as Node/Python, emit an additional log every-time the application uses > 95% of the sessions. In Java, we use the condition as a pre-condition for the algo but don't emit any log for this condition. We only emit one of the below logs,
a) WARN LOG - when there is an actual long-running transaction. This includes bunch of other pre-conditions conditions (lastUsedTime, type of Transaction, etc.)
OR b) WARN LOG - We have automatically cleaned a long running transaction

Now what I mean as pushing log to the exporter is - the logs will be stored in a destination as per what is configured for the application. For ex - Some apps may configure cloud logging while others could configure logs to be stored on separate files on the app server.

The note about the exporter is not too relevant for Java where there is a default logging behaviour and I think it was more relevant for other languages like Node where a default logging capability was absent. We added a custom logging capability in Node (as part of sessions leaks) where the default logging was console logs or you could define some other exporter.

LMK if this documentation can be better framed or excluded in context of Java client.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We're using java.util.logging for this, right? Then I would just explicitly call out that. So something like 'The warning is logged using java.util.logging.'. I think that most people know what they need to do to configure that, and can otherwise search for it.

``` java
final SessionPoolOptions sessionPoolOptions =
SessionPoolOptions.newBuilder().setWarnIfInactiveTransactions().build()

final Spanner spanner =
SpannerOptions.newBuilder()
.setSessionPoolOption(sessionPoolOptions)
.build()
.getService();
final DatabaseClient client = spanner.getDatabaseClient(databaseId);

// Example Log message to warn presence of long running transactions
// Detected long-running session <session-info>. To automatically remove long-running sessions, set SessionOption ActionOnInactiveTransaction
// to WARN_AND_CLOSE by invoking setWarnAndCloseIfInactiveTransactions() method. <Stack Trace and information on session>

```
##### Automatically clean inactive transactions
When the option to automatically clean inactive transactions is enabled, the client library will automatically spot
problematic transactions that are running for extremely long periods of 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.

``` java
final SessionPoolOptions sessionPoolOptions =
SessionPoolOptions.newBuilder().setWarnAndCloseIfInactiveTransactions().build()

final Spanner spanner =
SpannerOptions.newBuilder()
.setSessionPoolOption(sessionPoolOptions)
.build()
.getService();
final DatabaseClient client = spanner.getDatabaseClient(databaseId);

// Example Log message for when transaction is recycled
// Removing long-running session <Stack Trace and information on session>
```