Skip to content

add elapsed statistics logs to suggester rebuild #2221

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
merged 5 commits into from
Aug 13, 2019
Merged

add elapsed statistics logs to suggester rebuild #2221

Changes from 2 commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
c697e82
add elapsed statistics logs to suggester rebuild
Jul 19, 2018
6eb5ecf
use simpler statistics
Aug 13, 2019
2a93d11
logger
Aug 13, 2019
86f7528
use Instant/Duration
Aug 13, 2019
cd1a060
fmt
Aug 13, 2019
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
61 changes: 33 additions & 28 deletions suggester/src/main/java/org/opengrok/suggest/Suggester.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@
*/
package org.opengrok.suggest;

import org.apache.commons.lang3.time.DurationFormatUtils;
import org.apache.lucene.index.DirectoryReader;
import org.apache.lucene.index.IndexReader;
import org.apache.lucene.index.Term;
Expand Down Expand Up @@ -64,7 +65,7 @@ public final class Suggester implements Closeable {

private static final String PROJECTS_DISABLED_KEY = "";

private static final Logger logger = Logger.getLogger(Suggester.class.getName());
private static final Logger LOGGER = Logger.getLogger(Suggester.class.getName());

private final Map<String, SuggesterProjectData> projectData = new ConcurrentHashMap<>();

Expand Down Expand Up @@ -140,23 +141,24 @@ public Suggester(
*/
public void init(final Collection<NamedIndexDir> luceneIndexes) {
if (luceneIndexes == null || luceneIndexes.isEmpty()) {
logger.log(Level.INFO, "No index directories found, exiting...");
LOGGER.log(Level.INFO, "No index directories found, exiting...");
return;
}
if (!projectsEnabled && luceneIndexes.size() > 1) {
throw new IllegalArgumentException("Projects are not enabled and multiple Lucene indexes were passed");
}

synchronized (lock) {
logger.log(Level.INFO, "Initializing suggester");
long startTime = System.currentTimeMillis();
LOGGER.log(Level.INFO, "Initializing suggester");

ExecutorService executor = Executors.newWorkStealingPool(rebuildParallelismLevel);

for (NamedIndexDir indexDir : luceneIndexes) {
submitInitIfIndexExists(executor, indexDir);
}

shutdownAndAwaitTermination(executor, "Suggester successfully initialized");
shutdownAndAwaitTermination(executor, startTime, "Suggester successfully initialized");
}
}

Expand All @@ -165,18 +167,18 @@ private void submitInitIfIndexExists(final ExecutorService executorService, fina
if (indexExists(indexDir.path)) {
executorService.submit(getInitRunnable(indexDir));
} else {
logger.log(Level.FINE, "Index in {0} directory does not exist, skipping...", indexDir);
LOGGER.log(Level.FINE, "Index in {0} directory does not exist, skipping...", indexDir);
}
} catch (IOException e) {
logger.log(Level.WARNING, "Could not check if index exists", e);
LOGGER.log(Level.WARNING, "Could not check if index exists", e);
}
}

private Runnable getInitRunnable(final NamedIndexDir indexDir) {
return () -> {
try {
Instant start = Instant.now();
logger.log(Level.FINE, "Initializing {0}", indexDir);
LOGGER.log(Level.FINE, "Initializing {0}", indexDir);

SuggesterProjectData wfst = new SuggesterProjectData(FSDirectory.open(indexDir.path),
getSuggesterDir(indexDir.name), allowMostPopular, allowedFields);
Expand All @@ -188,9 +190,9 @@ private Runnable getInitRunnable(final NamedIndexDir indexDir) {
}

Duration d = Duration.between(start, Instant.now());
logger.log(Level.FINE, "Finished initialization of {0}, took {1}", new Object[] {indexDir, d});
LOGGER.log(Level.FINE, "Finished initialization of {0}, took {1}", new Object[] {indexDir, d});
} catch (Exception e) {
logger.log(Level.SEVERE, "Could not initialize suggester data for " + indexDir, e);
LOGGER.log(Level.SEVERE, "Could not initialize suggester data for " + indexDir, e);
}
};
}
Expand All @@ -209,13 +211,15 @@ private boolean indexExists(final Path indexDir) throws IOException {
}
}

