add logs with request latency for json readData/metaData API

gcsio/src/main/java/com/google/cloud/hadoop/gcsio/GoogleCloudStorageImpl.java

@@ -29,6 +29,7 @@
 import static java.lang.Math.min;
 import static java.lang.Math.toIntExact;
 import static java.util.Arrays.stream;
+import static java.util.concurrent.TimeUnit.MILLISECONDS;
 import static java.util.function.Function.identity;
 import static java.util.stream.Collectors.toMap;
 
@@ -66,6 +67,7 @@
 import com.google.cloud.hadoop.util.RetryDeterminer;
 import com.google.cloud.hadoop.util.RetryHttpInitializer;
 import com.google.common.annotations.VisibleForTesting;
+import com.google.common.base.Stopwatch;
 import com.google.common.cache.CacheBuilder;
 import com.google.common.cache.CacheLoader;
 import com.google.common.cache.LoadingCache;
@@ -2139,13 +2141,28 @@ private StorageObject getObject(StorageResourceId resourceId) throws IOException
             // Request only fields used in GoogleCloudStorageItemInfo:
             // https://cloud.google.com/storage/docs/json_api/v1/objects#resource-representations
             .setFields(OBJECT_FIELDS);
+    Stopwatch metadataStopwatch = Stopwatch.createStarted();
+
     try {
-      return getObject.execute();
+      StorageObject object = getObject.execute();
+
+      logger.atFinest().log(
+          "GoogleCloudStorageImpl:getMetadata complete context:%d,time:%d,resource:%s,requestId:%s",
+          Thread.currentThread().getId(),
+          metadataStopwatch.elapsed(MILLISECONDS),
+          resourceId,
+          getObject.getLastResponseHeaders().getFirstHeaderStringValue("x-guploader-uploadid"));
+      return object;
     } catch (IOException e) {
       if (errorExtractor.itemNotFound(e)) {
-        logger.atFiner().withCause(e).log("getObject(%s): not found", resourceId);
+        logger.atFiner().withCause(e).log(
+            "getObject(%s): not found, context:%d,time:%d",
+            resourceId, Thread.currentThread().getId(), metadataStopwatch.elapsed(MILLISECONDS));
         return null;
       }
+      logger.atSevere().withCause(e).log(
+          "GoogleCloudStorageImpl:getMetadata exception context:%d,time:%d,resource:%s",
+          Thread.currentThread().getId(), metadataStopwatch.elapsed(MILLISECONDS), resourceId);
       throw new IOException("Error accessing " + resourceId, e);
     }
   }

gcsio/src/main/java/com/google/cloud/hadoop/gcsio/GoogleCloudStorageReadChannel.java

@@ -23,6 +23,7 @@
 import static com.google.common.base.Strings.nullToEmpty;
 import static java.lang.Math.min;
 import static java.lang.Math.toIntExact;
+import static java.util.concurrent.TimeUnit.MILLISECONDS;
 
 import com.google.api.client.http.HttpHeaders;
 import com.google.api.client.http.HttpResponse;
@@ -39,6 +40,7 @@
 import com.google.cloud.hadoop.util.ResilientOperation;
 import com.google.cloud.hadoop.util.RetryDeterminer;
 import com.google.common.annotations.VisibleForTesting;
+import com.google.common.base.Stopwatch;
 import com.google.common.base.Suppliers;
 import com.google.common.flogger.GoogleLogger;
 import java.io.ByteArrayInputStream;
