Skip to content

Commit 8f1b4ab

Browse files
authored
Log ETA and the completion percentage (#296)
1 parent 412897c commit 8f1b4ab

File tree

3 files changed

+181
-86
lines changed

3 files changed

+181
-86
lines changed

dumper/app/src/main/java/com/google/edwmigration/dumper/application/dumper/MetadataDumper.java

Lines changed: 1 addition & 84 deletions
Original file line numberDiff line numberDiff line change
@@ -19,7 +19,6 @@
1919
import static org.apache.commons.lang3.StringUtils.repeat;
2020

2121
import com.google.cloud.storage.contrib.nio.CloudStorageFileSystem;
22-
import com.google.common.base.Preconditions;
2322
import com.google.common.base.Stopwatch;
2423
import com.google.common.collect.ImmutableMap;
2524
import com.google.common.io.Closer;
@@ -29,28 +28,24 @@
2928
import com.google.edwmigration.dumper.application.dumper.connector.MetadataConnector;
3029
import com.google.edwmigration.dumper.application.dumper.handle.Handle;
3130
import com.google.edwmigration.dumper.application.dumper.io.FileSystemOutputHandleFactory;
32-
import com.google.edwmigration.dumper.application.dumper.io.OutputHandle;
3331
import com.google.edwmigration.dumper.application.dumper.io.OutputHandleFactory;
3432
import com.google.edwmigration.dumper.application.dumper.task.ArgumentsTask;
3533
import com.google.edwmigration.dumper.application.dumper.task.JdbcRunSQLScript;
3634
import com.google.edwmigration.dumper.application.dumper.task.Task;
3735
import com.google.edwmigration.dumper.application.dumper.task.TaskCategory;
3836
import com.google.edwmigration.dumper.application.dumper.task.TaskGroup;
3937
import com.google.edwmigration.dumper.application.dumper.task.TaskResult;
40-
import com.google.edwmigration.dumper.application.dumper.task.TaskRunContext;
4138
import com.google.edwmigration.dumper.application.dumper.task.TaskSetState;
4239
import com.google.edwmigration.dumper.application.dumper.task.TaskSetState.Impl;
4340
import com.google.edwmigration.dumper.application.dumper.task.TaskState;
4441
import com.google.edwmigration.dumper.application.dumper.task.VersionTask;
4542
import java.io.File;
4643
import java.io.IOException;
4744
import java.net.URI;
48-
import java.nio.charset.StandardCharsets;
4945
import java.nio.file.FileSystem;
5046
import java.nio.file.FileSystems;
5147
import java.nio.file.Path;
5248
import java.nio.file.Paths;
53-
import java.sql.SQLException;
5449
import java.util.ArrayList;
5550
import java.util.Arrays;
5651
import java.util.List;
@@ -60,18 +55,15 @@
6055
import java.util.regex.Matcher;
6156
import java.util.regex.Pattern;
6257
import java.util.stream.Collectors;
63-
import javax.annotation.CheckForNull;
6458
import javax.annotation.Nonnull;
6559
import org.apache.commons.lang3.StringUtils;
66-
import org.checkerframework.checker.nullness.qual.EnsuresNonNullIf;
6760
import org.slf4j.Logger;
6861
import org.slf4j.LoggerFactory;
6962

7063
/** @author miguel */
7164
public class MetadataDumper {
7265

7366
private static final Logger LOG = LoggerFactory.getLogger(MetadataDumper.class);
74-
private static final Logger PROGRESS_LOG = LoggerFactory.getLogger("progress-logger");
7567

7668
private static final ImmutableMap<String, Connector> CONNECTORS;
7769

@@ -126,64 +118,6 @@ public void run(@Nonnull ConnectorArguments arguments) throws Exception {
126118
run(connector, arguments);
127119
}
128120

129-
@CheckForNull
130-
private <T> T runTask(
131-
@Nonnull TaskRunContext context, @Nonnull TaskSetState.Impl state, Task<T> task)
132-
throws MetadataDumperUsageException {
133-
try {
134-
CHECK:
135-
{
136-
TaskState ts = state.getTaskState(task);
137-
Preconditions.checkState(
138-
ts == TaskState.NOT_STARTED, "TaskState was bad: " + ts + " for " + task);
139-
}
140-
141-
PRECONDITION:
142-
for (Task.Condition condition : task.getConditions()) {
143-
if (!condition.evaluate(state)) {
144-
LOG.debug("Skipped " + task.getName() + " because " + condition.toSkipReason());
145-
state.setTaskResult(task, TaskState.SKIPPED, null);
146-
return null;
147-
}
148-
}
149-
150-
RUN:
151-
{
152-
T value = task.run(context);
153-
state.setTaskResult(task, TaskState.SUCCEEDED, value);
154-
return value;
155-
}
156-
} catch (Exception e) {
157-
// MetadataDumperUsageException should be fatal.
158-
if (e instanceof MetadataDumperUsageException) throw (MetadataDumperUsageException) e;
159-
if (e instanceof SQLException && e.getCause() instanceof MetadataDumperUsageException)
160-
throw (MetadataDumperUsageException) e.getCause();
161-
// TaskGroup is an attempt to get rid of this condition.
162-
// We might need an additional TaskRunner / TaskSupport with an overrideable handleException
163-
// method instead of this runTask() method.
164-
if (!task.handleException(e)) LOG.warn("Task failed: " + task + ": " + e, e);
165-
state.setTaskException(task, TaskState.FAILED, e);
166-
try {
167-
OutputHandle sink = context.newOutputFileHandle(task.getTargetPath() + ".exception.txt");
168-
sink.asCharSink(StandardCharsets.UTF_8)
169-
.writeLines(
170-
Arrays.asList(
171-
task.toString(),
172-
"******************************",
173-
String.valueOf(new DumperDiagnosticQuery(e).call())));
174-
} catch (Exception f) {
175-
LOG.warn("Exception-recorder failed: " + f, f);
176-
}
177-
}
178-
return null;
179-
}
180-
181-
@EnsuresNonNullIf(expression = "#1", result = false)
182-
private static boolean isNullOrEmpty(@CheckForNull Object[] in) {
183-
if (in == null) return true;
184-
return in.length == 0;
185-
}
186-
187121
private void print(@Nonnull Task<?> task, int indent) {
188122
System.out.println(repeat(' ', indent * 2) + task);
189123
if (task instanceof TaskGroup) {
@@ -265,24 +199,7 @@ protected void run(@Nonnull Connector connector, @Nonnull ConnectorArguments arg
265199

266200
Handle handle = closer.register(connector.open(arguments));
267201

268-
TaskRunContext runContext =
269-
new TaskRunContext(sinkFactory, handle, arguments.getThreadPoolSize()) {
270-
@Override
271-
public TaskState getTaskState(Task<?> task) {
272-
return state.getTaskState(task);
273-
}
274-
275-
@Override
276-
public <T> T runChildTask(Task<T> task) throws MetadataDumperUsageException {
277-
return runTask(this, state, task);
278-
}
279-
};
280-
TASK:
281-
for (int i = 0; i < tasks.size(); i++) {
282-
runTask(runContext, state, tasks.get(i));
283-
PROGRESS_LOG.info("Finished " + (i + 1) + " out of " + tasks.size() + " tasks");
284-
}
285-
202+
new TasksRunner(sinkFactory, handle, arguments.getThreadPoolSize(), state, tasks).run();
286203
} finally {
287204
// We must do this in finally after the ZipFileSystem has been closed.
288205
File outputFile = new File(outputFileLocation);
Lines changed: 178 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,178 @@
1+
/*
2+
* Copyright 2022-2023 Google LLC
3+
* Copyright 2013-2021 CompilerWorks
4+
*
5+
* Licensed under the Apache License, Version 2.0 (the "License");
6+
* you may not use this file except in compliance with the License.
7+
* You may obtain a copy of the License at
8+
*
9+
* http://www.apache.org/licenses/LICENSE-2.0
10+
*
11+
* Unless required by applicable law or agreed to in writing, software
12+
* distributed under the License is distributed on an "AS IS" BASIS,
13+
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14+
* See the License for the specific language governing permissions and
15+
* limitations under the License.
16+
*/
17+
package com.google.edwmigration.dumper.application.dumper;
18+
19+
import com.google.common.base.Preconditions;
20+
import com.google.common.base.Stopwatch;
21+
import com.google.edwmigration.dumper.application.dumper.handle.Handle;
22+
import com.google.edwmigration.dumper.application.dumper.io.OutputHandle;
23+
import com.google.edwmigration.dumper.application.dumper.io.OutputHandleFactory;
24+
import com.google.edwmigration.dumper.application.dumper.task.Task;
25+
import com.google.edwmigration.dumper.application.dumper.task.TaskGroup;
26+
import com.google.edwmigration.dumper.application.dumper.task.TaskRunContext;
27+
import com.google.edwmigration.dumper.application.dumper.task.TaskSetState;
28+
import com.google.edwmigration.dumper.application.dumper.task.TaskSetState.Impl;
29+
import com.google.edwmigration.dumper.application.dumper.task.TaskState;
30+
import java.nio.charset.StandardCharsets;
31+
import java.sql.SQLException;
32+
import java.util.Arrays;
33+
import java.util.List;
34+
import java.util.concurrent.TimeUnit;
35+
import java.util.concurrent.atomic.AtomicInteger;
36+
import javax.annotation.CheckForNull;
37+
import javax.annotation.Nonnull;
38+
import org.apache.commons.lang3.time.DurationFormatUtils;
39+
import org.slf4j.Logger;
40+
import org.slf4j.LoggerFactory;
41+
42+
/** @author ishmum */
43+
public class TasksRunner {
44+
45+
private static final Logger LOG = LoggerFactory.getLogger(TasksRunner.class);
46+
private static final Logger PROGRESS_LOG = LoggerFactory.getLogger("progress-logger");
47+
48+
private AtomicInteger numberOfCompletedTasks;
49+
private final int totalNumberOfTasks;
50+
private final Stopwatch stopwatch;
51+
52+
private final TaskRunContext context;
53+
private final TaskSetState.Impl state;
54+
private final List<Task<?>> tasks;
55+
56+
public TasksRunner(
57+
OutputHandleFactory sinkFactory,
58+
Handle handle,
59+
int threadPoolSize,
60+
@Nonnull TaskSetState.Impl state,
61+
List<Task<?>> tasks) {
62+
context = createContext(sinkFactory, handle, threadPoolSize, state);
63+
this.state = state;
64+
this.tasks = tasks;
65+
totalNumberOfTasks = countTasks(tasks);
66+
stopwatch = Stopwatch.createStarted();
67+
numberOfCompletedTasks = new AtomicInteger();
68+
}
69+
70+
private TaskRunContext createContext(
71+
OutputHandleFactory sinkFactory, Handle handle, int threadPoolSize, Impl state) {
72+
return new TaskRunContext(sinkFactory, handle, threadPoolSize) {
73+
@Override
74+
public TaskState getTaskState(Task<?> task) {
75+
return state.getTaskState(task);
76+
}
77+
78+
@Override
79+
public <T> T runChildTask(Task<T> task) throws MetadataDumperUsageException {
80+
return handleTask(task);
81+
}
82+
};
83+
}
84+
85+
public void run() throws MetadataDumperUsageException {
86+
for (Task<?> task : tasks) {
87+
handleTask(task);
88+
}
89+
}
90+
91+
@CheckForNull
92+
private <T> T handleTask(Task<T> task) throws MetadataDumperUsageException {
93+
T t = runTask(task);
94+
if (!(task instanceof TaskGroup)) {
95+
numberOfCompletedTasks.getAndIncrement();
96+
}
97+
logProgress();
98+
return t;
99+
}
100+
101+
private void logProgress() {
102+
int numberOfCompletedTasks = this.numberOfCompletedTasks.get();
103+
104+
long averageTimePerTaskInMillisecond =
105+
numberOfCompletedTasks == 0
106+
? 0
107+
: stopwatch.elapsed(TimeUnit.MILLISECONDS) / numberOfCompletedTasks;
108+
109+
int percentFinished = numberOfCompletedTasks * 100 / totalNumberOfTasks;
110+
String progressMessage = percentFinished + "% Completed";
111+
112+
int remainingTasks = totalNumberOfTasks - numberOfCompletedTasks;
113+
long remainingTimeInMillis = averageTimePerTaskInMillisecond * remainingTasks;
114+
115+
if (numberOfCompletedTasks > 10) {
116+
progressMessage =
117+
progressMessage
118+
+ ". ETA: "
119+
+ DurationFormatUtils.formatDurationWords(remainingTimeInMillis, true, true);
120+
}
121+
PROGRESS_LOG.info(progressMessage);
122+
}
123+
124+
private <T> T runTask(Task<T> task) throws MetadataDumperUsageException {
125+
try {
126+
CHECK:
127+
{
128+
TaskState ts = state.getTaskState(task);
129+
Preconditions.checkState(
130+
ts == TaskState.NOT_STARTED, "TaskState was bad: " + ts + " for " + task);
131+
}
132+
133+
PRECONDITION:
134+
for (Task.Condition condition : task.getConditions()) {
135+
if (!condition.evaluate(state)) {
136+
LOG.debug("Skipped " + task.getName() + " because " + condition.toSkipReason());
137+
state.setTaskResult(task, TaskState.SKIPPED, null);
138+
return null;
139+
}
140+
}
141+
142+
RUN:
143+
{
144+
T value = task.run(context);
145+
state.setTaskResult(task, TaskState.SUCCEEDED, value);
146+
return value;
147+
}
148+
} catch (Exception e) {
149+
// MetadataDumperUsageException should be fatal.
150+
if (e instanceof MetadataDumperUsageException) throw (MetadataDumperUsageException) e;
151+
if (e instanceof SQLException && e.getCause() instanceof MetadataDumperUsageException)
152+
throw (MetadataDumperUsageException) e.getCause();
153+
// TaskGroup is an attempt to get rid of this condition.
154+
// We might need an additional TaskRunner / TaskSupport with an overrideable handleException
155+
// method instead of this runTask() method.
156+
if (!task.handleException(e)) LOG.warn("Task failed: " + task + ": " + e, e);
157+
state.setTaskException(task, TaskState.FAILED, e);
158+
try {
159+
OutputHandle sink = context.newOutputFileHandle(task.getTargetPath() + ".exception.txt");
160+
sink.asCharSink(StandardCharsets.UTF_8)
161+
.writeLines(
162+
Arrays.asList(
163+
task.toString(),
164+
"******************************",
165+
String.valueOf(new DumperDiagnosticQuery(e).call())));
166+
} catch (Exception f) {
167+
LOG.warn("Exception-recorder failed: " + f, f);
168+
}
169+
}
170+
return null;
171+
}
172+
173+
private int countTasks(List<Task<?>> tasks) {
174+
return tasks.stream()
175+
.mapToInt(task -> task instanceof TaskGroup ? countTasks(((TaskGroup) task).getTasks()) : 1)
176+
.sum();
177+
}
178+
}

dumper/app/src/main/resources/logback.xml

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -21,11 +21,11 @@
2121
<appender name="FILE" class="ch.qos.logback.core.FileAppender">
2222
<file>progress.log.${currentTime}</file>
2323
<encoder>
24-
<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern>
24+
<pattern>%d{HH:mm:ss.SSS} %msg%n</pattern>
2525
</encoder>
2626
</appender>
2727

28-
<logger name="progress-logger" additivity="false">
28+
<logger name="progress-logger">
2929
<appender-ref ref="FILE" />
3030
</logger>
3131

0 commit comments

Comments
 (0)