diff --git a/src/main/java/com/uid2/shared/store/salt/RotatingSaltProvider.java b/src/main/java/com/uid2/shared/store/salt/RotatingSaltProvider.java index 79ed3815..ccaed217 100644 --- a/src/main/java/com/uid2/shared/store/salt/RotatingSaltProvider.java +++ b/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); diff --git a/src/main/java/com/uid2/shared/vertx/CloudSyncVerticle.java b/src/main/java/com/uid2/shared/vertx/CloudSyncVerticle.java index 98b3d2df..25815d00 100644 --- a/src/main/java/com/uid2/shared/vertx/CloudSyncVerticle.java +++ b/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 cloudDownloadFile(String s3Path) { } private void cloudDownloadBlocking(Promise 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)); diff --git a/src/main/java/com/uid2/shared/vertx/RotatingStoreVerticle.java b/src/main/java/com/uid2/shared/vertx/RotatingStoreVerticle.java index db99ab2f..23ce22f6 100644 --- a/src/main/java/com/uid2/shared/vertx/RotatingStoreVerticle.java +++ b/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 startPromise) throws Exception { private void startRefresh(Promise 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 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); } } -} +} \ No newline at end of file