SNOW-1335472: Support Virtual Threads by using `ReentrantLock` instead of `synchronized` for `SFSession#open`
Opened this issue · 10 comments
What is the current behavior?
The SFSession#open
function is synchronized
, so when using Snowflake JDBC w/ Virtual Threads, pinning frequently occurs.
What is the desired behavior?
The same functionality can be implemented using ReentrantLock
and Virtual Thread pinning will be avoided. Happy to open a PR if there isn't a particular reason why synchronized
still needs to be used.
How would this improve snowflake-jdbc
?
Better performance and reliability of apps leveraging snowflake-jdbc
References, Other Background
Proposed implementation:
private final ReentrantLock openLock = new ReentrantLock();
...
/**
* Open a new database session
*
* @throws SFException this is a runtime exception
* @throws SnowflakeSQLException exception raised from Snowflake components
*/
public void open() throws SFException, SnowflakeSQLException {
openLock.lock();
try {
performSanityCheckOnProperties();
Map<SFSessionProperty, Object> connectionPropertiesMap = getConnectionPropertiesMap();
logger.debug(
"input: server={}, account={}, user={}, password={}, role={}, database={}, schema={},"
+ " warehouse={}, validate_default_parameters={}, authenticator={}, ocsp_mode={},"
+ " passcode_in_password={}, passcode={}, private_key={}, disable_socks_proxy={},"
+ " application={}, app_id={}, app_version={}, login_timeout={}, retry_timeout={}, network_timeout={},"
+ " query_timeout={}, tracing={}, private_key_file={}, private_key_file_pwd={}."
+ " session_parameters: client_store_temporary_credential={}, gzip_disabled={}",
connectionPropertiesMap.get(SFSessionProperty.SERVER_URL),
connectionPropertiesMap.get(SFSessionProperty.ACCOUNT),
connectionPropertiesMap.get(SFSessionProperty.USER),
!Strings.isNullOrEmpty((String) connectionPropertiesMap.get(SFSessionProperty.PASSWORD))
? "***"
: "(empty)",
connectionPropertiesMap.get(SFSessionProperty.ROLE),
connectionPropertiesMap.get(SFSessionProperty.DATABASE),
connectionPropertiesMap.get(SFSessionProperty.SCHEMA),
connectionPropertiesMap.get(SFSessionProperty.WAREHOUSE),
connectionPropertiesMap.get(SFSessionProperty.VALIDATE_DEFAULT_PARAMETERS),
connectionPropertiesMap.get(SFSessionProperty.AUTHENTICATOR),
getOCSPMode().name(),
connectionPropertiesMap.get(SFSessionProperty.PASSCODE_IN_PASSWORD),
!Strings.isNullOrEmpty((String) connectionPropertiesMap.get(SFSessionProperty.PASSCODE))
? "***"
: "(empty)",
connectionPropertiesMap.get(SFSessionProperty.PRIVATE_KEY) != null
? "(not null)"
: "(null)",
connectionPropertiesMap.get(SFSessionProperty.DISABLE_SOCKS_PROXY),
connectionPropertiesMap.get(SFSessionProperty.APPLICATION),
connectionPropertiesMap.get(SFSessionProperty.APP_ID),
connectionPropertiesMap.get(SFSessionProperty.APP_VERSION),
connectionPropertiesMap.get(SFSessionProperty.LOGIN_TIMEOUT),
connectionPropertiesMap.get(SFSessionProperty.RETRY_TIMEOUT),
connectionPropertiesMap.get(SFSessionProperty.NETWORK_TIMEOUT),
connectionPropertiesMap.get(SFSessionProperty.QUERY_TIMEOUT),
connectionPropertiesMap.get(SFSessionProperty.TRACING),
connectionPropertiesMap.get(SFSessionProperty.PRIVATE_KEY_FILE),
!Strings.isNullOrEmpty(
(String) connectionPropertiesMap.get(SFSessionProperty.PRIVATE_KEY_FILE_PWD))
? "***"
: "(empty)",
sessionParametersMap.get(CLIENT_STORE_TEMPORARY_CREDENTIAL),
connectionPropertiesMap.get(SFSessionProperty.GZIP_DISABLED));
HttpClientSettingsKey httpClientSettingsKey = getHttpClientKey();
logger.debug(
"connection proxy parameters: use_proxy={}, proxy_host={}, proxy_port={}, proxy_user={},"
+ " proxy_password={}, non_proxy_hosts={}, proxy_protocol={}",
httpClientSettingsKey.usesProxy(),
httpClientSettingsKey.getProxyHost(),
httpClientSettingsKey.getProxyPort(),
httpClientSettingsKey.getProxyUser(),
!Strings.isNullOrEmpty(httpClientSettingsKey.getProxyPassword()) ? "***" : "(empty)",
httpClientSettingsKey.getNonProxyHosts(),
httpClientSettingsKey.getProxyHttpProtocol());
// TODO: temporarily hardcode sessionParameter debug info. will be changed in the future
SFLoginInput loginInput = new SFLoginInput();
loginInput
.setServerUrl((String) connectionPropertiesMap.get(SFSessionProperty.SERVER_URL))
.setDatabaseName((String) connectionPropertiesMap.get(SFSessionProperty.DATABASE))
.setSchemaName((String) connectionPropertiesMap.get(SFSessionProperty.SCHEMA))
.setWarehouse((String) connectionPropertiesMap.get(SFSessionProperty.WAREHOUSE))
.setRole((String) connectionPropertiesMap.get(SFSessionProperty.ROLE))
.setValidateDefaultParameters(
connectionPropertiesMap.get(SFSessionProperty.VALIDATE_DEFAULT_PARAMETERS))
.setAuthenticator((String) connectionPropertiesMap.get(SFSessionProperty.AUTHENTICATOR))
.setOKTAUserName((String) connectionPropertiesMap.get(SFSessionProperty.OKTA_USERNAME))
.setAccountName((String) connectionPropertiesMap.get(SFSessionProperty.ACCOUNT))
.setLoginTimeout(loginTimeout)
.setRetryTimeout(retryTimeout)
.setAuthTimeout(authTimeout)
.setUserName((String) connectionPropertiesMap.get(SFSessionProperty.USER))
.setPassword((String) connectionPropertiesMap.get(SFSessionProperty.PASSWORD))
.setToken((String) connectionPropertiesMap.get(SFSessionProperty.TOKEN))
.setPasscodeInPassword(passcodeInPassword)
.setPasscode((String) connectionPropertiesMap.get(SFSessionProperty.PASSCODE))
.setConnectionTimeout(httpClientConnectionTimeout)
.setSocketTimeout(httpClientSocketTimeout)
.setAppId((String) connectionPropertiesMap.get(SFSessionProperty.APP_ID))
.setAppVersion((String) connectionPropertiesMap.get(SFSessionProperty.APP_VERSION))
.setSessionParameters(sessionParametersMap)
.setPrivateKey((PrivateKey) connectionPropertiesMap.get(SFSessionProperty.PRIVATE_KEY))
.setPrivateKeyFile(
(String) connectionPropertiesMap.get(SFSessionProperty.PRIVATE_KEY_FILE))
.setPrivateKeyFilePwd(
(String) connectionPropertiesMap.get(SFSessionProperty.PRIVATE_KEY_FILE_PWD))
.setApplication((String) connectionPropertiesMap.get(SFSessionProperty.APPLICATION))
.setServiceName(getServiceName())
.setOCSPMode(getOCSPMode())
.setHttpClientSettingsKey(httpClientSettingsKey)
.setDisableConsoleLogin(
connectionPropertiesMap.get(SFSessionProperty.DISABLE_CONSOLE_LOGIN) != null
? getBooleanValue(
connectionPropertiesMap.get(SFSessionProperty.DISABLE_CONSOLE_LOGIN))
: true);
// Enable or disable OOB telemetry based on connection parameter. Default is disabled.
// The value may still change later when session parameters from the server are read.
if (getBooleanValue(
connectionPropertiesMap.get(SFSessionProperty.CLIENT_OUT_OF_BAND_TELEMETRY_ENABLED))) {
TelemetryService.enable();
} else {
TelemetryService.disable();
}
// propagate OCSP mode to SFTrustManager. Note OCSP setting is global on JVM.
HttpUtil.initHttpClient(httpClientSettingsKey, null);
SFLoginOutput loginOutput =
SessionUtil.openSession(loginInput, connectionPropertiesMap, tracingLevel.toString());
isClosed = false;
authTimeout = loginInput.getAuthTimeout();
sessionToken = loginOutput.getSessionToken();
masterToken = loginOutput.getMasterToken();
idToken = loginOutput.getIdToken();
mfaToken = loginOutput.getMfaToken();
setDatabaseVersion(loginOutput.getDatabaseVersion());
setDatabaseMajorVersion(loginOutput.getDatabaseMajorVersion());
setDatabaseMinorVersion(loginOutput.getDatabaseMinorVersion());
httpClientSocketTimeout = loginOutput.getHttpClientSocketTimeout();
masterTokenValidityInSeconds = loginOutput.getMasterTokenValidityInSeconds();
setDatabase(loginOutput.getSessionDatabase());
setSchema(loginOutput.getSessionSchema());
setRole(loginOutput.getSessionRole());
setWarehouse(loginOutput.getSessionWarehouse());
setSessionId(loginOutput.getSessionId());
setAutoCommit(loginOutput.getAutoCommit());
// Update common parameter values for this session
SessionUtil.updateSfDriverParamValues(loginOutput.getCommonParams(), this);
// Enable or disable HTAP OOB telemetry based on connection parameter. Default is disabled.
if (getBooleanValue(
connectionPropertiesMap.get(SFSessionProperty.HTAP_OOB_TELEMETRY_ENABLED))) {
TelemetryService.enableHTAP();
} else {
TelemetryService.disableHTAP();
}
String loginDatabaseName = (String) connectionPropertiesMap.get(SFSessionProperty.DATABASE);
String loginSchemaName = (String) connectionPropertiesMap.get(SFSessionProperty.SCHEMA);
String loginRole = (String) connectionPropertiesMap.get(SFSessionProperty.ROLE);
String loginWarehouse = (String) connectionPropertiesMap.get(SFSessionProperty.WAREHOUSE);
if (loginDatabaseName != null && !loginDatabaseName.equalsIgnoreCase(getDatabase())) {
sqlWarnings.add(
new SFException(
ErrorCode.CONNECTION_ESTABLISHED_WITH_DIFFERENT_PROP,
"Database",
loginDatabaseName,
getDatabase()));
}
if (loginSchemaName != null && !loginSchemaName.equalsIgnoreCase(getSchema())) {
sqlWarnings.add(
new SFException(
ErrorCode.CONNECTION_ESTABLISHED_WITH_DIFFERENT_PROP,
"Schema",
loginSchemaName,
getSchema()));
}
if (loginRole != null && !loginRole.equalsIgnoreCase(getRole())) {
sqlWarnings.add(
new SFException(
ErrorCode.CONNECTION_ESTABLISHED_WITH_DIFFERENT_PROP,
"Role",
loginRole,
getRole()));
}
if (loginWarehouse != null && !loginWarehouse.equalsIgnoreCase(getWarehouse())) {
sqlWarnings.add(
new SFException(
ErrorCode.CONNECTION_ESTABLISHED_WITH_DIFFERENT_PROP,
"Warehouse",
loginWarehouse,
getWarehouse()));
}
boolean disableQueryContextCache = getDisableQueryContextCacheOption();
logger.debug(
"Query context cache is {}", ((disableQueryContextCache) ? "disabled" : "enabled"));
// Initialize QCC
if (!disableQueryContextCache) {
qcc = new QueryContextCache(this.getQueryContextCacheSize());
} else {
qcc = null;
}
// start heartbeat for this session so that the master token will not expire
startHeartbeatForThisSession();
} finally {
openLock.unlock();
}
}
What is your Snowflake account identifier, if any?
Hello @jtb93 ,
Thanks for raising the issue, Could you please let us know how its impacting currently, please explain the scenario where and how it will improve the performance.
Please note: While ReentrantLock might provide better performance in some scenarios, it also incurs some overhead compared to the intrinsic locking mechanism provided by synchronized. And also the performance will vary as per scenarios.
The example which you quoted for "SFSession.open" , may not result in significant performance improvements. The reason is that the critical section of code protected by the lock (openLock) is not particularly long or complex. In this case, the critical section of code is relatively short, so the overhead of acquiring the lock is not likely to be a significant factor in overall performance.
will keep this thread posted.
Regards,
Sujan
Hi @sfc-gh-sghosh. The team behind the MariaDB JDBC driver team actually put out a pretty thorough write-up that does a good job of explaining the benefits.
And while the SFSession#open
code may not appear super long or complex on its own, performing any I/O within synchronized functions or blocks results in “pinning” (i.e. the small, fixed-size thread-pool of carrier threads, which Virtual Threads run on, gets blocked, effectively preventing the app from being able to serve concurrent requests).
My understanding is that pinning that either only occurs very infrequently (e.g. just at app start-up) or does not involve I/O is typically okay.
But when leveraging something like Spring Boot MVC w/ Virtual threads enabled + Snowflake JDBC, pinning happens repeatedly (as can be demonstrated by the numerous log messages that occur when the app is run w/ option -Djdk.tracePinnedThreads=short
).
LMK if I’m off-base conceptually, if something like a print-out of the log messages I am seeing would be helpful, or you have any advice on if there are any work-around approaches we could use to avoid and/or mitigate pinning other than swapping-in ReentrantLock
for synchronized
. 🙂
Thanks!
the overhead of acquiring the lock is not likely to be a significant factor in overall performance
And, for clarity, the overhead of acquiring the lock is not my concern. It's the pinning of the Virtual thread carrier threads that is the issue.
Compare the performance difference between the Maria DB + MySQL JDBC drivers.
I agree that any difference between ReentrantLock
and synchronized
in a vacuum is likely to be negligible. But when considering how Virtual Threads operate there is a substantial difference.
the overhead of acquiring the lock is not likely to be a significant factor in overall performance
And, for clarity, the overhead of acquiring the lock is not my concern. It's the pinning of the Virtual thread carrier threads that is the issue.
Compare the performance difference between the Maria DB + MySQL JDBC drivers.
I agree that any difference between ReentrantLock and synchronized in a vacuum is likely to be negligible. But when considering how Virtual Threads operate there is a substantial difference.
(Sorry for the double-post. Don't seem to be able to edit posts)
Hi @sfc-gh-sghosh , been about a week since I last heard from you. Any update?
My team is looking at making our decision whether or not to use Snowflake JDBC this week, so knowing if the library intends to support Virtual Threads or not would be really helpful :-)
Hi @sfc-gh-sghosh, it's been a couple weeks since I last heard from you. Any update yet or an approximate ETA for when status-triaging will be completed?
Thanks!
Hello @jtb93 ,
Sorry for the delay, and thanks for the update; we are checking internally with the team and will update.
Could you please provide us the logs from Spring boot MVC with virtual thread enabled when run w/ option -Djdk.tracePinnedThreads=short.
Regards,
Sujan
@sfc-gh-sghosh @sfc-gh-snow-drivers-warsaw-dl
Virtual Thread pinning using Spring Boot MVC w/ virtual threads enabled
Using net.snowflake:snowflake-jdbc
v3.16.0, Spring Boot MVC v3.2.5, and -Djdk.tracePinnedThreads=short
DEBUG 2024-05-18T03:29:45,060 - [snowflake-loom-3] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL query
DEBUG 2024-05-18T03:29:45,060 - [snowflake-loom-2] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL query
DEBUG 2024-05-18T03:29:45,060 - [snowflake-loom-1] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL query
DEBUG 2024-05-18T03:29:45,060 - [snowflake-loom-10] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL query
DEBUG 2024-05-18T03:29:45,060 - [snowflake-loom-9] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL query
DEBUG 2024-05-18T03:29:45,060 - [snowflake-loom-5] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL query
DEBUG 2024-05-18T03:29:45,060 - [snowflake-loom-8] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL query
DEBUG 2024-05-18T03:29:45,060 - [snowflake-loom-4] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL query
DEBUG 2024-05-18T03:29:45,060 - [snowflake-loom-7] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL query
DEBUG 2024-05-18T03:29:45,060 - [snowflake-loom-11] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL query
DEBUG 2024-05-18T03:29:45,060 - [snowflake-loom-6] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL query
DEBUG 2024-05-18T03:29:45,060 - [snowflake-loom-12] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL query
DEBUG 2024-05-18T03:29:45,061 - [snowflake-loom-10] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL statement [SELECT * FROM DATABASE.SCHEMA.TABLE LIMIT ? OFFSET ?]
DEBUG 2024-05-18T03:29:45,061 - [snowflake-loom-4] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL statement [SELECT * FROM DATABASE.SCHEMA.TABLE LIMIT ? OFFSET ?]
DEBUG 2024-05-18T03:29:45,061 - [snowflake-loom-11] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL statement [SELECT * FROM DATABASE.SCHEMA.TABLE LIMIT ? OFFSET ?]
DEBUG 2024-05-18T03:29:45,061 - [snowflake-loom-9] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL statement [SELECT * FROM DATABASE.SCHEMA.TABLE LIMIT ? OFFSET ?]
DEBUG 2024-05-18T03:29:45,061 - [snowflake-loom-3] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL statement [SELECT * FROM DATABASE.SCHEMA.TABLE LIMIT ? OFFSET ?]
DEBUG 2024-05-18T03:29:45,061 - [snowflake-loom-6] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL statement [SELECT * FROM DATABASE.SCHEMA.TABLE LIMIT ? OFFSET ?]
DEBUG 2024-05-18T03:29:45,061 - [snowflake-loom-8] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL statement [SELECT * FROM DATABASE.SCHEMA.TABLE LIMIT ? OFFSET ?]
DEBUG 2024-05-18T03:29:45,061 - [snowflake-loom-12] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL statement [SELECT * FROM DATABASE.SCHEMA.TABLE LIMIT ? OFFSET ?]
DEBUG 2024-05-18T03:29:45,061 - [snowflake-loom-5] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL statement [SELECT * FROM DATABASE.SCHEMA.TABLE LIMIT ? OFFSET ?]
DEBUG 2024-05-18T03:29:45,061 - [snowflake-loom-7] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL statement [SELECT * FROM DATABASE.SCHEMA.TABLE LIMIT ? OFFSET ?]
DEBUG 2024-05-18T03:29:45,061 - [snowflake-loom-2] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL statement [SELECT * FROM DATABASE.SCHEMA.TABLE LIMIT ? OFFSET ?]
DEBUG 2024-05-18T03:29:45,061 - [snowflake-loom-1] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL statement [SELECT * FROM DATABASE.SCHEMA.TABLE LIMIT ? OFFSET ?]
DEBUG 2024-05-18T03:29:45,063 - [snowflake-loom-11] org.springframework.jdbc.datasource.DataSourceUtils: Fetching JDBC Connection from DataSource
DEBUG 2024-05-18T03:29:45,063 - [snowflake-loom-6] org.springframework.jdbc.datasource.DataSourceUtils: Fetching JDBC Connection from DataSource
DEBUG 2024-05-18T03:29:45,063 - [snowflake-loom-1] org.springframework.jdbc.datasource.DataSourceUtils: Fetching JDBC Connection from DataSource
DEBUG 2024-05-18T03:29:45,063 - [snowflake-loom-7] org.springframework.jdbc.datasource.DataSourceUtils: Fetching JDBC Connection from DataSource
DEBUG 2024-05-18T03:29:45,063 - [snowflake-loom-4] org.springframework.jdbc.datasource.DataSourceUtils: Fetching JDBC Connection from DataSource
DEBUG 2024-05-18T03:29:45,063 - [snowflake-loom-10] org.springframework.jdbc.datasource.DataSourceUtils: Fetching JDBC Connection from DataSource
DEBUG 2024-05-18T03:29:45,063 - [snowflake-loom-8] org.springframework.jdbc.datasource.DataSourceUtils: Fetching JDBC Connection from DataSource
DEBUG 2024-05-18T03:29:45,063 - [snowflake-loom-9] org.springframework.jdbc.datasource.DataSourceUtils: Fetching JDBC Connection from DataSource
DEBUG 2024-05-18T03:29:45,063 - [snowflake-loom-2] org.springframework.jdbc.datasource.DataSourceUtils: Fetching JDBC Connection from DataSource
DEBUG 2024-05-18T03:29:45,063 - [snowflake-loom-3] org.springframework.jdbc.datasource.DataSourceUtils: Fetching JDBC Connection from DataSource
DEBUG 2024-05-18T03:29:45,063 - [snowflake-loom-12] org.springframework.jdbc.datasource.DataSourceUtils: Fetching JDBC Connection from DataSource
DEBUG 2024-05-18T03:29:45,063 - [snowflake-loom-5] org.springframework.jdbc.datasource.DataSourceUtils: Fetching JDBC Connection from DataSource
Thread[#51,ForkJoinPool-1-worker-3,5,CarrierThreads]
net.snowflake.client.jdbc.internal.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:253) <== monitors:1
net.snowflake.client.core.SFSession.open(SFSession.java:614) <== monitors:1
Thread[#50,ForkJoinPool-1-worker-2,5,CarrierThreads]
net.snowflake.client.jdbc.internal.apache.http.impl.conn.PoolingHttpClientConnectionManager.connect(PoolingHttpClientConnectionManager.java:376) <== monitors:1
net.snowflake.client.core.SFSession.open(SFSession.java:614) <== monitors:1
Thread[#61,ForkJoinPool-1-worker-7,5,CarrierThreads]
net.snowflake.client.jdbc.internal.apache.http.impl.conn.PoolingHttpClientConnectionManager.connect(PoolingHttpClientConnectionManager.java:376) <== monitors:1
net.snowflake.client.core.SFSession.open(SFSession.java:614) <== monitors:1
Thread[#50,ForkJoinPool-1-worker-2,5,CarrierThreads]
net.snowflake.client.jdbc.internal.apache.http.impl.conn.PoolingHttpClientConnectionManager.connect(PoolingHttpClientConnectionManager.java:376) <== monitors:1
net.snowflake.client.core.SFSession.open(SFSession.java:614) <== monitors:1
Thread[#75,ForkJoinPool-1-worker-9,5,CarrierThreads]
net.snowflake.client.core.SFSession.open(SFSession.java:614) <== monitors:1
Thread[#54,ForkJoinPool-1-worker-6,5,CarrierThreads]
net.snowflake.client.jdbc.internal.apache.http.impl.conn.PoolingHttpClientConnectionManager.upgrade(PoolingHttpClientConnectionManager.java:392) <== monitors:1
net.snowflake.client.core.SFSession.open(SFSession.java:614) <== monitors:1
Thread[#54,ForkJoinPool-1-worker-6,5,CarrierThreads]
net.snowflake.client.jdbc.internal.apache.http.impl.conn.PoolingHttpClientConnectionManager.upgrade(PoolingHttpClientConnectionManager.java:392) <== monitors:1
net.snowflake.client.core.SFSession.open(SFSession.java:614) <== monitors:1
Thread[#81,ForkJoinPool-1-worker-10,5,CarrierThreads]
net.snowflake.client.jdbc.internal.apache.http.impl.conn.PoolingHttpClientConnectionManager.upgrade(PoolingHttpClientConnectionManager.java:392) <== monitors:1
net.snowflake.client.core.SFSession.open(SFSession.java:614) <== monitors:1
Thread[#53,ForkJoinPool-1-worker-5,5,CarrierThreads]
net.snowflake.client.jdbc.internal.apache.http.impl.conn.PoolingHttpClientConnectionManager.upgrade(PoolingHttpClientConnectionManager.java:392) <== monitors:1
net.snowflake.client.core.SFSession.open(SFSession.java:614) <== monitors:1
Thread[#65,ForkJoinPool-1-worker-8,5,CarrierThreads]
net.snowflake.client.jdbc.internal.apache.http.impl.conn.PoolingHttpClientConnectionManager.upgrade(PoolingHttpClientConnectionManager.java:392) <== monitors:1
net.snowflake.client.core.SFSession.open(SFSession.java:614) <== monitors:1
Thread[#61,ForkJoinPool-1-worker-7,5,CarrierThreads]
net.snowflake.client.jdbc.internal.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:253) <== monitors:1
net.snowflake.client.jdbc.internal.apache.http.impl.conn.PoolingHttpClientConnectionManager.upgrade(PoolingHttpClientConnectionManager.java:392) <== monitors:1
net.snowflake.client.core.SFSession.open(SFSession.java:614) <== monitors:1
Thread[#54,ForkJoinPool-1-worker-6,5,CarrierThreads]
net.snowflake.client.jdbc.internal.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:253) <== monitors:1
net.snowflake.client.jdbc.internal.apache.http.impl.conn.PoolingHttpClientConnectionManager.upgrade(PoolingHttpClientConnectionManager.java:392) <== monitors:1
net.snowflake.client.core.SFSession.open(SFSession.java:614) <== monitors:1
Thread[#51,ForkJoinPool-1-worker-3,5,CarrierThreads]
net.snowflake.client.jdbc.internal.apache.http.impl.conn.PoolingHttpClientConnectionManager.connect(PoolingHttpClientConnectionManager.java:376) <== monitors:1
net.snowflake.client.jdbc.internal.apache.http.impl.conn.PoolingHttpClientConnectionManager.upgrade(PoolingHttpClientConnectionManager.java:392) <== monitors:1
net.snowflake.client.core.SFSession.open(SFSession.java:614) <== monitors:1
Thread[#51,ForkJoinPool-1-worker-3,5,CarrierThreads]
net.snowflake.client.jdbc.internal.apache.http.impl.conn.PoolingHttpClientConnectionManager.upgrade(PoolingHttpClientConnectionManager.java:392) <== monitors:1
net.snowflake.client.core.SFSession.open(SFSession.java:614) <== monitors:1
Thread[#51,ForkJoinPool-1-worker-3,5,CarrierThreads]
net.snowflake.client.jdbc.internal.apache.http.impl.conn.PoolingHttpClientConnectionManager.upgrade(PoolingHttpClientConnectionManager.java:392) <== monitors:1
net.snowflake.client.core.SFSession.open(SFSession.java:614) <== monitors:1
Thread[#54,ForkJoinPool-1-worker-6,5,CarrierThreads]
net.snowflake.client.core.SFSession.open(SFSession.java:614) <== monitors:1
Thread[#51,ForkJoinPool-1-worker-3,5,CarrierThreads]
net.snowflake.client.core.SFSession.open(SFSession.java:614) <== monitors:1
DEBUG 2024-05-18T03:29:47,208 - [snowflake-loom-13] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL query
DEBUG 2024-05-18T03:29:47,208 - [snowflake-loom-13] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL statement [SELECT * FROM DATABASE.SCHEMA.TABLE LIMIT ? OFFSET ?]
Thread[#92,ForkJoinPool-1-worker-12,5,CarrierThreads]
net.snowflake.client.jdbc.internal.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:253) <== monitors:1
net.snowflake.client.core.SFStatement.executeHelper(SFStatement.java:498) <== monitors:1
DEBUG 2024-05-18T03:29:47,208 - [snowflake-loom-13] org.springframework.jdbc.datasource.DataSourceUtils: Fetching JDBC Connection from DataSource
DEBUG 2024-05-18T03:29:47,213 - [snowflake-loom-14] org.springframework.jdbc.core.JdbcTemplate: Executing prepared SQL query
Thread[#54,ForkJoinPool-1-worker-6,5,CarrierThreads]
net.snowflake.client.jdbc.internal.apache.http.impl.conn.PoolingHttpClientConnectionManager.connect(PoolingHttpClientConnectionManager.java:376) <== monitors:1
net.snowflake.client.core.SFSession.open(SFSession.java:614) <== monitors:1
After swapping-out synchronized
for ReentrantLock
in SFSession#open
+ AbstractConnPool#lease(T, Object, FutureCallback)
SFSession#open
private final ReentrantLock openLock = new ReentrantLock();
...
/**
* Open a new database session
*
* @throws SFException this is a runtime exception
* @throws SnowflakeSQLException exception raised from Snowflake components
*/
public void open() throws SFException, SnowflakeSQLException {
openLock.lock();
try {
performSanityCheckOnProperties();
Map<SFSessionProperty, Object> connectionPropertiesMap = getConnectionPropertiesMap();
logger.debug(
"input: server={}, account={}, user={}, password={}, role={}, database={}, schema={},"
+ " warehouse={}, validate_default_parameters={}, authenticator={}, ocsp_mode={},"
+ " passcode_in_password={}, passcode={}, private_key={}, disable_socks_proxy={},"
+ " application={}, app_id={}, app_version={}, login_timeout={}, retry_timeout={}, network_timeout={},"
+ " query_timeout={}, tracing={}, private_key_file={}, private_key_file_pwd={}."
+ " session_parameters: client_store_temporary_credential={}, gzip_disabled={}",
connectionPropertiesMap.get(SFSessionProperty.SERVER_URL),
connectionPropertiesMap.get(SFSessionProperty.ACCOUNT),
connectionPropertiesMap.get(SFSessionProperty.USER),
!Strings.isNullOrEmpty((String) connectionPropertiesMap.get(SFSessionProperty.PASSWORD))
? "***"
: "(empty)",
connectionPropertiesMap.get(SFSessionProperty.ROLE),
connectionPropertiesMap.get(SFSessionProperty.DATABASE),
connectionPropertiesMap.get(SFSessionProperty.SCHEMA),
connectionPropertiesMap.get(SFSessionProperty.WAREHOUSE),
connectionPropertiesMap.get(SFSessionProperty.VALIDATE_DEFAULT_PARAMETERS),
connectionPropertiesMap.get(SFSessionProperty.AUTHENTICATOR),
getOCSPMode().name(),
connectionPropertiesMap.get(SFSessionProperty.PASSCODE_IN_PASSWORD),
!Strings.isNullOrEmpty((String) connectionPropertiesMap.get(SFSessionProperty.PASSCODE))
? "***"
: "(empty)",
connectionPropertiesMap.get(SFSessionProperty.PRIVATE_KEY) != null
? "(not null)"
: "(null)",
connectionPropertiesMap.get(SFSessionProperty.DISABLE_SOCKS_PROXY),
connectionPropertiesMap.get(SFSessionProperty.APPLICATION),
connectionPropertiesMap.get(SFSessionProperty.APP_ID),
connectionPropertiesMap.get(SFSessionProperty.APP_VERSION),
connectionPropertiesMap.get(SFSessionProperty.LOGIN_TIMEOUT),
connectionPropertiesMap.get(SFSessionProperty.RETRY_TIMEOUT),
connectionPropertiesMap.get(SFSessionProperty.NETWORK_TIMEOUT),
connectionPropertiesMap.get(SFSessionProperty.QUERY_TIMEOUT),
connectionPropertiesMap.get(SFSessionProperty.TRACING),
connectionPropertiesMap.get(SFSessionProperty.PRIVATE_KEY_FILE),
!Strings.isNullOrEmpty(
(String) connectionPropertiesMap.get(SFSessionProperty.PRIVATE_KEY_FILE_PWD))
? "***"
: "(empty)",
sessionParametersMap.get(CLIENT_STORE_TEMPORARY_CREDENTIAL),
connectionPropertiesMap.get(SFSessionProperty.GZIP_DISABLED));
HttpClientSettingsKey httpClientSettingsKey = getHttpClientKey();
logger.debug(
"connection proxy parameters: use_proxy={}, proxy_host={}, proxy_port={}, proxy_user={},"
+ " proxy_password={}, non_proxy_hosts={}, proxy_protocol={}",
httpClientSettingsKey.usesProxy(),
httpClientSettingsKey.getProxyHost(),
httpClientSettingsKey.getProxyPort(),
httpClientSettingsKey.getProxyUser(),
!Strings.isNullOrEmpty(httpClientSettingsKey.getProxyPassword()) ? "***" : "(empty)",
httpClientSettingsKey.getNonProxyHosts(),
httpClientSettingsKey.getProxyHttpProtocol());
// TODO: temporarily hardcode sessionParameter debug info. will be changed in the future
SFLoginInput loginInput = new SFLoginInput();
loginInput
.setServerUrl((String) connectionPropertiesMap.get(SFSessionProperty.SERVER_URL))
.setDatabaseName((String) connectionPropertiesMap.get(SFSessionProperty.DATABASE))
.setSchemaName((String) connectionPropertiesMap.get(SFSessionProperty.SCHEMA))
.setWarehouse((String) connectionPropertiesMap.get(SFSessionProperty.WAREHOUSE))
.setRole((String) connectionPropertiesMap.get(SFSessionProperty.ROLE))
.setValidateDefaultParameters(
connectionPropertiesMap.get(SFSessionProperty.VALIDATE_DEFAULT_PARAMETERS))
.setAuthenticator((String) connectionPropertiesMap.get(SFSessionProperty.AUTHENTICATOR))
.setOKTAUserName((String) connectionPropertiesMap.get(SFSessionProperty.OKTA_USERNAME))
.setAccountName((String) connectionPropertiesMap.get(SFSessionProperty.ACCOUNT))
.setLoginTimeout(loginTimeout)
.setRetryTimeout(retryTimeout)
.setAuthTimeout(authTimeout)
.setUserName((String) connectionPropertiesMap.get(SFSessionProperty.USER))
.setPassword((String) connectionPropertiesMap.get(SFSessionProperty.PASSWORD))
.setToken((String) connectionPropertiesMap.get(SFSessionProperty.TOKEN))
.setPasscodeInPassword(passcodeInPassword)
.setPasscode((String) connectionPropertiesMap.get(SFSessionProperty.PASSCODE))
.setConnectionTimeout(httpClientConnectionTimeout)
.setSocketTimeout(httpClientSocketTimeout)
.setAppId((String) connectionPropertiesMap.get(SFSessionProperty.APP_ID))
.setAppVersion((String) connectionPropertiesMap.get(SFSessionProperty.APP_VERSION))
.setSessionParameters(sessionParametersMap)
.setPrivateKey((PrivateKey) connectionPropertiesMap.get(SFSessionProperty.PRIVATE_KEY))
.setPrivateKeyFile((String) connectionPropertiesMap.get(SFSessionProperty.PRIVATE_KEY_FILE))
.setPrivateKeyFilePwd(
(String) connectionPropertiesMap.get(SFSessionProperty.PRIVATE_KEY_FILE_PWD))
.setApplication((String) connectionPropertiesMap.get(SFSessionProperty.APPLICATION))
.setServiceName(getServiceName())
.setOCSPMode(getOCSPMode())
.setHttpClientSettingsKey(httpClientSettingsKey)
.setDisableConsoleLogin(
connectionPropertiesMap.get(SFSessionProperty.DISABLE_CONSOLE_LOGIN) != null
? getBooleanValue(
connectionPropertiesMap.get(SFSessionProperty.DISABLE_CONSOLE_LOGIN))
: true);
// Enable or disable OOB telemetry based on connection parameter. Default is disabled.
// The value may still change later when session parameters from the server are read.
if (getBooleanValue(
connectionPropertiesMap.get(SFSessionProperty.CLIENT_OUT_OF_BAND_TELEMETRY_ENABLED))) {
TelemetryService.enable();
} else {
TelemetryService.disable();
}
// propagate OCSP mode to SFTrustManager. Note OCSP setting is global on JVM.
HttpUtil.initHttpClient(httpClientSettingsKey, null);
SFLoginOutput loginOutput =
SessionUtil.openSession(loginInput, connectionPropertiesMap, tracingLevel.toString());
isClosed = false;
authTimeout = loginInput.getAuthTimeout();
sessionToken = loginOutput.getSessionToken();
masterToken = loginOutput.getMasterToken();
idToken = loginOutput.getIdToken();
mfaToken = loginOutput.getMfaToken();
setDatabaseVersion(loginOutput.getDatabaseVersion());
setDatabaseMajorVersion(loginOutput.getDatabaseMajorVersion());
setDatabaseMinorVersion(loginOutput.getDatabaseMinorVersion());
httpClientSocketTimeout = loginOutput.getHttpClientSocketTimeout();
masterTokenValidityInSeconds = loginOutput.getMasterTokenValidityInSeconds();
setDatabase(loginOutput.getSessionDatabase());
setSchema(loginOutput.getSessionSchema());
setRole(loginOutput.getSessionRole());
setWarehouse(loginOutput.getSessionWarehouse());
setSessionId(loginOutput.getSessionId());
setAutoCommit(loginOutput.getAutoCommit());
// Update common parameter values for this session
SessionUtil.updateSfDriverParamValues(loginOutput.getCommonParams(), this);
// Enable or disable HTAP OOB telemetry based on connection parameter. Default is disabled.
if (getBooleanValue(
connectionPropertiesMap.get(SFSessionProperty.HTAP_OOB_TELEMETRY_ENABLED))) {
TelemetryService.enableHTAP();
} else {
TelemetryService.disableHTAP();
}
String loginDatabaseName = (String) connectionPropertiesMap.get(SFSessionProperty.DATABASE);
String loginSchemaName = (String) connectionPropertiesMap.get(SFSessionProperty.SCHEMA);
String loginRole = (String) connectionPropertiesMap.get(SFSessionProperty.ROLE);
String loginWarehouse = (String) connectionPropertiesMap.get(SFSessionProperty.WAREHOUSE);
if (loginDatabaseName != null && !loginDatabaseName.equalsIgnoreCase(getDatabase())) {
sqlWarnings.add(
new SFException(
ErrorCode.CONNECTION_ESTABLISHED_WITH_DIFFERENT_PROP,
"Database",
loginDatabaseName,
getDatabase()));
}
if (loginSchemaName != null && !loginSchemaName.equalsIgnoreCase(getSchema())) {
sqlWarnings.add(
new SFException(
ErrorCode.CONNECTION_ESTABLISHED_WITH_DIFFERENT_PROP,
"Schema",
loginSchemaName,
getSchema()));
}
if (loginRole != null && !loginRole.equalsIgnoreCase(getRole())) {
sqlWarnings.add(
new SFException(
ErrorCode.CONNECTION_ESTABLISHED_WITH_DIFFERENT_PROP, "Role", loginRole, getRole()));
}
if (loginWarehouse != null && !loginWarehouse.equalsIgnoreCase(getWarehouse())) {
sqlWarnings.add(
new SFException(
ErrorCode.CONNECTION_ESTABLISHED_WITH_DIFFERENT_PROP,
"Warehouse",
loginWarehouse,
getWarehouse()));
}
boolean disableQueryContextCache = getDisableQueryContextCacheOption();
logger.debug(
"Query context cache is {}", ((disableQueryContextCache) ? "disabled" : "enabled"));
// Initialize QCC
if (!disableQueryContextCache) {
qcc = new QueryContextCache(this.getQueryContextCacheSize());
} else {
qcc = null;
}
// start heartbeat for this session so that the master token will not expire
startHeartbeatForThisSession();
} finally {
openLock.unlock();
}
}
AbstractConnPool#lease(T, Object, FutureCallback)
public Future<E> lease(final T route, final Object state, final FutureCallback<E> callback) {
...
return new Future<E>() {
private final ReentrantLock getLock = new ReentrantLock();
...
public E get(long timeout, TimeUnit timeUnit) throws InterruptedException, ExecutionException, TimeoutException {
while(true) {
getLock.lock();
try {
...
} finally {
getLock.unlock();
}
}
}
};
}
Only remaining pinning that I am seeing is less common (and is less straightforward to address as the synchronized block causing the pinning uses an instance of an interface class as the monitor object).
Thread[#90,ForkJoinPool-1-worker-10,5,CarrierThreads]
net.snowflake.client.jdbc.internal.apache.http.impl.conn.PoolingHttpClientConnectionManager.releaseConnection(PoolingHttpClientConnectionManager.java:349) <== monitors:1
net.snowflake.client.jdbc.internal.apache.http.impl.execchain.ConnectionHolder.releaseConnection(ConnectionHolder.java:99) <== monitors:1
LMK if there's any else needed from my end!
Hi @sfc-gh-snow-drivers-warsaw-dl, it's been a few weeks since I last received an update, so just checking-in. LMK if there's anything I can do to help expedite things.
hi @jtb93 appreciate your interest in the matter. Your enhancement request is with the relevant team who will consider it for future plans, alongside with all the other enhancement requests, but we cannot commit to any timeline at this point.
If this capability is very important for your use-case, the best next step is to contact your Snowflake account team (your Sales rep. or the SE) and express the importance of the enhancement to them. They can help product management to reprioritize this request.
Alternatively of course if that's within your capabilities, you can also submit a PR with the implementation (I saw that mentioned somewhere in this issue?) which contribution is very much appreciated.