search

snowflakedb / snowflake-jdbc

Snowflake JDBC Driver
Apache License 2.0
178 stars 169 forks source link

SNOW-1335472: Support Virtual Threads by using `ReentrantLock` instead of `synchronized` for `SFSession#open` #1729

Open jtb93 opened 7 months ago

jtb93 commented 7 months ago

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 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?

sfc-gh-sghosh commented 7 months ago

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

jtb93 commented 7 months ago

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. :slightly_smiling_face:

Thanks!

jtb93 commented 7 months ago

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.

jtb93 commented 7 months ago

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)

jtb93 commented 6 months ago

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 :-)

jtb93 commented 6 months ago

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!

sfc-gh-sghosh commented 6 months ago

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

jtb93 commented 6 months ago

@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 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 lease(final T route, final Object state, final FutureCallback callback) { ... return new Future() { 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!

jtb93 commented 5 months ago

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.

sfc-gh-dszmolka commented 5 months ago

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.