Skip to content

Commit 92b1e07

Browse files
olavloiteolavloite
authored
feat: include thread name in traces (#3173)
Include the name of the tread that is executing a statement in the traces that are generated, so it is easier to debug concurrency issues. Sometimes, it is not clear whether a statement is being executed by a background worker thread or the main thread.
1 parent 943d649 commit 92b1e07

File tree

7 files changed

+121
-36
lines changed

7 files changed

+121
-36
lines changed

‎.readme-partials.yaml

+3-2
Original file line numberDiff line numberDiff line change
@@ -153,8 +153,9 @@ custom_content: |
153153
154154
#### OpenTelemetry SQL Statement Tracing
155155
The OpenTelemetry traces that are generated by the Java client include any request and transaction
156-
tags that have been set. The traces can also include the SQL statements that are executed. Enable
157-
this with the `enableExtendedTracing` option:
156+
tags that have been set. The traces can also include the SQL statements that are executed and the
157+
name of the thread that executes the statement. Enable this with the `enableExtendedTracing`
158+
option:
158159
159160
```
160161
SpannerOptions options = SpannerOptions.newBuilder()

‎README.md

+3-2
Original file line numberDiff line numberDiff line change
@@ -259,8 +259,9 @@ Spanner spanner = options.getService();
259259

260260
#### OpenTelemetry SQL Statement Tracing
261261
The OpenTelemetry traces that are generated by the Java client include any request and transaction
262-
tags that have been set. The traces can also include the SQL statements that are executed. Enable
263-
this with the `enableExtendedTracing` option:
262+
tags that have been set. The traces can also include the SQL statements that are executed and the
263+
name of the thread that executes the statement. Enable this with the `enableExtendedTracing`
264+
option:
264265

265266
```
266267
SpannerOptions options = SpannerOptions.newBuilder()

‎google-cloud-spanner/src/main/java/com/google/cloud/spanner/OpenTelemetryContextKeys.java

+30
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,30 @@
1+
/*
2+
* Copyright 2024 Google LLC
3+
*
4+
* Licensed under the Apache License, Version 2.0 (the "License");
5+
* you may not use this file except in compliance with the License.
6+
* You may obtain a copy of the License at
7+
*
8+
* http://www.apache.org/licenses/LICENSE-2.0
9+
*
10+
* Unless required by applicable law or agreed to in writing, software
11+
* distributed under the License is distributed on an "AS IS" BASIS,
12+
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13+
* See the License for the specific language governing permissions and
14+
* limitations under the License.
15+
*/
16+
17+
package com.google.cloud.spanner;
18+
19+
import com.google.api.core.InternalApi;
20+
import io.opentelemetry.context.ContextKey;
21+
22+
/**
23+
* Keys for OpenTelemetry context variables that are used by the Spanner client library. Only
24+
* intended for internal use.
25+
*/
26+
@InternalApi
27+
public class OpenTelemetryContextKeys {
28+
@InternalApi
29+
public static final ContextKey<String> THREAD_NAME_KEY = ContextKey.named("thread.name");
30+
}

‎google-cloud-spanner/src/main/java/com/google/cloud/spanner/SpannerOptions.java

+2
Original file line numberDiff line numberDiff line change
@@ -1383,6 +1383,7 @@ public Builder setEnableApiTracing(boolean enableApiTracing) {
13831383
*
13841384
* <ul>
13851385
* <li>db.statement: Contains the SQL statement that is being executed.
1386+
* <li>thread.name: The name of the thread that executes the statement.
13861387
* </ul>
13871388
*/
13881389
public Builder setEnableExtendedTracing(boolean enableExtendedTracing) {
@@ -1673,6 +1674,7 @@ public boolean isUseVirtualThreads() {
16731674
*
16741675
* <ul>
16751676
* <li>db.statement: Contains the SQL statement that is being executed.
1677+
* <li>thread.name: The name of the thread that executes the statement.
16761678
* </ul>
16771679
*/
16781680
public boolean isEnableExtendedTracing() {

‎google-cloud-spanner/src/main/java/com/google/cloud/spanner/TraceWrapper.java

+10
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@
1919
import com.google.cloud.spanner.Options.TagOption;
2020
import com.google.cloud.spanner.Options.TransactionOption;
2121
import com.google.cloud.spanner.SpannerOptions.TracingFramework;
22+
import com.google.common.base.MoreObjects;
2223
import io.opencensus.trace.BlankSpan;
2324
import io.opencensus.trace.Span;
2425
import io.opencensus.trace.Tracer;
@@ -41,6 +42,7 @@ class TraceWrapper {
4142
AttributeKey.stringKey("db.statement");
4243
private static final AttributeKey<List<String>> DB_STATEMENT_ARRAY_KEY =
4344
AttributeKey.stringArrayKey("db.statement");
45+
private static final AttributeKey<String> THREAD_NAME_KEY = AttributeKey.stringKey("thread.name");
4446

4547
private final Tracer openCensusTracer;
4648
private final io.opentelemetry.api.trace.Tracer openTelemetryTracer;
@@ -154,6 +156,7 @@ Attributes createStatementAttributes(Statement statement, Options options) {
154156
AttributesBuilder builder = Attributes.builder();
155157
if (this.enableExtendedTracing) {
156158
builder.put(DB_STATEMENT_KEY, statement.getSql());
159+
builder.put(THREAD_NAME_KEY, getTraceThreadName());
157160
}
158161
if (options != null && options.hasTag()) {
159162
builder.put(STATEMENT_TAG_KEY, options.tag());
@@ -172,6 +175,7 @@ Attributes createStatementBatchAttributes(Iterable<Statement> statements, Option
172175
StreamSupport.stream(statements.spliterator(), false)
173176
.map(Statement::getSql)
174177
.collect(Collectors.toList()));
178+
builder.put(THREAD_NAME_KEY, getTraceThreadName());
175179
}
176180
if (options != null && options.hasTag()) {
177181
builder.put(STATEMENT_TAG_KEY, options.tag());
@@ -180,4 +184,10 @@ Attributes createStatementBatchAttributes(Iterable<Statement> statements, Option
180184
}
181185
return Attributes.empty();
182186
}
187+
188+
private static String getTraceThreadName() {
189+
return MoreObjects.firstNonNull(
190+
Context.current().get(OpenTelemetryContextKeys.THREAD_NAME_KEY),
191+
Thread.currentThread().getName());
192+
}
183193
}

‎google-cloud-spanner/src/main/java/com/google/cloud/spanner/connection/AbstractBaseUnitOfWork.java

+41-32
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,7 @@
2525
import com.google.cloud.spanner.BatchTransactionId;
2626
import com.google.cloud.spanner.Dialect;
2727
import com.google.cloud.spanner.ErrorCode;
28+
import com.google.cloud.spanner.OpenTelemetryContextKeys;
2829
import com.google.cloud.spanner.Options.QueryOption;
2930
import com.google.cloud.spanner.Options.RpcPriority;
3031
import com.google.cloud.spanner.Partition;
@@ -47,6 +48,7 @@
4748
import io.grpc.Status;
4849
import io.opentelemetry.api.common.AttributeKey;
4950
import io.opentelemetry.api.trace.Span;
51+
import io.opentelemetry.context.Scope;
5052
import java.util.Collection;
5153
import java.util.Collections;
5254
import java.util.HashSet;
@@ -358,40 +360,47 @@ public <ReqT, RespT> ApiCallContext configure(
358360
}
359361
});
360362
}
361-
ApiFuture<T> f = statementExecutor.submit(context.wrap(callable));
362-
final SpannerAsyncExecutionException caller =
363-
callType == CallType.ASYNC
364-
? new SpannerAsyncExecutionException(statement.getStatement())
365-
: null;
366-
final ApiFuture<T> future =
367-
ApiFutures.catching(
368-
f,
369-
Throwable.class,
370-
input -> {
371-
if (caller != null) {
372-
input.addSuppressed(caller);
363+
// Register the name of the thread that called this method as the thread name that should be
364+
// traced.
365+
try (Scope ignore =
366+
io.opentelemetry.context.Context.current()
367+
.with(OpenTelemetryContextKeys.THREAD_NAME_KEY, Thread.currentThread().getName())
368+
.makeCurrent()) {
369+
ApiFuture<T> f = statementExecutor.submit(context.wrap(callable));
370+
final SpannerAsyncExecutionException caller =
371+
callType == CallType.ASYNC
372+
? new SpannerAsyncExecutionException(statement.getStatement())
373+
: null;
374+
final ApiFuture<T> future =
375+
ApiFutures.catching(
376+
f,
377+
Throwable.class,
378+
input -> {
379+
if (caller != null) {
380+
input.addSuppressed(caller);
381+
}
382+
throw SpannerExceptionFactory.asSpannerException(input);
383+
},
384+
MoreExecutors.directExecutor());
385+
synchronized (this) {
386+
this.currentlyRunningStatementFuture = future;
387+
}
388+
future.addListener(
389+
new Runnable() {
390+
@Override
391+
public void run() {
392+
synchronized (this) {
393+
if (currentlyRunningStatementFuture == future) {
394+
currentlyRunningStatementFuture = null;
395+
}
373396
}
374-
throw SpannerExceptionFactory.asSpannerException(input);
375-
},
376-
MoreExecutors.directExecutor());
377-
synchronized (this) {
378-
this.currentlyRunningStatementFuture = future;
379-
}
380-
future.addListener(
381-
new Runnable() {
382-
@Override
383-
public void run() {
384-
synchronized (this) {
385-
if (currentlyRunningStatementFuture == future) {
386-
currentlyRunningStatementFuture = null;
397+
if (isSingleUse()) {
398+
endUnitOfWorkSpan();
387399
}
388400
}
389-
if (isSingleUse()) {
390-
endUnitOfWorkSpan();
391-
}
392-
}
393-
},
394-
MoreExecutors.directExecutor());
395-
return future;
401+
},
402+
MoreExecutors.directExecutor());
403+
return future;
404+
}
396405
}
397406
}

‎google-cloud-spanner/src/test/java/com/google/cloud/spanner/connection/OpenTelemetryTracingTest.java

+32
Original file line numberDiff line numberDiff line change
@@ -164,6 +164,14 @@ public boolean isEnableExtendedTracing() {
164164
"CloudSpannerOperation.ExecuteStreamingQuery",
165165
Attributes.of(AttributeKey.stringKey("db.statement"), SELECT1_STATEMENT.getSql()),
166166
spans);
167+
SpanData executeQuerySpan =
168+
getSpan(
169+
"CloudSpannerOperation.ExecuteStreamingQuery",
170+
Attributes.of(
171+
AttributeKey.stringKey("db.statement"), SELECT1_STATEMENT.getSql(),
172+
AttributeKey.stringKey("thread.name"), Thread.currentThread().getName()),
173+
spans);
174+
167175
assertParent(
168176
"CloudSpannerJdbc.SingleUseTransaction", "CloudSpanner.ReadOnlyTransaction", spans);
169177
assertParent(
@@ -190,6 +198,14 @@ public void testSingleUseQuery() {
190198
"CloudSpannerOperation.ExecuteStreamingQuery",
191199
Attributes.of(AttributeKey.stringKey("db.statement"), SELECT1_STATEMENT.getSql()),
192200
spans);
201+
SpanData executeQuerySpan =
202+
getSpan(
203+
"CloudSpannerOperation.ExecuteStreamingQuery",
204+
Attributes.of(
205+
AttributeKey.stringKey("db.statement"), SELECT1_STATEMENT.getSql(),
206+
AttributeKey.stringKey("thread.name"), Thread.currentThread().getName()),
207+
spans);
208+
193209
assertParent(
194210
"CloudSpannerJdbc.SingleUseTransaction", "CloudSpanner.ReadOnlyTransaction", spans);
195211
assertParent(
@@ -222,6 +238,13 @@ public void testSingleUseUpdate() {
222238
"CloudSpannerOperation.ExecuteUpdate",
223239
Attributes.of(AttributeKey.stringKey("db.statement"), INSERT_STATEMENT.getSql()),
224240
spans);
241+
SpanData executeQuerySpan =
242+
getSpan(
243+
"CloudSpannerOperation.ExecuteUpdate",
244+
Attributes.of(
245+
AttributeKey.stringKey("db.statement"), INSERT_STATEMENT.getSql(),
246+
AttributeKey.stringKey("thread.name"), Thread.currentThread().getName()),
247+
spans);
225248
assertParent("CloudSpanner.ReadWriteTransaction", "CloudSpannerOperation.Commit", spans);
226249
}
227250

@@ -244,6 +267,15 @@ public void testSingleUseBatchUpdate() {
244267
AttributeKey.stringArrayKey("db.statement"),
245268
ImmutableList.of(INSERT_STATEMENT.getSql(), INSERT_STATEMENT.getSql())),
246269
spans);
270+
SpanData executeQuerySpan =
271+
getSpan(
272+
"CloudSpannerOperation.BatchUpdate",
273+
Attributes.of(
274+
AttributeKey.stringArrayKey("db.statement"),
275+
ImmutableList.of(INSERT_STATEMENT.getSql(), INSERT_STATEMENT.getSql())),
276+
spans);
277+
String threadName = executeQuerySpan.getAttributes().get(AttributeKey.stringKey("thread.name"));
278+
assertEquals(Thread.currentThread().getName(), threadName);
247279
assertContains("CloudSpannerOperation.Commit", spans);
248280

249281
assertParent(

0 commit comments

Comments
 (0)