r2dbc core: Blocked main thread on createSslCustomizer

[magiccrafter]

Bug Description

The current version of the library seems to block the main thread with the latest Netty & R2DBC driver/SPI.

Profiling results:
CPU Utilization:

Between the 12th and 14th minutes, I've run a very light load test of 2 rps to troubleshoot the problem faster.

CPU Thread HotSpots:

Versions of the libraries used to reproduce the problem:
Spring Boot: 2.7.0
Nety Core: 4.1.77.Final
Reactor netty: 1.0.19
io.r2dbc:r2dbc spi: 0.9.1.RELEASE
io.r2dbc:r2dbc pool: 0.9.0.RELEASE
org.postgresql:r2dbc-postgresql:jar:0.9.1.RELEASE

for more details check the dependency tree:

[INFO] +- org.springframework.boot:spring-boot-starter-actuator:jar:2.7.0:compile
[INFO] |  +- org.springframework.boot:spring-boot-starter:jar:2.7.0:compile
[INFO] |  |  +- org.springframework.boot:spring-boot:jar:2.7.0:compile
[INFO] |  |  +- org.springframework.boot:spring-boot-starter-logging:jar:2.7.0:compile
[INFO] +- org.springframework.boot:spring-boot-starter-webflux:jar:2.7.0:compile
[INFO] |  +- org.springframework.boot:spring-boot-starter-json:jar:2.7.0:compile
[INFO] |  |  +- com.fasterxml.jackson.datatype:jackson-datatype-jdk8:jar:2.13.3:compile
[INFO] |  |  \- com.fasterxml.jackson.module:jackson-module-parameter-names:jar:2.13.3:compile
[INFO] |  +- org.springframework.boot:spring-boot-starter-reactor-netty:jar:2.7.0:compile
[INFO] |  |  \- io.projectreactor.netty:reactor-netty-http:jar:1.0.19:compile
[INFO] |  |     +- io.netty:netty-codec-http:jar:4.1.77.Final:compile
[INFO] |  |     +- io.netty:netty-codec-http2:jar:4.1.77.Final:compile
[INFO] |  |     +- io.netty:netty-resolver-dns:jar:4.1.77.Final:compile
[INFO] |  |     |  \- io.netty:netty-codec-dns:jar:4.1.77.Final:compile
[INFO] |  |     +- io.netty:netty-resolver-dns-native-macos:jar:osx-x86_64:4.1.77.Final:compile
[INFO] |  |     |  \- io.netty:netty-resolver-dns-classes-macos:jar:4.1.77.Final:compile
[INFO] |  |     \- io.netty:netty-transport-native-epoll:jar:linux-x86_64:4.1.77.Final:compile
[INFO] |  \- org.springframework:spring-webflux:jar:5.3.20:compile
[INFO] +- org.springframework.boot:spring-boot-starter-data-r2dbc:jar:2.7.0:compile
[INFO] |  +- org.springframework.data:spring-data-r2dbc:jar:1.5.0:compile
[INFO] |  |  +- org.springframework.data:spring-data-commons:jar:2.7.0:compile
[INFO] |  |  +- org.springframework.data:spring-data-relational:jar:2.4.0:compile
[INFO] |  |  \- org.springframework:spring-r2dbc:jar:5.3.20:compile
[INFO] |  +- io.r2dbc:r2dbc-spi:jar:0.9.1.RELEASE:compile
[INFO] |  \- io.r2dbc:r2dbc-pool:jar:0.9.0.RELEASE:compile
[INFO] |     \- io.projectreactor.addons:reactor-pool:jar:0.2.8:compile
[INFO] +- org.postgresql:r2dbc-postgresql:jar:0.9.1.RELEASE:compile
[INFO] |  +- com.ongres.scram:client:jar:2.1:compile
[INFO] |  |  \- com.ongres.scram:common:jar:2.1:compile
[INFO] |  |     \- com.ongres.stringprep:saslprep:jar:1.1:compile
[INFO] |  |        \- com.ongres.stringprep:stringprep:jar:1.1:compile
[INFO] |  \- io.projectreactor.netty:reactor-netty:jar:1.0.19:compile
[INFO] |     +- io.projectreactor.netty:reactor-netty-core:jar:1.0.19:compile
[INFO] |     |  \- io.netty:netty-handler-proxy:jar:4.1.77.Final:compile
[INFO] |     |     \- io.netty:netty-codec-socks:jar:4.1.77.Final:compile
[INFO] |     +- io.projectreactor.netty.incubator:reactor-netty-incubator-quic:jar:0.0.8:runtime
[INFO] |     |  \- io.netty.incubator:netty-incubator-codec-native-quic:jar:linux-x86_64:0.0.26.Final:runtime
[INFO] |     |     \- io.netty.incubator:netty-incubator-codec-classes-quic:jar:0.0.26.Final:runtime
[INFO] |     \- io.projectreactor.netty:reactor-netty-http-brave:jar:1.0.19:runtime
[INFO] |        \- io.zipkin.brave:brave-instrumentation-http:jar:5.13.9:compile
[INFO] +- com.google.cloud.sql:cloud-sql-connector-r2dbc-postgres:jar:1.6.0:compile
[INFO] |  +- com.google.cloud.sql:cloud-sql-connector-r2dbc-core:jar:1.6.0:compile
[INFO] |  +- com.google.cloud.sql:jdbc-socket-factory-core:jar:1.6.0:compile
[INFO] |  |  +- com.github.jnr:jnr-unixsocket:jar:0.38.17:compile
[INFO] |  |  |  +- com.github.jnr:jnr-ffi:jar:2.2.11:compile
[INFO] |  |  |  |  +- com.github.jnr:jffi:jar:1.3.9:compile
[INFO] |  |  |  |  +- com.github.jnr:jffi:jar:native:1.3.9:runtime
[INFO] |  |  |  |  +- org.ow2.asm:asm-commons:jar:9.2:compile
[INFO] |  |  |  |  +- com.github.jnr:jnr-a64asm:jar:1.0.0:compile
[INFO] |  |  |  |  \- com.github.jnr:jnr-x86asm:jar:1.0.2:compile
[INFO] |  |  |  +- com.github.jnr:jnr-constants:jar:0.10.3:compile
[INFO] |  |  |  +- com.github.jnr:jnr-enxio:jar:0.32.13:compile
[INFO] |  |  |  \- com.github.jnr:jnr-posix:jar:3.1.15:compile
[INFO] |  |  +- org.ow2.asm:asm-util:jar:9.3:compile
[INFO] |  |  |  +- org.ow2.asm:asm:jar:9.3:compile
[INFO] |  |  |  +- org.ow2.asm:asm-tree:jar:9.3:compile
[INFO] |  |  |  \- org.ow2.asm:asm-analysis:jar:9.3:compile
[INFO] |  |  +- com.google.api-client:google-api-client:jar:1.34.0:compile
[INFO] |  |  |  +- com.google.oauth-client:google-oauth-client:jar:1.33.2:compile
[INFO] |  |  |  \- com.google.http-client:google-http-client-apache-v2:jar:1.41.7:compile
[INFO] |  |  +- org.checkerframework:checker-compat-qual:jar:2.5.5:compile
[INFO] |  |  +- com.google.apis:google-api-services-sqladmin:jar:v1beta4-rev20220323-1.32.1:compile
[INFO] |  |  \- com.google.api:gax:jar:2.16.0:compile
[INFO] |  \- io.netty:netty-handler:jar:4.1.77.Final:compile
[INFO] |     +- io.netty:netty-common:jar:4.1.77.Final:compile
[INFO] |     +- io.netty:netty-resolver:jar:4.1.77.Final:compile
[INFO] |     +- io.netty:netty-buffer:jar:4.1.77.Final:compile
[INFO] |     +- io.netty:netty-transport:jar:4.1.77.Final:compile
[INFO] |     \- io.netty:netty-codec:jar:4.1.77.Final:compile
[INFO] +- com.google.auth:google-auth-library-oauth2-http:jar:1.6.0:compile
[INFO] |  +- com.google.auto.value:auto-value-annotations:jar:1.9:compile
[INFO] |  +- com.google.auth:google-auth-library-credentials:jar:1.6.0:compile
[INFO] |  +- com.google.http-client:google-http-client:jar:1.41.7:compile
[INFO] |  |  +- org.apache.httpcomponents:httpclient:jar:4.5.13:compile
[INFO] |  |  +- org.apache.httpcomponents:httpcore:jar:4.4.15:compile
[INFO] |  |  +- com.google.j2objc:j2objc-annotations:jar:1.3:compile
[INFO] |  |  +- io.opencensus:opencensus-api:jar:0.31.0:compile
[INFO] |  |  \- io.opencensus:opencensus-contrib-http-util:jar:0.31.0:compile
[INFO] |  +- com.google.http-client:google-http-client-gson:jar:1.41.7:compile
[INFO] |  |  \- com.google.code.gson:gson:jar:2.9.0:compile
[INFO] |  \- com.google.guava:guava:jar:31.1-jre:compile
[INFO] |     +- com.google.guava:failureaccess:jar:1.0.1:compile
[INFO] |     \- com.google.guava:listenablefuture:jar:9999.0-empty-to-avoid-conflict-with-guava:compile
[INFO] +- org.postgresql:postgresql:jar:42.3.5:runtime
[INFO] |  \- org.checkerframework:checker-qual:jar:3.5.0:compile

