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?

Answer 1

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

In general:

1. 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.
2. 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.