Skip to content

fix: higher application blocking latency precision #1676

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Mar 23, 2023
Merged

fix: higher application blocking latency precision #1676

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 6 additions & 4 deletions ...le/src/main/java/com/google/cloud/bigtable/data/v2/stub/metrics/BuiltinMetricsTracer.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -55,7 +55,7 @@ class BuiltinMetricsTracer extends BigtableTracer {
// Total server latency needs to be atomic because it's accessed from different threads. E.g.
// request() from user thread and attempt failed from grpc thread. We're only measuring the extra
// time application spent blocking grpc buffer, which will be operationLatency - serverLatency.
private final AtomicLong totalServerLatency = new AtomicLong(0);
private final AtomicLong totalServerLatencyNano = new AtomicLong(0);
// Stopwatch is not thread safe so this is a workaround to check if the stopwatch changes is
// flushed to memory.
private final Stopwatch serverLatencyTimer = Stopwatch.createUnstarted();
Expand Down Expand Up @@ -171,7 +171,7 @@ public void responseReceived() {
// In all the cases, we want to stop the serverLatencyTimer here.
synchronized (timerLock) {
if (serverLatencyTimerIsRunning) {
totalServerLatency.addAndGet(serverLatencyTimer.elapsed(TimeUnit.MILLISECONDS));
totalServerLatencyNano.addAndGet(serverLatencyTimer.elapsed(TimeUnit.NANOSECONDS));
serverLatencyTimer.reset();
serverLatencyTimerIsRunning = false;
}
Expand Down Expand Up @@ -233,6 +233,7 @@ private void recordOperationCompletion(@Nullable Throwable status) {
}
operationTimer.stop();
long operationLatency = operationTimer.elapsed(TimeUnit.MILLISECONDS);
long operationLatencyNano = operationTimer.elapsed(TimeUnit.NANOSECONDS);

// Only record when retry count is greater than 0 so the retry
// graph will be less confusing
Expand All @@ -242,7 +243,8 @@ private void recordOperationCompletion(@Nullable Throwable status) {

// serverLatencyTimer should already be stopped in recordAttemptCompletion
recorder.putOperationLatencies(operationLatency);
recorder.putApplicationLatencies(operationLatency - totalServerLatency.get());
recorder.putApplicationLatencies(
Duration.ofNanos(operationLatencyNano - totalServerLatencyNano.get()).toMillis());

if (operationType == OperationType.ServerStreaming
&& spanName.getMethodName().equals("ReadRows")) {
Expand All @@ -258,7 +260,7 @@ private void recordAttemptCompletion(@Nullable Throwable status) {
synchronized (timerLock) {
if (serverLatencyTimerIsRunning) {
requestLeft.decrementAndGet();
totalServerLatency.addAndGet(serverLatencyTimer.elapsed(TimeUnit.MILLISECONDS));
totalServerLatencyNano.addAndGet(serverLatencyTimer.elapsed(TimeUnit.NANOSECONDS));
serverLatencyTimer.reset();
serverLatencyTimerIsRunning = false;
}
Expand Down