@@ -66,6 +68,8 @@ public class GoogleCloudStorageReadChannel implements SeekableByteChannel {
 
   private static final String GZIP_ENCODING = "gzip";
 
+  private static final String GCS_REQUEST_ID_HEADER = "x-guploader-uploadid";
+
   // GCS access instance.
   private final Storage gcs;
 
@@ -104,6 +108,8 @@ public class GoogleCloudStorageReadChannel implements SeekableByteChannel {
   // Size of the contentChannel.
   private long contentChannelEnd = -1;
 
+  private Stopwatch stopwatch;
+
   // Whether to use bounded range requests or streaming requests.
   @VisibleForTesting boolean randomAccess;
 
@@ -229,6 +235,7 @@ protected GoogleCloudStorageItemInfo getInitialMetadata() throws IOException {
   /** Returns {@link GoogleCloudStorageItemInfo} used to initialize metadata in constructor. */
   private GoogleCloudStorageItemInfo fetchInitialMetadata() throws IOException {
     StorageObject object;
+    Stopwatch metadataStopwatch = Stopwatch.createStarted();
     try {
       // Request only fields that are used for metadata initialization
       Storage.Objects.Get getObject = createRequest().setFields("contentEncoding,generation,size");
@@ -239,11 +246,26 @@ private GoogleCloudStorageItemInfo fetchInitialMetadata() throws IOException {
               RetryDeterminer.SOCKET_ERRORS,
               IOException.class,
               sleeper);
+
+      logger.atFinest().log(
+          "GoogleCloudStorageReadChannel:getMetadata complete context:%d,time:%d,resource:%s,requestId:%s",
+          Thread.currentThread().getId(),
+          metadataStopwatch.elapsed(MILLISECONDS),
+          resourceId,
+          getObject.getLastResponseHeaders().getFirstHeaderStringValue(GCS_REQUEST_ID_HEADER));
     } catch (IOException e) {
-      throw errorExtractor.itemNotFound(e)
-          ? createFileNotFoundException(resourceId, e)
-          : new IOException("Error reading " + resourceId, e);
+      if (errorExtractor.itemNotFound(e)) {
+        throw createFileNotFoundException(resourceId, e);
+      } else {
+        logger.atSevere().withCause(e).log(
+            "GoogleCloudStorageReadChannel:getMetadata exception context:%d,time:%d,resource:%s",
+            Thread.currentThread().getId(), metadataStopwatch.elapsed(MILLISECONDS), resourceId);
+        throw new IOException("Error reading " + resourceId, e);
+      }
     } catch (InterruptedException e) {
+      logger.atSevere().withCause(e).log(
+          "GoogleCloudStorageReadChannel:getMetadata exception context:%d,time:%d,resource:%s",
+          Thread.currentThread().getId(), metadataStopwatch.elapsed(MILLISECONDS), resourceId);
       Thread.currentThread().interrupt();
       throw new IOException("Thread interrupt received.", e);
     }
@@ -398,8 +420,12 @@ public int read(ByteBuffer buffer) throws IOException {
 
         ++retriesAttempted;
         logger.atWarning().withCause(ioe).log(
-            "Failed read retry #%s/%s for '%s'. Sleeping...",
-            retriesAttempted, maxRetries, resourceId);
+            "Failed read context:%d,retry:%s/%s,time:%d,resource:%s",
+            Thread.currentThread().getId(),
+            retriesAttempted,
+            maxRetries,
+            stopwatch.elapsed(MILLISECONDS),
+            resourceId);
         try {
           boolean backOffSuccessful = BackOffUtils.next(sleeper, readBackOff.get());
           if (!backOffSuccessful) {
@@ -930,7 +956,17 @@ protected InputStream openStream(long bytesToRead) throws IOException {
     Storage.Objects.Get getObject = createDataRequest(rangeHeader);
     HttpResponse response;
     try {
+      stopwatch = Stopwatch.createStarted();
       response = getObject.executeMedia();
+
+      logger.atFinest().log(
+          "openStream complete context:%d,time:%d,bytesToRead:%d,rangeSize:%d,resource:%s,requestId:%s",
+          Thread.currentThread().getId(),
+          stopwatch.elapsed(MILLISECONDS),
+          bytesToRead,
+          contentChannelEnd - contentChannelPosition,
+          resourceId,
+          response.getHeaders().getFirstHeaderStringValue(GCS_REQUEST_ID_HEADER));
       // TODO(b/110832992): validate response range header against expected/request range
     } catch (IOException e) {
       if (!metadataInitialized && errorExtractor.rangeNotSatisfiable(e) && currentPosition == 0) {
@@ -995,13 +1031,21 @@ protected InputStream openStream(long bytesToRead) throws IOException {
           cacheFooter(response);
           if (retriesCount != 0) {
             logger.atInfo().log(
-                "Successfully cached footer after %s retries for '%s'", retriesCount, resourceId);
+                "Successfully cached footer context:%d,retries:%s,time:%d,resource:%s",
+                Thread.currentThread().getId(),
+                retriesCount,
+                stopwatch.elapsed(MILLISECONDS),
+                resourceId);
           }
           break;
         } catch (IOException footerException) {
-          logger.atInfo().withCause(footerException).log(
-              "Failed to prefetch footer (retry #%s/%s) for '%s'",
-              retriesCount + 1, maxRetries, resourceId);
+          logger.atWarning().withCause(footerException).log(
+              "Failed to prefetch footer context:%d,retry:%s/%s,time:%d,resource:%s",
+              Thread.currentThread().getId(),
+              retriesCount + 1,
+              maxRetries,
+              stopwatch.elapsed(MILLISECONDS),
+              resourceId);
           if (retriesCount == 0) {
             readBackOff.get().reset();
           }