Add logging for long fetches for NestedSets.
Add logging for fetches which exceed the 5s threshold, including the serialized
size.
@@ -15,6 +15,7 @@ package com.google.devtools.build.lib.collect.nestedset;
import com.google.auto.value.AutoValue;
import com.google.common.annotations.VisibleForTesting;
+import com.google.common.base.Stopwatch;
import com.google.common.cache.Cache;
import com.google.common.cache.CacheBuilder;
import com.google.common.collect.ImmutableList;
@@ -33,11 +34,13 @@ import com.google.protobuf.CodedInputStream;
import com.google.protobuf.CodedOutputStream;
import java.io.ByteArrayOutputStream;
import java.io.IOException;
+import java.time.Duration;
import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.ExecutionException;
import java.util.concurrent.Executor;
+import java.util.logging.Logger;
import javax.annotation.Nullable;
/**
@@ -65,6 +68,10 @@ import javax.annotation.Nullable;
* recursively retrieving B using its fingerprint.
*/
public class NestedSetStore {
+
+ private static final Logger logger = Logger.getLogger(NestedSetStore.class.getName());
+ private static final Duration FETCH_FROM_STORAGE_LOGGING_THRESHOLD = Duration.ofSeconds(5);
+
/** Stores fingerprint -> NestedSet associations. */
public interface NestedSetStorageEndpoint {
/**
@@ -353,10 +360,19 @@ public class NestedSetStore {
return contents;
}
ListenableFuture<byte[]> retrieved = nestedSetStorageEndpoint.get(fingerprint);
+ Stopwatch fetchStopwatch = Stopwatch.createStarted();
future.setFuture(
Futures.transformAsync(
retrieved,
bytes -> {
+ Duration fetchDuration = fetchStopwatch.elapsed();
+ if (FETCH_FROM_STORAGE_LOGGING_THRESHOLD.compareTo(fetchDuration) < 0) {
+ logger.info(
+ String.format(
+ "NestedSet fetch took: %dms, size: %dB",
+ fetchDuration.toMillis(), bytes.length));
+ }
+
CodedInputStream codedIn = CodedInputStream.newInstance(bytes);
int numberOfElements = codedIn.readInt32();
DeserializationContext newDeserializationContext =
