From 4877cec3e82554cfc7a03f3552b3c62198af0d28 Mon Sep 17 00:00:00 2001 From: David Turner Date: Thu, 14 Jun 2018 13:41:25 +0100 Subject: [PATCH] More detailed tracing when writing metadata (#31319) Packaging tests are occasionally failing (#30295) because of very slow index template creation. It looks like the slow part is updating the on-disk cluster state, and this change will help to confirm this. --- .../gateway/MetaDataStateFormat.java | 21 ++++++++++++------- .../gateway/MetaStateService.java | 2 ++ 2 files changed, 15 insertions(+), 8 deletions(-) diff --git a/server/src/main/java/org/elasticsearch/gateway/MetaDataStateFormat.java b/server/src/main/java/org/elasticsearch/gateway/MetaDataStateFormat.java index 0821b176e75e6..e048512e6382c 100644 --- a/server/src/main/java/org/elasticsearch/gateway/MetaDataStateFormat.java +++ b/server/src/main/java/org/elasticsearch/gateway/MetaDataStateFormat.java @@ -29,6 +29,7 @@ import org.apache.lucene.store.IndexInput; import org.apache.lucene.store.OutputStreamIndexOutput; import org.apache.lucene.store.SimpleFSDirectory; +import org.elasticsearch.common.logging.Loggers; import org.elasticsearch.core.internal.io.IOUtils; import org.elasticsearch.ExceptionsHelper; import org.elasticsearch.common.bytes.BytesArray; @@ -76,6 +77,7 @@ public abstract class MetaDataStateFormat { private final String prefix; private final Pattern stateFilePattern; + private static final Logger logger = Loggers.getLogger(MetaDataStateFormat.class); /** * Creates a new {@link MetaDataStateFormat} instance @@ -134,6 +136,7 @@ public void close() throws IOException { IOUtils.fsync(tmpStatePath, false); // fsync the state file Files.move(tmpStatePath, finalStatePath, StandardCopyOption.ATOMIC_MOVE); IOUtils.fsync(stateLocation, true); + logger.trace("written state to {}", finalStatePath); for (int i = 1; i < locations.length; i++) { stateLocation = locations[i].resolve(STATE_DIR_NAME); Files.createDirectories(stateLocation); @@ -145,12 +148,15 @@ public void close() throws IOException { // we are on the same FileSystem / Partition here we can do an atomic move Files.move(tmpPath, finalPath, StandardCopyOption.ATOMIC_MOVE); IOUtils.fsync(stateLocation, true); + logger.trace("copied state to {}", finalPath); } finally { Files.deleteIfExists(tmpPath); + logger.trace("cleaned up {}", tmpPath); } } } finally { Files.deleteIfExists(tmpStatePath); + logger.trace("cleaned up {}", tmpStatePath); } cleanupOldFiles(prefix, fileName, locations); } @@ -211,20 +217,19 @@ protected Directory newDirectory(Path dir) throws IOException { } private void cleanupOldFiles(final String prefix, final String currentStateFile, Path[] locations) throws IOException { - final DirectoryStream.Filter filter = new DirectoryStream.Filter() { - @Override - public boolean accept(Path entry) throws IOException { - final String entryFileName = entry.getFileName().toString(); - return Files.isRegularFile(entry) - && entryFileName.startsWith(prefix) // only state files - && currentStateFile.equals(entryFileName) == false; // keep the current state file around - } + final DirectoryStream.Filter filter = entry -> { + final String entryFileName = entry.getFileName().toString(); + return Files.isRegularFile(entry) + && entryFileName.startsWith(prefix) // only state files + && currentStateFile.equals(entryFileName) == false; // keep the current state file around }; // now clean up the old files for (Path dataLocation : locations) { + logger.trace("cleanupOldFiles: cleaning up {}", dataLocation); try (DirectoryStream stream = Files.newDirectoryStream(dataLocation.resolve(STATE_DIR_NAME), filter)) { for (Path stateFile : stream) { Files.deleteIfExists(stateFile); + logger.trace("cleanupOldFiles: cleaned up {}", stateFile); } } } diff --git a/server/src/main/java/org/elasticsearch/gateway/MetaStateService.java b/server/src/main/java/org/elasticsearch/gateway/MetaStateService.java index 00b981175f228..fd1698bb00659 100644 --- a/server/src/main/java/org/elasticsearch/gateway/MetaStateService.java +++ b/server/src/main/java/org/elasticsearch/gateway/MetaStateService.java @@ -123,6 +123,7 @@ public void writeIndex(String reason, IndexMetaData indexMetaData) throws IOExce try { IndexMetaData.FORMAT.write(indexMetaData, nodeEnv.indexPaths(indexMetaData.getIndex())); + logger.trace("[{}] state written", index); } catch (Exception ex) { logger.warn(() -> new ParameterizedMessage("[{}]: failed to write index state", index), ex); throw new IOException("failed to write state for [" + index + "]", ex); @@ -136,6 +137,7 @@ void writeGlobalState(String reason, MetaData metaData) throws IOException { logger.trace("[_global] writing state, reason [{}]", reason); try { MetaData.FORMAT.write(metaData, nodeEnv.nodeDataPaths()); + logger.trace("[_global] state written"); } catch (Exception ex) { logger.warn("[_global]: failed to write global state", ex); throw new IOException("failed to write global state", ex);