/** Writes a detailed informational status message to the log, at INFO level */
private final void logStatusInfo() {
if (info(log)) {
try {
final int batchesInProgress =
importThreadPool.getQueueSize() + importThreadPool.getActiveCount();
final Float batchesPerSecond =
importStatus.getTargetCounterRate(
BulkImportStatus.TARGET_COUNTER_BATCHES_COMPLETE, SECONDS);
final Long estimatedCompletionTimeInNs = importStatus.getEstimatedRemainingDurationInNs();
String message = null;
if (batchesPerSecond != null && estimatedCompletionTimeInNs != null) {
message =
String.format(
"Multithreaded import in progress - %d batch%s yet to be imported. "
+ "At current rate (%.3f batch%s per second), estimated completion in %s.",
batchesInProgress,
pluralise(batchesInProgress, "es"),
batchesPerSecond,
pluralise(batchesPerSecond, "es"),
getHumanReadableDuration(estimatedCompletionTimeInNs, false));
} else {
message =
String.format(
"Multithreaded import in progress - %d batch%s yet to be imported.",
batchesInProgress, pluralise(batchesInProgress, "es"));
}
info(log, message);
} catch (final IllegalFormatException ife) {
// To help troubleshoot bugs in the String.format calls above
error(log, ife);
}
}
}
/**
* Awaits completion of the import, by checking if the import thread pool and associated queue are
* empty, with sleeps in between polls.
*
* @throws InterruptedException If a sleep is interrupted.
*/
private final void awaitCompletion() throws InterruptedException {
if (multiThreadedImport) {
// Log status then wait for everything to wrap up...
if (debug(log))
debug(log, "Scanning complete. Waiting for completion of multithreaded import.");
logStatusInfo();
}
importThreadPool.shutdown(); // Orderly shutdown (lets the queue drain)
// Log status every hour, then go back to waiting - in single threaded case this won't wait at
// all
while (!importThreadPool.awaitTermination(1, TimeUnit.HOURS)) {
logStatusInfo();
}
}
/**
* Used to submit a batch to the import thread pool. Note that this method can block (due to the
* use of a blocking queue in the thread pool).
*
* @param batch The batch to submit <i>(may be null or empty, although that will result in a
* no-op)</i>.
*/
private void submitBatch(final Batch batch) {
if (batch != null && batch.size() > 0) {
if (importStatus.inProgress() && !importStatus.isStopping()) {
importThreadPool.execute(new BatchImportJob(batch));
} else {
if (warn(log)) warn(log, "New batch submitted during shutdown - ignoring new work.");
}
}
}
/** @see java.lang.Runnable#run() */
@Override
public void run() {
boolean inPlacePossible = false;
try {
source.init(importStatus, parameters);
inPlacePossible = source.inPlaceImportPossible();
if (info(log))
info(
log,
"Import ("
+ (inPlacePossible ? "in-place" : "streaming")
+ ") started from "
+ source.getName()
+ ".");
importStatus.importStarted(
userId, source, targetAsPath, importThreadPool, batchWeight, inPlacePossible, dryRun);
// ------------------------------------------------------------------
// Phase 1 - Folder scanning (single threaded)
// ------------------------------------------------------------------
source.scanFolders(importStatus, this);
if (debug(log))
debug(
log,
"Folder import complete in "
+ getHumanReadableDuration(importStatus.getDurationInNs())
+ ".");
// ------------------------------------------------------------------
// Phase 2 - File scanning
// ------------------------------------------------------------------
filePhase = true;
// Maximise level of concurrency, since there's no longer any risk of out-of-order batches
source.scanFiles(importStatus, this);
if (debug(log))
debug(
log,
"File scan complete in "
+ getHumanReadableDuration(importStatus.getDurationInNs())
+ ".");
importStatus.scanningComplete();
// ------------------------------------------------------------------
// Phase 3 - Wait for multi-threaded import to complete and shutdown
// ------------------------------------------------------------------
submitCurrentBatch(); // Submit whatever is left in the final (partial) batch...
awaitCompletion();
if (debug(log))
debug(log, "Import complete" + (multiThreadedImport ? ", thread pool shutdown" : "") + ".");
} catch (final Throwable t) {
Throwable rootCause = getRootCause(t);
String rootCauseClassName = rootCause.getClass().getName();
if (importStatus.isStopping()
&& (rootCause instanceof InterruptedException
|| rootCause instanceof ClosedByInterruptException
|| "com.hazelcast.core.RuntimeInterruptedException"
.equals(rootCauseClassName))) // For compatibility across 4.x *sigh*
{
// A stop import was requested
if (debug(log))
debug(log, Thread.currentThread().getName() + " was interrupted by a stop request.", t);
} else {
// An unexpected exception occurred during scanning - log it and kill the import
error(log, "Bulk import from '" + source.getName() + "' failed.", t);
importStatus.unexpectedError(t);
}
if (debug(log))
debug(log, "Forcibly shutting down import thread pool and awaiting shutdown...");
importThreadPool.shutdownNow();
try {
importThreadPool.awaitTermination(
Long.MAX_VALUE,
TimeUnit.DAYS); // Wait forever (technically merely a very long time, but whatevs...)
} catch (final InterruptedException ie) {
// Not much we can do here but log it and keep on truckin'
if (warn(log))
warn(
log,
Thread.currentThread().getName()
+ " was interrupted while awaiting shutdown of import thread pool.",
ie);
}
} finally {
// Reset the thread factory
if (importThreadPool.getThreadFactory() instanceof BulkImportThreadFactory) {
((BulkImportThreadFactory) importThreadPool.getThreadFactory()).reset();
}
// Mark the import complete
importStatus.importComplete();
// Invoke the completion handlers (if any)
if (completionHandlers != null) {
for (final BulkImportCompletionHandler handler : completionHandlers) {
try {
handler.importComplete(importStatus);
} catch (final Exception e) {
if (error(log))
error(
log, "Completion handler threw an unexpected exception. It will be ignored.", e);
}
}
}
// Always invoke the logging completion handler last
loggingBulkImportCompletionHandler.importComplete(importStatus);
}
}
