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.

Author: DaveCTurner

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<T> {
     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<Path> filter = new DirectoryStream.Filter<Path>() {
-            @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<Path> 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<Path> stream = Files.newDirectoryStream(dataLocation.resolve(STATE_DIR_NAME), filter)) {
                 for (Path stateFile : stream) {
                     Files.deleteIfExists(stateFile);
+                    logger.trace("cleanupOldFiles: cleaned up {}", stateFile);
                 }
             }
         }

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);