Stacktrace

N/A

How to reproduce

1. Build a simple app with Spring Boot 2.7.0 and com.google.cloud.sql:cloud-sql-connector-r2dbc-postgres dependency to connect to a managed Postgres db in GCP

Environment

1. OS type and version: eclipse-temurin , tested with both debian and centos flavors
2. Java SDK version: 17
3. Socket Factory version: 1.6.0

[kurtisvg]

Hi @magiccrafter -- thanks for taking the time to look at this issue. @shubha-rajan has started looking into it, but we have a team event we're currently participating in so we probably won't have any update until next week.

In the meantime, it would be great if you can provide more details steps on reproducing this issue - a small sample app and instructions on how to identify the block is happening might be great.

[magiccrafter]

@kurtisvg , I've created this tiny project which you can use to reproduce the issue:
https://github.com/magiccrafter/spring-cloud-sql-proxy-ssl-issue

A baseline test run against local Postgres container proving that the issue is not in the SB and r2dbc libraries:

docker run -p 5432:5432 -e POSTGRES_USER=postgres -e POSTGRES_PASSWORD=postgres -e POSTGRES_DB=postgres -d postgres -N 20000

run locally against the dockerized postgres:

java -Dspring.profiles.active=dev -classpath ... com.example.sqlproxyissue.Application (similar in IDE)

