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.

Sign up for GitHub

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

Jump to bottom

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

Open
jtb93 opened this issue Apr 18, 2024 · 10 comments · May be fixed by #1795
Open

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

jtb93 opened this issue Apr 18, 2024 · 10 comments · May be fixed by #1795
Assignees
@sfc-gh-snow-drivers-warsaw-dl
Labels
enhancement The issue is a request for improvement or a new feature status-triage_done Initial triage done, will be further handled by the driver team

Comments

@jtb93
Copy link

jtb93 commented Apr 18, 2024

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?
@jtb93 jtb93 added the feature label Apr 18, 2024
@github-actions github-actions bot changed the title Support Virtual Threads by using ReentrantLock instead of synchronized for SFSession#open SNOW-1335472: Support Virtual Threads by using ReentrantLock instead of synchronized for SFSession#open Apr 18, 2024
@sfc-gh-sghosh sfc-gh-sghosh self-assigned this Apr 22, 2024
@sfc-gh-sghosh sfc-gh-sghosh added the status-triage Issue is under initial triage label Apr 22, 2024
@sfc-gh-sghosh
Copy link
Contributor

sfc-gh-sghosh commented Apr 22, 2024 •
edited
Loading

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
Copy link
Author

jtb93 commented Apr 23, 2024

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!

@jtb93
Copy link
Author

jtb93 commented Apr 23, 2024

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
Copy link
Author

jtb93 commented Apr 23, 2024

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
Copy link
Author

jtb93 commented Apr 29, 2024

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
Copy link
Author

jtb93 commented May 6, 2024

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
Copy link
Contributor

sfc-gh-sghosh commented May 14, 2024 •
edited
Loading

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-sghosh added status-triage_done Initial triage done, will be further handled by the driver team enhancement The issue is a request for improvement or a new feature status-triage Issue is under initial triage and removed status-triage Issue is under initial triage status-triage_done Initial triage done, will be further handled by the driver team labels May 14, 2024
@jtb93
Copy link
Author

jtb93 commented May 20, 2024

@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!

@jtb93
Copy link
Author

jtb93 commented Jun 5, 2024

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
Copy link
Contributor

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.

@jtb93 jtb93 linked a pull request Jun 19, 2024 that will close this issue
Draft
12 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@sfc-gh-snow-drivers-warsaw-dl sfc-gh-snow-drivers-warsaw-dl

Labels
enhancement The issue is a request for improvement or a new feature status-triage_done Initial triage done, will be further handled by the driver team
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

SNOW-1335472: Use ReentrantLock instead of synchronized for SFSession#open jtb93/snowflake-jdbc
4 participants
@jtb93 @sfc-gh-dszmolka @sfc-gh-sghosh @sfc-gh-snow-drivers-warsaw-dl