Skip to content

[b/343209773] Improve ETA logging. #994

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
lszydelko-google merged 4 commits into from
Oct 9, 2025
Merged

[b/343209773] Improve ETA logging. #994

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
cb63df8
[b/343209773] Improve ETA calculation - better handling of longer tasks
lszydelko-google Oct 9, 2025
3af83d1
clean test
lszydelko-google Oct 9, 2025
d276f4f
formatting
lszydelko-google Oct 9, 2025
52b7139
reshape solution - extract TaskLoggingUtil
lszydelko-google Oct 9, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 2 additions & 2 deletions ...pp/src/main/java/com/google/edwmigration/dumper/application/dumper/DurationFormatter.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -25,8 +25,8 @@ public static String formatApproximateDuration(Duration duration) {
long minutes = duration.toMinutes() % 60;
long hours = duration.toHours();

if (hours == 0 && minutes == 0) {
return "less than one minute";
if (hours == 0 && minutes < 15) {
return "less than 15 minutes";
}

ImmutableList.Builder<String> tokens = ImmutableList.builder();
Expand Down
89 changes: 89 additions & 0 deletions .../app/src/main/java/com/google/edwmigration/dumper/application/dumper/TaskLoggingUtil.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,89 @@
/*
* Copyright 2022-2025 Google LLC
* Copyright 2013-2021 CompilerWorks
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
package com.google.edwmigration.dumper.application.dumper;

import static com.google.edwmigration.dumper.application.dumper.DurationFormatter.formatApproximateDuration;
import static java.lang.Math.max;

import com.google.common.base.Stopwatch;
import java.time.Duration;
import java.util.ArrayDeque;
import java.util.Arrays;
import java.util.Collections;
import java.util.Deque;
import java.util.concurrent.atomic.AtomicInteger;

class TaskLoggingUtil {
private final int TASK_QUEUE_SIZE = 10;
AtomicInteger numberOfCompletedTasks;
final int totalNumberOfTasks;
final Stopwatch stopwatch;
final Deque<Duration> lastTaskDurations = new ArrayDeque<>(TASK_QUEUE_SIZE);

public TaskLoggingUtil(int totalNumberOfTasks) {
this.totalNumberOfTasks = totalNumberOfTasks;
stopwatch = Stopwatch.createStarted();
numberOfCompletedTasks = new AtomicInteger();
}

private Duration getAverageTaskDurationFromAllTasks() {
return stopwatch.elapsed().dividedBy(max(1, numberOfCompletedTasks.get()));
}

private Duration getAverageTaskDurationFromLatestTasks() {
if (lastTaskDurations.isEmpty()) {
return Duration.ZERO;
}
Duration total = lastTaskDurations.getLast().minus(lastTaskDurations.getFirst());

return total.dividedBy(lastTaskDurations.size());
}

private Duration getTaskDuration() {
return Collections.max(
Arrays.asList(
getAverageTaskDurationFromAllTasks(), getAverageTaskDurationFromLatestTasks()));
}

public void recordTaskCompletion() {
numberOfCompletedTasks.getAndIncrement();

Duration taskDuration = stopwatch.elapsed();
if (lastTaskDurations.size() == TASK_QUEUE_SIZE) {
lastTaskDurations.removeFirst();
}
lastTaskDurations.addLast(taskDuration);
}

public String getProgressLog() {
int completedTasks = numberOfCompletedTasks.get();

Duration averageTimePerTask = getTaskDuration();

int percentFinished = completedTasks * 100 / totalNumberOfTasks;
String progressMessage = percentFinished + "% Completed";

int remainingTasks = totalNumberOfTasks - completedTasks;
Duration remainingTime = averageTimePerTask.multipliedBy(remainingTasks);

if (completedTasks > TASK_QUEUE_SIZE && remainingTasks > 0) {
progressMessage += ". ETA: " + formatApproximateDuration(remainingTime);
}

return progressMessage;
}
}
34 changes: 5 additions & 29 deletions dumper/app/src/main/java/com/google/edwmigration/dumper/application/dumper/TasksRunner.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,11 +16,7 @@
*/
package com.google.edwmigration.dumper.application.dumper;

import static com.google.edwmigration.dumper.application.dumper.DurationFormatter.formatApproximateDuration;
import static java.lang.Math.max;

import com.google.common.base.Preconditions;
import com.google.common.base.Stopwatch;
import com.google.edwmigration.dumper.application.dumper.handle.Handle;
import com.google.edwmigration.dumper.application.dumper.io.OutputHandle;
import com.google.edwmigration.dumper.application.dumper.io.OutputHandle.WriteMode;
Expand All @@ -34,10 +30,8 @@
import java.io.IOException;
import java.nio.charset.StandardCharsets;
import java.sql.SQLException;
import java.time.Duration;
import java.util.Arrays;
import java.util.List;
import java.util.concurrent.atomic.AtomicInteger;
import javax.annotation.CheckForNull;
import javax.annotation.Nonnull;
import org.slf4j.Logger;
Expand All @@ -49,14 +43,12 @@ public class TasksRunner implements TaskRunContextOps {
private static final Logger logger = LoggerFactory.getLogger(TasksRunner.class);
public static final Logger PROGRESS_LOG = LoggerFactory.getLogger("progress-logger");

private AtomicInteger numberOfCompletedTasks;
private final int totalNumberOfTasks;
private final Stopwatch stopwatch;

private final TaskRunContext context;
private final TaskSetState.Impl state;
private final List<Task<?>> tasks;

private final TaskLoggingUtil taskLoggingUtil;

public TasksRunner(
OutputHandleFactory sinkFactory,
Handle handle,
Expand All @@ -67,9 +59,7 @@ public TasksRunner(
context = createContext(sinkFactory, handle, threadPoolSize, arguments);
this.state = state;
this.tasks = tasks;
totalNumberOfTasks = countTasks(tasks);
stopwatch = Stopwatch.createStarted();
numberOfCompletedTasks = new AtomicInteger();
this.taskLoggingUtil = new TaskLoggingUtil(countTasks(tasks));
}

private TaskRunContext createContext(
Expand Down Expand Up @@ -101,28 +91,14 @@ public void run() throws MetadataDumperUsageException {
private <T> T handleTask(Task<T> task) throws MetadataDumperUsageException {
T t = runTask(task);
if (!(task instanceof TaskGroup)) {
numberOfCompletedTasks.getAndIncrement();
taskLoggingUtil.recordTaskCompletion();
}
logProgress();
return t;
}

private void logProgress() {
int numberOfCompletedTasks = this.numberOfCompletedTasks.get();

Duration averageTimePerTask = stopwatch.elapsed().dividedBy(max(1, numberOfCompletedTasks));

int percentFinished = numberOfCompletedTasks * 100 / totalNumberOfTasks;
String progressMessage = percentFinished + "% Completed";

int remainingTasks = totalNumberOfTasks - numberOfCompletedTasks;
Duration remainingTime = averageTimePerTask.multipliedBy(remainingTasks);

if (numberOfCompletedTasks > 10 && remainingTasks > 0) {
progressMessage += ". ETA: " + formatApproximateDuration(remainingTime);
}

PROGRESS_LOG.info(progressMessage);
PROGRESS_LOG.info(taskLoggingUtil.getProgressLog());
}

private static final String ACCESS_CONTROL_EXCEPTION_MSG_SUFFIX =
Expand Down
18 changes: 7 additions & 11 deletions ...rc/test/java/com/google/edwmigration/dumper/application/dumper/DurationFormatterTest.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -33,17 +33,13 @@ public class DurationFormatterTest {
@DataPoints("durations")
public static final ImmutableList<Pair<Duration, String>> DURATIONS =
ImmutableList.of(
Pair.of(Duration.ZERO, "less than one minute"),
Pair.of(Duration.ofMillis(1), "less than one minute"),
Pair.of(Duration.ofSeconds(1), "less than one minute"),
Pair.of(Duration.ofSeconds(59), "less than one minute"),
Pair.of(Duration.ofMinutes(1), "~1 minute"),
Pair.of(Duration.ofMinutes(1).plusSeconds(1), "~1 minute"),
Pair.of(Duration.ofMinutes(1).plusSeconds(59), "~1 minute"),
Pair.of(Duration.ofMinutes(2), "~2 minutes"),
Pair.of(Duration.ofMinutes(2).plusSeconds(1), "~2 minutes"),
Pair.of(Duration.ofMinutes(2).plusSeconds(59), "~2 minutes"),
Pair.of(Duration.ofMinutes(11), "~11 minutes"),
Pair.of(Duration.ZERO, "less than 15 minutes"),
Pair.of(Duration.ofMillis(1), "less than 15 minutes"),
Pair.of(Duration.ofSeconds(1), "less than 15 minutes"),
Pair.of(Duration.ofMinutes(2), "less than 15 minutes"),
Pair.of(Duration.ofMinutes(2).plusSeconds(1), "less than 15 minutes"),
Pair.of(Duration.ofMinutes(14).plusSeconds(59), "less than 15 minutes"),
Pair.of(Duration.ofMinutes(15), "~15 minutes"),
Pair.of(Duration.ofMinutes(21), "~21 minutes"),
Pair.of(Duration.ofMinutes(34), "~34 minutes"),
Pair.of(Duration.ofMinutes(59).plusSeconds(59).plusMillis(999), "~59 minutes"),
Expand Down
140 changes: 140 additions & 0 deletions .../src/test/java/com/google/edwmigration/dumper/application/dumper/TaskLoggingUtilTest.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,140 @@
/*
* Copyright 2022-2025 Google LLC
* Copyright 2013-2021 CompilerWorks
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
package com.google.edwmigration.dumper.application.dumper;

import static org.junit.Assert.assertEquals;
import static org.mockito.Mockito.*;

import com.google.common.base.Stopwatch;
import java.time.Duration;
import org.junit.Before;
import org.junit.Test;
import org.mockito.Mockito;

public class TaskLoggingUtilTest {

private TaskLoggingUtil util;

@Before
public void setUp() {
util = new TaskLoggingUtil(5);
}

@Test
public void testRecordTaskCompletion_IncrementsCompletedTasksAndStoresDurations() {
int initialCompleted = util.numberOfCompletedTasks.get();
util.recordTaskCompletion();
assertEquals(initialCompleted + 1, util.numberOfCompletedTasks.get());
// After first completion, lastTaskDurations should have 1 element
assertEquals(1, util.lastTaskDurations.size());
util.recordTaskCompletion();
assertEquals(2, util.lastTaskDurations.size());
}

@Test
public void testRecordTaskCompletion_QueueDoesNotExceedMaxSize() {
for (int i = 0; i < 15; i++) {
util.recordTaskCompletion();
}
// Should not exceed TASK_QUEUE_SIZE (10)
assertEquals(10, util.lastTaskDurations.size());
}

@Test
public void testGetProgressLog_ETA_NotShownWhenCompletedTasksNotEnough() {
// Complete less than or equal to TASK_QUEUE_SIZE tasks
for (int i = 0; i < 10; i++) {
util.recordTaskCompletion();
}
Stopwatch spyStopwatch = Mockito.spy(Stopwatch.createUnstarted());
spyStopwatch.start();
spyStopwatch.reset();
when(spyStopwatch.elapsed()).thenReturn(Duration.ofMinutes(16));
try {
java.lang.reflect.Field field = TaskLoggingUtil.class.getDeclaredField("stopwatch");
field.setAccessible(true);
field.set(util, spyStopwatch);
} catch (Exception e) {
throw new RuntimeException(e);
}
String log = util.getProgressLog();
// ETA should not be shown since completedTasks <= TASK_QUEUE_SIZE
assertEquals(false, log.contains("ETA"));
}

@Test
public void testGetProgressLog_RemainingDurationFromAllTasksWhenLatestTasksEmpty() {
// Only one task completed, so lastTaskDurations has one element
util.recordTaskCompletion();
Stopwatch spyStopwatch = Mockito.spy(Stopwatch.createUnstarted());
spyStopwatch.start();
spyStopwatch.reset();
when(spyStopwatch.elapsed()).thenReturn(Duration.ofMinutes(15));
try {
java.lang.reflect.Field field = TaskLoggingUtil.class.getDeclaredField("stopwatch");
field.setAccessible(true);
field.set(util, spyStopwatch);
} catch (Exception e) {
throw new RuntimeException(e);
}
String log = util.getProgressLog();
// Should not show ETA, and should use all-tasks average
assertEquals(false, log.contains("ETA"));
assertEquals(true, log.contains("% Completed"));
}

@Test
public void testRecordTaskCompletion_HandlesMultipleWraps() {
// Fill up the queue, then add more to ensure oldest are removed
for (int i = 0; i < 25; i++) {
util.recordTaskCompletion();
}
assertEquals(10, util.lastTaskDurations.size());
}

@Test
public void testGetProgressLog_ZeroTasks() {
// No tasks completed
String log = util.getProgressLog();
assertEquals(true, log.contains("0% Completed"));
assertEquals(false, log.contains("ETA"));
}

@Test
public void testGetProgressLog_UsesAllTasksAverage() {
// Simulate only 1 completion, so latestTasks is empty or not enough
util.recordTaskCompletion();
String log = util.getProgressLog();
// Should not contain ETA since completedTasks <= TASK_QUEUE_SIZE
assertEquals(false, log.contains("ETA"));
// Should show percent completed
assertEquals(true, log.contains("% Completed"));
}

@Test
public void testGetProgressLog_LessThanTaskQueueSize() {
// Complete less than TASK_QUEUE_SIZE tasks
for (int i = 0; i < 5; i++) {
util.recordTaskCompletion();
}
String log = util.getProgressLog();
// Should not contain ETA
assertEquals(false, log.contains("ETA"));
// Should show percent completed
assertEquals(true, log.contains("% Completed"));
}
}
Loading