Steps to reproduce the issue:

1. Replace all TODOs with a managed Posgres db of yours, which requires GKE with WI and IAM to be set accordingly
2. Deploy in kubernetes environment, i.e. GKE
3. curl http://localhost:8080/books/genN/10000 (GET) only one time
4. curl http://localhost:8080/books (GET) several times (blocking and very slow)

Steps to check the good behavior with the previous version of SB 2.6.6 and io.r2dbc:r2dbc-postgresql:

• exactly the same as the above in good_old_2.6 branch

The main difference is in the reactive r2dbc-postgresql library.

[kurtisvg]

Thanks for the work here, and sorry we haven't gotten a chance to look at this issue sooner -- we're stretch a little thin between holidays and summer vacations.

This is a priority for us to try and address before the next release.

[kurtisvg]

@magiccrafter I'm having some trouble replicating this -- in our own sample, it seems like my profiler is saying it's happening in a background thread. Can I ask what profiler you are using? Can you provide step by step instructions on how you are getting your results?

I'm unable to run your example -- no matter what I configure it just says "password must not be null"

[kurtisvg]

I've been playing around with this for couple of hours and managed to modify the app enough to get it to connect (I think?).

But something is still going wrong -- if I call 'genN/100` I'm getting the following error:

Failed to obtain R2DBC Connection; nested exception is io.r2dbc.postgresql.PostgresqlConnectionFactory$PostgresConnectionException: Cannot connect to IP/<unresolved>:3307

I don't really understand what this means -- our sample app seems to be working fine, so I don't think it's my configuration or set up. I am getting connections in my database, so it seems to be connecting okay. but I don't understand enough SpringBoot to know what's happening under the hood.

I'm going to bump this down to a p2 so it doesn't block the release -- not sure what's happening, but since we are unable to reproduce it I want to make it's a library problem and not an app problem.

[magiccrafter]

I've switched to cloud sql auth proxy for gcp (as a sidecar) to use the latest Spring Boot version. Since then we don't observe any performance issues. imo the root cause is with the version mismatch of the r2dbc-postgresql library in your lib and the one coming with SB. I will keep an eye on the project and once you upgrade to org.postgresql:r2dbc-postgresql:jar:0.9.1.RELEASE I may give it another try. Thanks.

[kurtisvg]

@magiccrafter ah interesting - so you suspect it's a problem between 0.8.12.RELEASE and 0.9.1.RELEASE? I will take a look a second and see why we haven't updated

[kurtisvg]

It looks like the problem was that the r2dbc driver moved group ids - I opened an issue on their repo (pgjdbc/r2dbc-postgresql#530) and manually bump our version: #909

[kurtisvg]

@magiccrafter It seems like the version we released yesterday should have the newer r2dbc library. Can you check and see if you still have an issue or not?

[kurtisvg]

Just wanted to follow up here. Did the new release solve the problem?

[magiccrafter]

I will check it after my holiday. In two/three weeks time.

[kurtisvg]

Thanks for the update! I'll close this out if I don't hear back in ~30 days or so