Improve usefulness of SpannerTemplate logging

[guycall]

For each executed Spanner query I get the log line:

Query elapsed milliseconds: 0

In nearly ever instance the value is 0ms (and occasionally 1ms). Is this showing anything useful? Could it be improved?

It gets generated by this code https://github.com/GoogleCloudPlatform/spring-cloud-gcp/blob/main/spring-cloud-gcp-data-spanner/src/main/java/com/google/cloud/spring/data/spanner/core/SpannerTemplate.java#L510

When I switch on higher logging levels I see the following additonal details:

2023-06-13 11:27:14.651 DEBUG c.g.c.s.d.s.c.SpannerTemplate - Executing query : SELECT * ...
2023-06-13 11:27:14.651 DEBUG c.g.c.s.d.s.c.SpannerTemplate - Query elapsed milliseconds: 0
2023-06-13 11:27:14.651 DEBUG c.g.c.s.s.v.GapicSpannerRpc   - google.spanner.v1.Spanner/ExecuteStreamingSql[1f1fcbd]: Start: ...
2023-06-13 11:27:14.653 DEBUG c.g.c.s.s.v.GapicSpannerRpc   - google.spanner.v1.Spanner/ExecuteStreamingSql[1f1fcbd]: Send: ...
2023-06-13 11:27:14.736 DEBUG c.g.c.s.s.v.GapicSpannerRpc   - google.spanner.v1.Spanner/ExecuteStreamingSql[1f1fcbd]: Received: ...
2023-06-13 11:27:14.736 DEBUG c.g.c.s.s.v.GapicSpannerRpc   - google.spanner.v1.Spanner/ExecuteStreamingSql[1f1fcbd]: Closed with status Status{code=OK...

This suggests the Query elasped milliseconds comes before the query has been sent to Spanner. So I am unclear of the value. Would it be better to show the duration between the Start, Send, Received, Closed? Maybe even the server execution time if available:

Query executed: 2ms sending, 4ms executing, 20ms receiving

[blakeli0]

Thanks @guycall for reporting this issue! I reproduce it locally also. In short, this is a bug in our logging and Query elasped milliseconds currently dose not provide any value.
Cloud Spanner Java client library actually delay the execution of query until the first call to ResultSet#next(), this behavior is implemented as follows:

1. The result set has a ResumableStreamIterator that reads the gRPC stream.
2. That stream is started the first time ResultSet#next() is called.
   Special thanks to @olavloite for providing the above additional context!

Regarding what we can do in spring-cloud-gcp, I don't think we can provide additional log regarding Start, Send, Received, Closed, because it's up to the caller to decide when to actually call ResultSet#next(). We are probably going to delete the misleading logs you identified.