Merge pull request #534 from IABTechLab/wzh-UID2-6049-add-startup-timer-s3-new

add s3 related metrics

Author: lizk886

src/main/java/com/uid2/shared/store/salt/RotatingSaltProvider.java

@@ -129,7 +129,11 @@ private SaltSnapshot loadSnapshot(JsonObject spec, String firstLevelSalt, SaltFi
 
         final String path = spec.getString("location");
         Integer size = spec.getInteger("size");
+
+        final long downloadStart = System.currentTimeMillis();
         SaltEntry[] entries = readInputStream(this.contentStreamProvider.download(path), saltFileParser, size);
+        final long downloadEnd = System.currentTimeMillis();
+        LOGGER.info("Salt file downloaded in {} ms", downloadEnd - downloadStart);
 
         LOGGER.info("Loaded {} salts", size);
         return new SaltSnapshot(effective, expires, entries, firstLevelSalt);

src/main/java/com/uid2/shared/vertx/CloudSyncVerticle.java

@@ -7,6 +7,7 @@
 import com.uid2.shared.health.HealthManager;
 import io.micrometer.core.instrument.Counter;
 import io.micrometer.core.instrument.Gauge;
+import io.micrometer.core.instrument.Timer;
 import io.micrometer.core.instrument.Metrics;
 import io.vertx.core.*;
 import io.vertx.core.eventbus.Message;
@@ -44,6 +45,8 @@ public class CloudSyncVerticle extends AbstractVerticle {
     private final Counter counterDownloadFailures;
     private final Counter counterUploadFailures;
     private final Gauge gaugeConsecutiveRefreshFailures;
+    private final Timer downloadSuccessTimer;
+    private final Timer downloadFailureTimer;
 
     private final String name;
     private final ICloudStorage cloudStorage;
@@ -148,6 +151,10 @@ public CloudSyncVerticle(String name, ICloudStorage cloudStorage, ICloudStorage
             .tag("store", name)
             .description("gauge for number of consecutive " + name + " store refresh failures")
             .register(Metrics.globalRegistry);
+
+        this.downloadSuccessTimer = Metrics.timer("uid2_cloud_download_duration", "store_name", name, "status", "success");
+        
+        this.downloadFailureTimer = Metrics.timer("uid2_cloud_download_duration", "store_name", name, "status", "failure");
     }
 
     @Override
@@ -379,13 +386,24 @@ private Future<Void> cloudDownloadFile(String s3Path) {
     }
 
     private void cloudDownloadBlocking(Promise<Void> promise, String s3Path) {
+        final long cloudDownloadStart = System.nanoTime();
         try {
             String localPath = this.cloudSync.toLocalPath(s3Path);
             try (InputStream cloudInput = this.cloudStorage.download(s3Path)) {
+                final long cloudDownloadEnd = System.nanoTime();
+                final long cloudDownloadTimeMs = (cloudDownloadEnd - cloudDownloadStart) / 1_000_000;
+                
                 this.localStorage.upload(cloudInput, localPath);
+                
+                downloadSuccessTimer.record(java.time.Duration.ofMillis(cloudDownloadTimeMs));
+                LOGGER.info("S3 download completed: {} in {} ms", cloudStorage.mask(s3Path), cloudDownloadTimeMs);
             }
             promise.complete();
         } catch (Exception ex) {
+            final long cloudDownloadEnd = System.nanoTime();
+            final long cloudDownloadTimeMs = (cloudDownloadEnd - cloudDownloadStart) / 1_000_000;
+            
+            downloadFailureTimer.record(java.time.Duration.ofMillis(cloudDownloadTimeMs));            
             // Be careful as the s3Path may contain the pre-signed S3 token, so do not log the whole path
             LOGGER.error("download error: " + ex.getClass().getSimpleName());
             promise.fail(new Throwable(ex));

src/main/java/com/uid2/shared/vertx/RotatingStoreVerticle.java

@@ -6,6 +6,7 @@
 import io.micrometer.core.instrument.Counter;
 import io.micrometer.core.instrument.Gauge;
 import io.micrometer.core.instrument.Metrics;
+import io.micrometer.core.instrument.Timer;
 import io.vertx.core.AbstractVerticle;
 import io.vertx.core.Promise;
 import io.vertx.core.json.JsonObject;
@@ -19,6 +20,7 @@ public class RotatingStoreVerticle extends AbstractVerticle {
     private static final Logger LOGGER = LoggerFactory.getLogger(RotatingStoreVerticle.class);
     private final String storeName;
     private final HealthComponent healthComponent;
+    private final Timer storeRefreshTimer;
     private final Counter counterStoreRefreshTimeMs;
     private final Counter counterStoreRefreshed;
     private final Gauge gaugeStoreVersion;
@@ -69,6 +71,7 @@ public RotatingStoreVerticle(String storeName, long refreshIntervalMs, IMetadata
             .register(Metrics.globalRegistry);
         this.versionedStore = versionedStore;
         this.refreshIntervalMs = refreshIntervalMs;
+        this.storeRefreshTimer = Metrics.timer("uid2_store_refresh_duration", "store_name", storeName);
     }
 
     @Override
@@ -79,6 +82,7 @@ public void start(Promise<Void> startPromise) throws Exception {
 
     private void startRefresh(Promise<Void> promise) {
         LOGGER.info("Starting " + this.storeName + " loading");
+        final long startupRefreshStart = System.nanoTime();
         vertx.executeBlocking(p -> {
             try {
                 this.refresh();
@@ -87,9 +91,13 @@ private void startRefresh(Promise<Void> promise) {
                 p.fail(e);
             }
         }, ar -> {
+            final long startupRefreshEnd = System.nanoTime();
+            final long startupRefreshTimeMs = (startupRefreshEnd - startupRefreshStart) / 1000000;
+
             if (ar.succeeded()) {
                 this.healthComponent.setHealthStatus(true);
                 promise.complete();
+                storeRefreshTimer.record(java.time.Duration.ofMillis(startupRefreshTimeMs));
                 LOGGER.info("Successful " + this.storeName + " loading. Starting Background Refresh");
                 this.startBackgroundRefresh();
             } else {
@@ -140,4 +148,4 @@ public synchronized void refresh() throws Exception {
             LOGGER.info("Successfully loaded " + this.storeName + " version " + version);
         }
     }
-}
+}