MixedClusterClientYamlTestSuiteIT times out more frequently lately

[nik9000]

Build scan: https://gradle-enterprise.elastic.co/s/4plpdtisgjwnu/

Repro line: Not going to be useful.

Reproduces locally?: No.

Applicable branches: 7.11, 7.12, 7.x. Happens on master, but only on windows as far as I can see.

Failure history:

https://build-stats.elastic.co/goto/2e7535c11ed73598b069d68b420f2014

Failure excerpt:

  2> WARNING: Suite execution timed out: org.elasticsearch.backwards.MixedClusterClientYamlTestSuiteIT
  2> ==== jstack at approximately timeout time ====
  2> "I/O dispatcher 576" ID=625 RUNNABLE (in native code)
  2> 	at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
  2> 	at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
stack traces looked boring when I scanned them

[mark-vieira]

It seems it's possible the items related to #69641 didn't completely resolve this issue. We see more failures on Windows due to that system being slower already (not using a ramdisk) so any general regression in test execution times is going to plague those builds more.

We can see this isn't specific to platform though. There's a clear regression in execution time for this test suite even on linux (below graph doesn't include Windows builds):

I believe the the fixes mentioned in #69641 should have percolated through CI already at this point. It sounds like there's still more work to do here to track down why these tests are taking so much longer.

[elasticmachine]

Pinging @elastic/es-core-features (Team:Core/Features)

[mark-vieira]

@jakelandis I hate to just tag Core/Features on this one again but I just want to ensure someone has eyes on this. We have a larger problem of these very coarse tests suites not having clear ownership which I intend to bring up to a larger audience.

[mark-vieira]

I believe the build scan @nik9000 linked to is incorrect, Here's a recent timeout failure: https://gradle-enterprise.elastic.co/s/qwnmut63k53hq

[mark-vieira]

I think this is a larger more serious issue. Here is the trend of our BWC jobs on the 7.x branch over the past month. Average build times have doubled here. Keep in mind, these builds on are Linux using ramdisks. We've introduced some serious regression somewhere here.

[jakelandis]

another example: https://gradle-enterprise.elastic.co/s/wdxaxxugsaka6

Both :qa:mixed-cluster:v6.8.15#mixedClusterTest, but different actual tests , and both on Linux.

in one case:
MixedClusterClientYamlTestSuiteIT » test {p0=search/160_exists_query/Test exists query on object inner field in empty index}

and in the other:
MixedClusterClientYamlTestSuiteIT » test {p0=indices.get_alias/10_basic/Get aliases via /name,name/_alias/{name}}

Also no smoking gun like regex or long pauses in test (from a quick scan of the logs).

[mark-vieira]

Here's the build times for master. There's a slight increase around the same time period but not quite as extreme. I suspect that the BWC testing against 6.8.15 is more problematic.

[nik9000]

I believe the build scan @nik9000 linked to is incorrect, Here's a recent timeout failure: https://gradle-enterprise.elastic.co/s/qwnmut63k53hq

Looks like I linked to a regular yaml test timing out. I got my wires crossed. But its also bad that that task fails.

[mark-vieira]

Jake and I did some digging here and I think we've nailed down a timeframe where we thing some kind of regression snuck into MixedClusterClientYamlTestSuiteIT. He's going to follow up on doing further investigations here. Thanks, Jake!

[jakelandis]

OK ... pretty sure I got to the bottom of this.

#69153 changed the distribution used by this (and other tests) to use the default distribution. This results in a different code flow in ESRestTestCase when cleaning up after itself. There is a check in there hasXpack that changes how the clean up of the composable templates and performed. Prior to that change, it hit a work flow where the first _index_template/* would (correctly) silently error and move on. In the new workflow with the default distribution, the logic is different and it appears that there is more work being done. For example instead of * it is deleting in a loop, and instead of short circuiting the call to delete the composable templates via the original exception, a call is being made get the composable templates, erroring and producing a stack trace.

All of this is very minimal per test... up to ~200ms slower...however, 200ms * 1300 test , then add on a additional full round of tests (due to a new staging branch) and that 40m window isn't quite good enough.

To reproduce

Use this command:

./gradlew  :qa:mixed-cluster:v6.8.15#mixedClusterTest  -Dtests.method="test {p0=search/220_total_hits_object/*}" --info

and this debug logging

diff --git a/test/framework/src/main/java/org/elasticsearch/test/rest/ESRestTestCase.java b/test/framework/src/main/java/org/elasticsearch/test/rest/ESRestTestCase.java
index 799a21a95fb..7395b983ee5 100644
--- a/test/framework/src/main/java/org/elasticsearch/test/rest/ESRestTestCase.java
+++ b/test/framework/src/main/java/org/elasticsearch/test/rest/ESRestTestCase.java
@@ -203,6 +203,7 @@ public abstract class ESRestTestCase extends ESTestCase {
                 nodeVersions.add(Version.fromString(nodeInfo.get("version").toString()));
                 for (Object module: (List<?>) nodeInfo.get("modules")) {
                     Map<?, ?> moduleInfo = (Map<?, ?>) module;
+                    logger.info("**** moduleInfo.get(\"name\"): " + moduleInfo.get("name"));
                     if (moduleInfo.get("name").toString().startsWith("x-pack-")) {
                         hasXPack = true;
                     }
@@ -593,8 +594,12 @@ public abstract class ESRestTestCase extends ESTestCase {
             wipeAllIndices();
         }
 
+        logger.info("**** Clearing preserveTemplatesUponCompletion [{}]", preserveTemplatesUponCompletion() );
         // wipe index templates
         if (preserveTemplatesUponCompletion() == false) {
+
+
+            logger.info("**** hasXpack [{}]", hasXPack() );
             if (hasXPack) {
                 /*
                  * Delete only templates that xpack doesn't automatically
@@ -605,6 +610,7 @@ public abstract class ESRestTestCase extends ESTestCase {
                 Request request = new Request("GET", "_cat/templates");
                 request.addParameter("h", "name");
                 String templates = EntityUtils.toString(adminClient().performRequest(request).getEntity());
+                logger.info("**** \"\".equals(templates)[{}]", "".equals(templates) );
                 if (false == "".equals(templates)) {
                     for (String template : templates.split("\n")) {
                         if (isXPackTemplate(template)) continue;
@@ -648,13 +654,16 @@ public abstract class ESRestTestCase extends ESTestCase {
                     // We hit a version of ES that doesn't support index templates v2 yet, so it's safe to ignore
                 }
             } else {
-                logger.debug("Clearing all templates");
+                logger.info("Clearing all templates");
                 adminClient().performRequest(new Request("DELETE", "_template/*"));
                 try {
+                    logger.info("***** before delete operation");
                     adminClient().performRequest(new Request("DELETE", "_index_template/*"));
                     adminClient().performRequest(new Request("DELETE", "_component_template/*"));
+                    logger.info("***** after delete operation");
                 } catch (ResponseException e) {
                     // We hit a version of ES that doesn't support index templates v2 yet, so it's safe to ignore
+                    logger.info("***** after delete operation - in catch");
                 }
             }
         }

Compare a current version (from today) 785a17c (slower) to something before #69153 such as 16a1662 (faster) and you can see the exact difference. You can see my notes from testing here: https://gist.github.com/jakelandis/428f5f62070c51047db86cf950190e19

I am pretty sure if we can make the xPack workflow closer to the non-xPack workflow we will gain back those ~200ms and the tests will still fit in the 40m window.