private void shutdownAndAwaitTermination(final ExecutorService executorService, final String logMessageOnSuccess) {
private void shutdownAndAwaitTermination(final ExecutorService executorService, long startTime, final String logMessageOnSuccess) {
executorService.shutdown();
try {
executorService.awaitTermination(awaitTerminationTime.toMillis(), TimeUnit.MILLISECONDS);
logger.log(Level.INFO, logMessageOnSuccess);
LOGGER.log(Level.INFO, logMessageOnSuccess + " (took {0})",
DurationFormatUtils.formatDurationWords(System.currentTimeMillis() - startTime,
true, true));
} catch (InterruptedException e) {
logger.log(Level.SEVERE, "Interrupted while building suggesters", e);
LOGGER.log(Level.SEVERE, "Interrupted while building suggesters", e);
Thread.currentThread().interrupt();
}
}
Expand All @@ -226,12 +230,13 @@ private void shutdownAndAwaitTermination(final ExecutorService executorService,
*/
public void rebuild(final Collection<NamedIndexDir> indexDirs) {
if (indexDirs == null || indexDirs.isEmpty()) {
logger.log(Level.INFO, "Not rebuilding suggester data because no index directories were specified");
LOGGER.log(Level.INFO, "Not rebuilding suggester data because no index directories were specified");
return;
}

synchronized (lock) {
logger.log(Level.INFO, "Rebuilding the following suggesters: {0}", indexDirs);
long startTime = System.currentTimeMillis();
LOGGER.log(Level.INFO, "Rebuilding the following suggesters: {0}", indexDirs);

ExecutorService executor = Executors.newWorkStealingPool(rebuildParallelismLevel);

Expand All @@ -244,21 +249,21 @@ public void rebuild(final Collection<NamedIndexDir> indexDirs) {
}
}

shutdownAndAwaitTermination(executor, "Suggesters for " + indexDirs + " were successfully rebuilt");
shutdownAndAwaitTermination(executor, startTime, "Suggesters for " + indexDirs + " were successfully rebuilt");
}
}

private Runnable getRebuildRunnable(final SuggesterProjectData data) {
return () -> {
try {
Instant start = Instant.now();
logger.log(Level.FINE, "Rebuilding {0}", data);
LOGGER.log(Level.FINE, "Rebuilding {0}", data);
data.rebuild();

Duration d = Duration.between(start, Instant.now());
logger.log(Level.FINE, "Rebuild of {0} finished, took {1}", new Object[] {data, d});
LOGGER.log(Level.FINE, "Rebuild of {0} finished, took {1}", new Object[] {data, d});
} catch (Exception e) {
logger.log(Level.SEVERE, "Could not rebuild suggester", e);
LOGGER.log(Level.SEVERE, "Could not rebuild suggester", e);
}
};
}
Expand All @@ -273,12 +278,12 @@ public void remove(final Iterable<String> names) {
}

synchronized (lock) {
logger.log(Level.INFO, "Removing following suggesters: {0}", names);
LOGGER.log(Level.INFO, "Removing following suggesters: {0}", names);

for (String suggesterName : names) {
SuggesterProjectData collection = projectData.get(suggesterName);
if (collection == null) {
logger.log(Level.WARNING, "Unknown suggester {0}", suggesterName);
LOGGER.log(Level.WARNING, "Unknown suggester {0}", suggesterName);
continue;
}
collection.remove();
Expand Down Expand Up @@ -329,7 +334,7 @@ private Suggestions prefixLookup(
List<LookupResultItem> results = readers.parallelStream().flatMap(namedIndexReader -> {
SuggesterProjectData data = projectData.get(namedIndexReader.name);
if (data == null) {
logger.log(Level.FINE, "{0} not yet initialized", namedIndexReader.name);
LOGGER.log(Level.FINE, "{0} not yet initialized", namedIndexReader.name);
partialResult.value = true;
return Stream.empty();
}
Expand Down Expand Up @@ -368,7 +373,7 @@ private Suggestions complexLookup(
try {
futures = executorService.invokeAll(searchTasks, timeThreshold, TimeUnit.MILLISECONDS);
} catch (InterruptedException e) {
logger.log(Level.WARNING, "Interrupted while invoking suggester search", e);
LOGGER.log(Level.WARNING, "Interrupted while invoking suggester search", e);
Thread.currentThread().interrupt();
return new Suggestions(Collections.emptyList(), true);
}
Expand All @@ -387,7 +392,7 @@ private Suggestions complexLookup(
try {
searchTask.wait();
} catch (InterruptedException e) {
logger.log(Level.WARNING, "Interrupted while waiting for task: {0}", searchTask);
LOGGER.log(Level.WARNING, "Interrupted while waiting for task: {0}", searchTask);
Thread.currentThread().interrupt();
}
}
Expand Down Expand Up @@ -427,7 +432,7 @@ public void onSearch(final Iterable<String> projects, final Query query) {
}
}
} catch (Exception e) {
logger.log(Level.FINE, "Could not update search count map", e);
LOGGER.log(Level.FINE, "Could not update search count map", e);
}
}

Expand Down Expand Up @@ -473,7 +478,7 @@ public void increaseSearchCount(final String project, final Term term, final int
}

if (data == null) {
logger.log(Level.WARNING, "Cannot update search count because of missing suggester data{}",
LOGGER.log(Level.WARNING, "Cannot update search count because of missing suggester data{}",
projectsEnabled ? " for project " + project : "");
return;
}
Expand All @@ -497,7 +502,7 @@ public List<Entry<BytesRef, Integer>> getSearchCounts(
) {
SuggesterProjectData data = projectData.get(project);
if (data == null) {
logger.log(Level.FINE, "Cannot retrieve search counts because suggester data for project {0} was not found",
LOGGER.log(Level.FINE, "Cannot retrieve search counts because suggester data for project {0} was not found",
project);
return Collections.emptyList();
}
Expand All @@ -515,7 +520,7 @@ public void close() {
try {
f.close();
} catch (IOException e) {
logger.log(Level.WARNING, "Could not close suggester data " + f, e);
LOGGER.log(Level.WARNING, "Could not close suggester data " + f, e);
}
});
}
Expand Down Expand Up @@ -549,7 +554,7 @@ public Void call() {

SuggesterProjectData data = projectData.get(namedIndexReader.name);
if (data == null) {
logger.log(Level.FINE, "{0} not yet initialized", namedIndexReader.name);
LOGGER.log(Level.FINE, "{0} not yet initialized", namedIndexReader.name);
return null;
}
boolean gotLock = data.tryLock();
Expand Down