From 4314423e5d95564092e9d4ab9a99957ab790a3ca Mon Sep 17 00:00:00 2001 From: Mohammed Daudali Date: Thu, 31 Oct 2024 00:06:32 +0800 Subject: [PATCH] [ASTS] Telemetry part 2: Add placeholders to logs (#7381) --- .../sweep/asts/DynamicTaskScheduler.java | 11 +++++---- .../DefaultSweepAssignedBucketStore.java | 17 ++++++++------ .../progress/DefaultBucketProgressStore.java | 23 ++++++++++--------- 3 files changed, 29 insertions(+), 22 deletions(-) diff --git a/atlasdb-impl-shared/src/main/java/com/palantir/atlasdb/sweep/asts/DynamicTaskScheduler.java b/atlasdb-impl-shared/src/main/java/com/palantir/atlasdb/sweep/asts/DynamicTaskScheduler.java index 665a8e7eca..7f2fa2c5fd 100644 --- a/atlasdb-impl-shared/src/main/java/com/palantir/atlasdb/sweep/asts/DynamicTaskScheduler.java +++ b/atlasdb-impl-shared/src/main/java/com/palantir/atlasdb/sweep/asts/DynamicTaskScheduler.java @@ -81,18 +81,18 @@ public void start() { if (isStarted.compareAndSet(false, true)) { scheduleNextIteration(automaticSweepRefreshDelay.get()); } else { - log.warn("Attempted to start an already started task", SafeArg.of("task", safeLoggableTaskName)); + log.warn("Attempted to start an already started task: {}", SafeArg.of("task", safeLoggableTaskName)); } } private void runOneIteration() { Duration delay = automaticSweepRefreshDelay.get(); try { - log.info("Running task", SafeArg.of("task", safeLoggableTaskName)); + log.info("Running task: {}", SafeArg.of("task", safeLoggableTaskName)); task.run(); } catch (Exception e) { log.warn( - "Failed to run task. Will retry in the next interval", + "Failed to run task {}. Will retry after delay {}", SafeArg.of("task", safeLoggableTaskName), SafeArg.of("delay", delay), e); @@ -101,7 +101,10 @@ private void runOneIteration() { } private void scheduleNextIteration(Duration delay) { - log.info("Scheduling next iteration", SafeArg.of("task", safeLoggableTaskName), SafeArg.of("delay", delay)); + log.info( + "Scheduling next iteration for {} with delay {}", + SafeArg.of("task", safeLoggableTaskName), + SafeArg.of("delay", delay)); scheduledExecutorService.schedule(this::runOneIteration, delay.toMillis(), TimeUnit.MILLISECONDS); } } diff --git a/atlasdb-impl-shared/src/main/java/com/palantir/atlasdb/sweep/asts/bucketingthings/DefaultSweepAssignedBucketStore.java b/atlasdb-impl-shared/src/main/java/com/palantir/atlasdb/sweep/asts/bucketingthings/DefaultSweepAssignedBucketStore.java index 42805bba2b..3b494b5045 100644 --- a/atlasdb-impl-shared/src/main/java/com/palantir/atlasdb/sweep/asts/bucketingthings/DefaultSweepAssignedBucketStore.java +++ b/atlasdb-impl-shared/src/main/java/com/palantir/atlasdb/sweep/asts/bucketingthings/DefaultSweepAssignedBucketStore.java @@ -150,7 +150,8 @@ public void updateStartingBucketForShardAndStrategy(Bucket newStartingBucket) { if (currentStartingBucket.isEmpty()) { keyValueService.checkAndSet(CheckAndSetRequest.newCell(TABLE_REF, cell, serializedBucketProgress)); if (log.isDebugEnabled()) { - log.debug("Persisted new starting bucket", SafeArg.of("newStartingBucket", newStartingBucket)); + log.debug( + "Persisted new starting bucket {}", SafeArg.of("newStartingBucket", newStartingBucket)); } } else { if (newStartingBucket.bucketIdentifier() > currentStartingBucket.get()) { @@ -161,14 +162,15 @@ public void updateStartingBucketForShardAndStrategy(Bucket newStartingBucket) { bucketIdentifierPersister.trySerialize(newStartingBucket.bucketIdentifier()))); if (log.isDebugEnabled()) { log.debug( - "Updated sweep bucket progress", + "Updated sweep bucket progress from {} to {}", SafeArg.of("previousStartingBucket", currentStartingBucket), SafeArg.of("newStartingBucket", newStartingBucket)); } } else { log.info( - "Attempted to update starting bucket, but the existing starting bucket in the database" - + " was already ahead of us (possible timelock lost lock?)", + "Attempted to update starting bucket from {} to {}, but the existing starting" + + " bucket in the database was already ahead of us" + + " (possible timelock lost lock?)", SafeArg.of("previousStartingBucket", currentStartingBucket), SafeArg.of("newStartingBucket", newStartingBucket)); } @@ -177,15 +179,16 @@ public void updateStartingBucketForShardAndStrategy(Bucket newStartingBucket) { } catch (RuntimeException e) { if (attempt == CAS_ATTEMPT_LIMIT) { log.warn( - "Repeatedly failed to update starting bucket as part of sweep; throwing, some work may" - + " need to be re-done.", + "Repeatedly failed to update starting bucket to {} as part of sweep; throwing" + + " after {} attempts, some work may need to be re-done", SafeArg.of("attemptedNewStartingBucket", newStartingBucket), SafeArg.of("numAttempts", CAS_ATTEMPT_LIMIT), e); throw e; } else { log.info( - "Failed to read or update starting bucket as part of sweep. Retrying", + "Failed to read or update starting bucket to {} as part of sweep after attempt {}." + + " Retrying", SafeArg.of("newStartingBucket", newStartingBucket), SafeArg.of("attemptNumber", attempt), e); diff --git a/atlasdb-impl-shared/src/main/java/com/palantir/atlasdb/sweep/asts/progress/DefaultBucketProgressStore.java b/atlasdb-impl-shared/src/main/java/com/palantir/atlasdb/sweep/asts/progress/DefaultBucketProgressStore.java index 377686c886..6d1f406f7a 100644 --- a/atlasdb-impl-shared/src/main/java/com/palantir/atlasdb/sweep/asts/progress/DefaultBucketProgressStore.java +++ b/atlasdb-impl-shared/src/main/java/com/palantir/atlasdb/sweep/asts/progress/DefaultBucketProgressStore.java @@ -72,7 +72,7 @@ public void updateBucketProgressToAtLeast(Bucket bucket, BucketProgress minimum) CheckAndSetRequest.newCell(TABLE_REF, bucketCell, serializedBucketProgress)); if (log.isDebugEnabled()) { log.debug( - "Persisted new sweep bucket progress", + "Persisted new sweep bucket {} progress to {}", SafeArg.of("bucket", bucket), SafeArg.of("minimumProgress", minimum)); } @@ -88,26 +88,26 @@ public void updateBucketProgressToAtLeast(Bucket bucket, BucketProgress minimum) bucketProgressPersister.serializeProgress(minimum))); if (log.isDebugEnabled()) { log.debug( - "Updated sweep bucket progress", + "Updated sweep bucket {} progress from {} to {}", SafeArg.of("bucket", bucket), - SafeArg.of("minimumProgress", minimum), - SafeArg.of("previousPersistedProgress", extantCurrentProgress)); + SafeArg.of("previousPersistedProgress", extantCurrentProgress), + SafeArg.of("minimumProgress", minimum)); } } else { log.info( - "Attempted to update sweep bucket progress, but the existing progress in the database" - + " was already ahead of us (possible timelock lost lock?)", + "Attempted to update sweep bucket {} progress, but the existing progress {}" + + " in the database was already ahead of us {} (possible timelock lost lock?)", SafeArg.of("bucket", bucket), - SafeArg.of("minimumProgress", minimum), - SafeArg.of("persistedProgress", extantCurrentProgress)); + SafeArg.of("persistedProgress", extantCurrentProgress), + SafeArg.of("minimumProgress", minimum)); } } return; } catch (RuntimeException e) { if (attempt == CAS_ATTEMPT_LIMIT - 1) { log.warn( - "Repeatedly failed to update bucket progress as part of sweep; throwing, some work may" - + " need to be re-done.", + "Repeatedly failed to update bucket {} progress to {} as part of sweep; throwing" + + " after {} attempts, some work may need to be re-done", SafeArg.of("bucket", bucket), SafeArg.of("minimumProgress", minimum), SafeArg.of("numAttempts", CAS_ATTEMPT_LIMIT), @@ -115,7 +115,8 @@ public void updateBucketProgressToAtLeast(Bucket bucket, BucketProgress minimum) throw e; } else { log.info( - "Failed to read or update bucket progress as part of sweep. Retrying", + "Failed to read or update bucket {} progress {} as part of sweep after attempt {}." + + " Retrying", SafeArg.of("bucket", bucket), SafeArg.of("minimumProgress", minimum), SafeArg.of("attemptNumber", attempt + 1),