[7.x] :qa:mixed-cluster:v7.11.2#mixedClusterTest {p0=cat.nodes/10_basic/Test cat nodes output}

[jakelandis]

This is a continuation of #69641

On 7.x it appears that for reasons yet to be determined, the regex used by "cat.nodes/10_basic/Test cat nodes output" is extremely expensive, to the point of causing tests to timeout.

On a modern desktop CPU the following command on 7.x can take over 1 minute to run

./gradlew ':qa:mixed-cluster:v7.11.2#mixedClusterTest'  -Dtests.timestamp=$(date +%S) -Dtests.method="test {p0=cat.nodes/10_basic/Test cat nodes output}" --info

For example:

org.elasticsearch.backwards.MixedClusterClientYamlTestSuiteIT > test {p0=cat.nodes/10_basic/Test cat nodes output} STANDARD_OUT
    [2021-03-02T03:46:19,108][INFO ][o.e.b.MixedClusterClientYamlTestSuiteIT] [test] [p0=cat.nodes/10_basic/Test cat nodes output] before test
    [2021-03-02T03:46:19,189][INFO ][o.e.b.MixedClusterClientYamlTestSuiteIT] [test] initializing REST clients against [http://[::1]:45603, http://127.0.0.1:46583, http://[::1]:43459, http://127.0.0.1:44891, http://[::1]:33689, http://127.0.0.1:33833, http://[::1]:36341, http://127.0.0.1:43035]
    [2021-03-02T03:46:19,617][INFO ][o.e.b.MixedClusterClientYamlTestSuiteIT] [test] initializing client, minimum es version [7.11.2], master version, [7.11.2], hosts [http://[::1]:45603, http://127.0.0.1:46583, http://[::1]:43459, http://127.0.0.1:44891, http://[::1]:33689, http://127.0.0.1:33833, http://[::1]:36341, http://127.0.0.1:43035], os [Ubuntu 20.04.1 LTS]
    [2021-03-02T03:48:19,626][INFO ][o.e.b.MixedClusterClientYamlTestSuiteIT] [test] Clearing template [.logstash-management]
    [2021-03-02T03:48:20,020][INFO ][o.e.b.MixedClusterClientYamlTestSuiteIT] [test] [p0=cat.nodes/10_basic/Test cat nodes output] after test

It has been observed that when running the full test suite that (on the same hardware ^^) to take 4 minutes.

Most all evidence and some testing done be @benwtrent lay blame at the regular expression(s) used in this test.

Further, I have found some successful tests that took 15m to perform this test:

It appears that this started with the innocent change introduced by #68605, which merely adds a character to set of character constants. During that 4m local test, I was able to grab the output of a _cat/nodes while the CPU was pegged with lots of work happening in regex (as evident by the stack)

ip        heap.percent ram.percent cpu load_1m load_5m load_15m node.role   master name
127.0.0.1           53          99   2    1.99    4.27     4.11 cdfhilmrstw -      v7.11.2-0
127.0.0.1           62          99   2    1.99    4.27     4.11 cdhilmrstw  -      v7.11.2-3
127.0.0.1           55          99   2    1.99    4.27     4.11 cdfhilmrstw -      v7.11.2-1
127.0.0.1           76          99   2    1.99    4.27     4.11 cdhilmrstw  *      v7.11.2-2

Oddly this is not an issue for master or other branches and seems specific to 7.x. The equivalent command from master is :

./gradlew ':qa:mixed-cluster:v7.13.0#mixedClusterTest'  -Dtests.timestamp=$(date +%S) -Dtests.method="test {p0=cat.nodes/10_basic/Test cat nodes output}" --info

and executes in under 1s on that same hardware ^^.

Build scan:

https://gradle-enterprise.elastic.co/s/az2nnpcpm5dd6

Repro line:

On 7.x

./gradlew ':qa:mixed-cluster:v7.11.2#mixedClusterTest'  -Dtests.timestamp=$(date +%S) -Dtests.method="test {p0=cat.nodes/10_basic/Test cat nodes output}" --info

Reproduces locally?:

The slowness does, but only up to 4m so far. I have not been able to

Applicable branches:

7.x

Failure history:
build-stats

and

gradle enterprise

Failure excerpt:

You will see "p0=cat.nodes/10_basic/Test cat nodes output" as the last test to execute. In the server logs, you will see a long pause with nothing in the logs until the container is killed by the test timeout. No relevant error.

[elasticmachine]

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

[benwtrent]

The thread stacks all indicated something funky with the regex. But using microbenchmarks, I could not see any huge performance problems. The regex always measured in nanoseconds (creating and applying the pattern)

I was using Java 15.

My understanding of the mixed cluster tests is that the client is using the "modern" ES version.
If there were regex issues, why aren't we seeing them in the mixed cluster tests hitting other versions?

The thread stacks and the fact that jake was able to get the API response faster than the test could finish indicate some processing after the API response is the cause. So, regex.

It doesn't all add up to me. We are obviously missing something.

[jakelandis]

muted only on 7.x : ee3673e

[jakelandis]

I think this is a long standing issue...but just now discovered. I can't see any direct correlation to #68605.

I am able to reproduce. By adding the following additional logging :

diff --git a/test/framework/src/main/java/org/elasticsearch/test/rest/yaml/section/MatchAssertion.java b/test/framework/src/main/java/org/elasticsearch/test/rest/yaml/section/MatchAssertion.java
index 0c205d368d0..bfa13576435 100644
--- a/test/framework/src/main/java/org/elasticsearch/test/rest/yaml/section/MatchAssertion.java
+++ b/test/framework/src/main/java/org/elasticsearch/test/rest/yaml/section/MatchAssertion.java
@@ -53,9 +53,10 @@ public class MatchAssertion extends Assertion {
                         safeClass(actualValue) + "]", actualValue, instanceOf(String.class));
                 String stringValue = (String) actualValue;
                 String regex = expValue.substring(1, expValue.length() - 1);
-                logger.trace("assert that [{}] matches [{}]", stringValue, regex);
+                logger.info("assert that [{}] matches [{}]", stringValue, regex);
                 assertThat("field [" + getField() + "] was expected to match the provided regex but didn't",
                         stringValue, matches(regex, Pattern.COMMENTS));
+                logger.info("done - assert that [{}] matches [{}]", stringValue, regex);
                 return;
             }
         }

