From 6009dc350fe9e8297243d1c742bd6a20971db6cb Mon Sep 17 00:00:00 2001 From: David Turner Date: Thu, 14 Jun 2018 08:37:25 +0100 Subject: [PATCH 1/2] More detailed tracing during writing metadata 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. --- .../java/org/elasticsearch/gateway/MetaDataStateFormat.java | 4 ++++ .../main/java/org/elasticsearch/gateway/MetaStateService.java | 2 ++ 2 files changed, 6 insertions(+) diff --git a/server/src/main/java/org/elasticsearch/gateway/MetaDataStateFormat.java b/server/src/main/java/org/elasticsearch/gateway/MetaDataStateFormat.java index 0821b176e75e6..c7db548044165 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,6 +148,7 @@ 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); } 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); From 4fc8a94381d7fc1fdf4fc3ad4f9e1a7255f89a8c Mon Sep 17 00:00:00 2001 From: David Turner Date: Thu, 14 Jun 2018 11:36:08 +0100 Subject: [PATCH 2/2] Trace deleteIfExists calls too --- .../gateway/MetaDataStateFormat.java | 17 +++++++++-------- 1 file changed, 9 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 c7db548044165..e048512e6382c 100644 --- a/server/src/main/java/org/elasticsearch/gateway/MetaDataStateFormat.java +++ b/server/src/main/java/org/elasticsearch/gateway/MetaDataStateFormat.java @@ -151,10 +151,12 @@ public void close() throws IOException { 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); } @@ -215,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); } } }