Spring Boot spanner latency problems

Question

I found our service has problems with latency and every single read statements is taking more than 40ms.

I tried to use native/derived queries and it always takes more than 40ms.

Reading data is really fast, it is taking below 1ms but from logs I can see that establishing grcp connection to Spanner takes most of the time.

logs from reading

10:16:36.485 [http-nio-8080-exec-2] [,] DEBUG o.s.web.servlet.DispatcherServlet - GET "/test", parameters={}
10:16:36.485 [http-nio-8080-exec-2] [,] DEBUG o.s.w.s.m.m.a.RequestMappingHandlerMapping - Mapped to edu.Controller#test()
10:16:36.485 [http-nio-8080-exec-2] [,] DEBUG o.s.o.j.s.OpenEntityManagerInViewInterceptor - Opening JPA EntityManager in OpenEntityManagerInViewInterceptor
10:16:36.485 [http-nio-8080-exec-2] [,] DEBUG c.g.c.s.d.s.c.SpannerTransactionManager - Creating new transaction with name [Repository.findById]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly
10:16:36.485 [http-nio-8080-exec-2] [,] DEBUG c.g.c.s.d.s.core.SpannerTemplate - Executing read on table test_table with keys: {[6fb703b4-59b4-4381-abd5-0594924c093c]} and columns: id, name
10:16:36.485 [http-nio-8080-exec-2] [,] DEBUG c.g.c.s.d.s.core.SpannerTemplate - Read elapsed milliseconds: 0
10:16:36.487 [grpc-default-worker-ELG-1-5] [,] DEBUG i.g.n.s.i.g.netty.NettyClientHandler - [id: 0xea23po983, L:/192.168.1.1:50000 - R:spanner.googleapis.com/200.200.200.200:443] OUTBOUND HEADERS: streamId=11 headers=GrpcHttp2OutboundHeaders[:authority: spanner.googleapis.com:443, :path: /google.spanner.v1.Spanner/BeginTransaction, :method: POST, :scheme: https
10:16:36.487 [grpc-default-worker-ELG-1-5] [,] DEBUG i.g.n.s.i.g.netty.NettyClientHandler - [id: 0xea23po983, L:/192.168.1.1:50000 - R:spanner.googleapis.com/200.200.200.200:443] OUTBOUND DATA: streamId=11 padding=0 endStream=true
10:16:36.525 [grpc-default-worker-ELG-1-5] [,] DEBUG i.g.n.s.i.g.netty.NettyClientHandler - [id: 0xea23po983, L:/192.168.1.1:50000 - R:spanner.googleapis.com/200.200.200.200:443] INBOUND HEADERS: streamId=11 headers=GrpcHttp2ResponseHeaders[:status: 200, content-type: application/grpc]

as you can see from timestamps of the last two logs it takes 39ms, I tried to use read only transactions, makes read without transaction, set rcp priority on SpannerTemplate to low but nothing helps and simple call to rest endpoint which is fetching object by id takes more than 40ms when reading from db takes less than 0ms.

Does anyone faced similar problems? And how I can fix / tune that?

The problem is not with Spanner. Your application takes 40 ms to return the data to the client. Look at the log for OUTBOUND DATA. That is an app->client networking issue. Summary: you do not have a problem to fix. The Internet is not infinitely fast. It will take time for the egress response to be consumed by the client. Since you have no control over the speed or quality of the client connection outside the cloud, there is nothing to solve except maybe to compress the response. 40 ms is actually a very fast response. — John Hanley
– John Hanley, Commented Dec 11, 2023 at 17:06
Hi @JohnHanley to be honest fetching simple object from database within 40ms does not sound to be very fast. From the logs we can also see "Read elapsed milliseconds: 0" which takes nanos. Moreover it is pretty fast as long as you don't call next() function on resultSet (Reulst set from google cloud spanner library). Once you do that it makes request for metadata to spanner and it takes more than 40ms. The same situation occurs when I deploy my app and it happens for 100% requests so it does not seems to be related with internet issues. — Wenaro
– Wenaro, Commented Dec 12, 2023 at 12:01
@Wenaro The Cloud Spanner Java client library defers some of the query execution to the first call to ResultSet#next(). See github.com/googleapis/java-spanner/blob/… Some of the 40ms that you are looking at is therefore most probably query execution and waiting for the first results. — Knut Olav Løite
– Knut Olav Løite, Commented Dec 15, 2023 at 8:31
@KnutOlavLøite but if I have endpoint for fetching object by id then every request to that service will defers some of the query execution to the first call to ResultSet#next() and every request fill take more than 40ms — Wenaro
– Wenaro, Commented Dec 15, 2023 at 9:57
I think that you need to try to dig into your application to determine exactly what part is taking most of the 40ms. A query that selects a single row from Cloud Spanner using the primary key and using a query parameter (so in JDBC using a java.sql.PreparedStatement) should be around 5ms. Things that could cause your query to take longer: 1. Your application is not running in the same region as Cloud Spanner 2. You are not selecting using the primary key 3. You are not using a parameterized query 4. etc... Without more info on your application, it is impossible to say. — Knut Olav Løite
– Knut Olav Løite, Commented Dec 15, 2023 at 14:13

Knut Olav Løite · Accepted Answer · 2023-12-11 09:47:45Z

0

It would be very helpful if you would also share an example of the code that you are executing.

In general:

The first time that you create a Cloud Spanner client and execute a query, the client will internally create a session pool and set up a connection to Cloud Spanner. This is a heavy operation that can take a 'long' time (tens of millieseconds). The initialization happens asynchronously. The query will have to wait for this to finish if it has not yet completed.
The second and further query that you execute on the same Cloud Spanner client will use the already created session pool and connection to Cloud Spanner. That means that the second and further queries should be quicker.

answered Dec 11, 2023 at 9:47

Knut Olav Løite

3,57710 silver badges23 bronze badges

Sign up to request clarification or add additional context in comments.

3 Comments

Wenaro Over a year ago

Even after tones of requests it always takes more than 40ms and it always takes this time on INBOUND HEADERS as we can see it from last two logs. I could not share the code example right now but I will try to prepare it. Service is using following dependencies 1. implementation platform('com.google.cloud:spring-cloud-gcp-dependencies:4.8.3') 2. implementation('com.google.cloud:spring-cloud-gcp-starter-data-spanner') 3. implementation 'com.google.cloud:google-cloud-spanner:6.52.1' and then simple derived query from repository findById(String id)

John Hanley Over a year ago

@Wenaro - The time it takes to transfer HEADERS is not a function of Spanner. That is the time it takes to transfer data from the client. You are misunderstanding where the latencies occur.

Wenaro Over a year ago

@JohnHanley I am not saying it is spanner problem. I even said that reading data is really fast from spanner but java driver takes 99% time to establish connection to fetch metadata about columns when u call next() function on resultSet. I also created a ticket on java-spanner: github.com/googleapis/java-spanner/issues/2757

Collectives™ on Stack Overflow

Spring Boot spanner latency problems

1 Answer 1

3 Comments

Your Answer

Hot Network Questions

Collectives™ on Stack Overflow

1 Answer 1

3 Comments

Your Answer

Sign up or log in

Post as a guest

Related