and then run

./gradlew ':qa:mixed-cluster:v7.11.2#mixedClusterTest'  -Dtests.timestamp=$(date +%S) -Dtests.method="test {p0=cat.nodes/10_basic/Test cat nodes output}" --info

I can now see the exact regex and matching string and create a repro case:

import java.util.regex.Matcher;
import java.util.regex.Pattern;

class Scratch {
    static String patternFromTest =  "  #ip                          heap.percent        ram.percent     cpu         load_1m                load_5m                load_15m               node.role                   master          name\n" +
            "    ^  ((\\d{1,3}\\.){3}\\d{1,3}  \\s+  \\d+            \\s+  \\d*         \\s+ (-)?\\d* \\s+ ((-)?\\d*(\\.\\d+)?)? \\s+ ((-)?\\d*(\\.\\d+)?)?\\s+  ((-)?\\d*(\\.\\d+)?)? \\s+ (-|[cdfhilmrstvw]{1,11}) \\s+ [-*x]     \\s+   (\\S+\\s?)+     \\n)+  $";
    static Pattern pattern = Pattern.compile(patternFromTest, Pattern.COMMENTS);
    static String outputFromTest ="127.0.0.1 22 71 7 5.83 3.24 1.62 cdfhilmrstw - v7.11.2-0\n" +
            "127.0.0.1 65 71 8 5.83 3.24 1.62 cdfhilmrstw - v7.11.2-1\n" +
            "127.0.0.1 70 71 9 5.83 3.24 1.62 cdhilmrstw  * v7.11.2-2\n" +
            "127.0.0.1 45 71 9 5.83 3.24 1.62 cdhilmrstw  - v7.11.2-3\n";
    public static void main(String[] args) {
        Matcher matcher = pattern.matcher(outputFromTest);
        long start = System.currentTimeMillis();
        System.out.println("start...");
        matcher.find();
        for(int i = 0 ; i <= matcher.groupCount(); i++){
            System.out.println("#### Group "+ i + " ########");
            System.out.println(matcher.group(i));
        }
        System.out.println("\ntook " + (System.currentTimeMillis() - start) /1000 + " seconds");
    }
}

with the output:

start...
#### Group 0 ########
127.0.0.1 22 71 7 5.83 3.24 1.62 cdfhilmrstw - v7.11.2-0
127.0.0.1 65 71 8 5.83 3.24 1.62 cdfhilmrstw - v7.11.2-1
127.0.0.1 70 71 9 5.83 3.24 1.62 cdhilmrstw  * v7.11.2-2
127.0.0.1 45 71 9 5.83 3.24 1.62 cdhilmrstw  - v7.11.2-3

#### Group 1 ########
127.0.0.1 45 71 9 5.83 3.24 1.62 cdhilmrstw  - v7.11.2-3

#### Group 2 ########
0.
#### Group 3 ########
null
#### Group 4 ########
5.83
#### Group 5 ########
null
#### Group 6 ########
.83
#### Group 7 ########
3.24
#### Group 8 ########
null
#### Group 9 ########
.24
#### Group 10 ########
1.62
#### Group 11 ########
null
#### Group 12 ########
.62
#### Group 13 ########
cdhilmrstw
#### Group 14 ########
v7.11.2-3

took 31 seconds

Note - the first line of the regex is a comment, so you must enable the Pattern.COMMENTS flag.

Also note that the output is multi-line, but the pattern compiler does not set that flag, despite the regex appearing to try to support multi-line (at least how i am reading the intent of the regex). The actual matching is only done against the first line.

Removing the f makes no difference so pretty sure this is not directly related to #68605, and unsure why this seems so common at the momement but only for 7.x.

It appears that the offender is (\S+\s?)+ ..not really sure what that is doing. I think it is a hack to match multi-line...but we don't actually match multi-line and we don't care about groups here, so I think we can just replace this with .* It also work and at least in my repro case, it very fast.

for example:

-               ^  ((\d{1,3}\.){3}\d{1,3}  \s+  \d+            \s+  \d*         \s+ (-)?\d* \s+ ((-)?\d*(\.\d+)?)? \s+ ((-)?\d*(\.\d+)?)?\s+  ((-)?\d*(\.\d+)?)? \s+ (-|[cdfhilmrstvw]{1,11}) \s+ [-*x]     \s+   (\S+\s?)+     \n)+  $/
+               ^  ((\d{1,3}\.){3}\d{1,3}  \s+  \d+            \s+  \d*         \s+ (-)?\d* \s+ ((-)?\d*(\.\d+)?)? \s+ ((-)?\d*(\.\d+)?)?\s+  ((-)?\d*(\.\d+)?)? \s+ (-|[cdfhilmrstvw]{1,11}) \s+ [-*x]     \s+   .*    \n)+  $/

EDIT: off-by mistake fixed

[benwtrent]

I think the .* should work just fine as we have the $ end anchor and are indeed only matching single lines.

Really great and tricky find!