[BUG] JSQLParser 4.6 : PostgreSQL : CPU burn when parsing certain queries

[llehtinen]

Always check against the Latest SNAPSHOT of JSQLParser and the Syntax Diagram

Failing SQL Feature:

• Parenthesis in a query lead to CPU burn - my example has ((( ... ))), add more parenthesis to see significant increase in the time it takes to fail

SQL Example:

• Valid PostgreSQL query (heavily reduced from a large query with many nested cases):

  -- Simple query which fails fast
  SELECT ('{"obj":{"field": "value"}}'::JSON -> 'obj'::TEXT ->> 'field'::TEXT)
  
  -- Same query nested in a case statement, takes the CPU for a spin
  SELECT
   CASE
      WHEN true
      THEN (SELECT ((('{"obj":{"field": "value"}}'::JSON -> 'obj'::TEXT ->> 'field'::TEXT))))
   END

My notes:

I was trying to narrow down the issue by testing the case statement query like this:

CCJSqlParserUtil.newParser(sql).withAllowComplexParsing(allowComplexParsing).statements();

JSql	allowComplexParsing	outcome
4.5	false	Fails fast
4.5	true	Fails after ~10 seconds of 100% CPU
4.6	false	Fails after ~20 seconds of 100% CPU
4.6	true	Doesn't finish in 3 minutes, CPU stays at 100%

Software Information:

• JSqlParser 4.5, 4.6
• Database PostgreSQL
  • https://www.postgresql.org/docs/9.3/functions-json.html

[manticore-projects]

Greetings!

Thanks for reporting, we are always very interested in such performance related corner cases.
Good news is: With PR #1778 your complex query times out as expected (within 20 seconds):

    // Supposed to time out
    @Test
    void testComplexIssue1792() throws JSQLParserException {
        String sqlStr =
                "SELECT\n"
                + " CASE\n"
                + "    WHEN true\n"
                + "    THEN (SELECT ((('{\"obj\":{\"field\": \"value\"}}'::JSON -> 'obj'::TEXT ->> 'field'::TEXT))))\n"
                + " END";
        Assertions.assertThrows(TimeoutException.class, new Executable() {
            @Override
            public void execute() throws Throwable {
                try {
                    assertSqlCanBeParsedAndDeparsed(sqlStr, true);
                } catch (JSQLParserException ex) {
                    throw ex.getCause();
                }
            }
        });
    }

Now, the more interesting question is: Is this query valid? (I am not good with this JSON crap.)
If it is valid on the RDBMS, then I would like to look for ways to speeding it up.

[manticore-projects]

You can make it time out faster when you don't want to wait 20 seconds:

    // Supposed to time out
    @Test
    void testComplexIssue1792() throws JSQLParserException {
        String sqlStr =
                "SELECT\n"
                + " CASE\n"
                + "    WHEN true\n"
                + "    THEN (SELECT ((('{\"obj\":{\"field\": \"value\"}}'::JSON -> 'obj'::TEXT ->> 'field'::TEXT))))\n"
                + " END";
        Assertions.assertThrows(TimeoutException.class, new Executable() {
            @Override
            public void execute() throws Throwable {
                try {
                    CCJSqlParserUtil.parse(sqlStr, parser -> {
                        parser.withTimeOut(1000);
                        parser.withAllowComplexParsing(true);
                    });
                } catch (JSQLParserException ex) {
                    throw ex.getCause();
                }
            }
        });
    }

[llehtinen]

Hey, and thanks for having a look.

The query is valid (whether it's a good query, different question).

I got into troubleshooting this because we had to roll back a deployment due to the CPU burn this was causing.

As for the other suggestion, we are intentionally staying away from the CCJSqlParserUtil.parse due to the single use executors created (and thrown away) by it.

[manticore-projects]

Thanks for quick round turn.

The query is valid (whether it's a good query, different question).
Great, so ideally it should parse and I would aim for that.

I got into troubleshooting this because we had to roll back a deployment due to the CPU burn this was causing.

Sorry for that but I still wonder how exactly you have achieved that. The Executor is there since 4.6 and should catch such timeouts reliably. How exactly are you parsing, please show me the boiler plate code.

As for the other suggestion, we are intentionally staying away from the CCJSqlParserUtil.parse due to the single use executors created (and thrown away) by it.

This executor my friend would have saved you! Because it observes if a query stalls and kills it softly before your CPU burns. Do you have a better/alternative suggestion replacing the "single use executor thrown away"? E. g. have a single instance of this executor which will be used for all queries and then only get destroyed on demand at the end?

[llehtinen]

Sorry for that but I still wonder how exactly you have achieved that. The Executor is there since 4.6 and should catch such timeouts reliably. How exactly are you parsing, please show me the boiler plate code.

Here is the code:

    /*
      Don't use `CCJSqlParserUtil.parse`, this has an overhead of launching a new executor service and parsing the sql there.
     */
    CCJSqlParser parser = CCJSqlParserUtil.newParser(sql).withAllowComplexParsing(false);

    return parser.Statements();

In the application in question, the number of requests is such that timing out after 20 seconds is not much better than never finishing.

One option you might consider is letting the client provide the executor. But the parsing sometimes going AWOL like this, is a bigger concern in my opinion.

[manticore-projects]

I am sorry for asking a dumb question: Why is the simplified select also failing if the query was valid?

    // Supposed to fail, but not to hang or time out
    @Test
    @Timeout(2000)
    void testIssue1792() throws JSQLParserException {
        String sqlStr =
                "SELECT ('{\"obj\":{\"field\": \"value\"}}'::JSON -> 'obj'::TEXT ->> 'field'::TEXT)";
        Assertions.assertThrows(JSQLParserException.class, new Executable() {
            @Override
            public void execute() throws Throwable {
               assertSqlCanBeParsedAndDeparsed(sqlStr, true);
            }
        });
    }

[llehtinen]

Why JSqlParser is failing to parse it? I don't know 😄

[llehtinen]

I believe this has not been an issue for us with 4.5 because it fails fast.

We're using this library to collect statistics on table usage, and those are recorded after the query has been executed. If it fails, it's not the end of the world. But if it hangs, it sort of is. As it turned out.

[manticore-projects]

Ok, so as far as I understand it, we have 2 problems here:

1. We need to provide a facility, where a large number of queries can be parsed under the super-vision of one single time-out monitor (instead of spawning one for each query).

2. We need to figure out, why your query can't be parsed.

Unfortunately you will always be able to craft a statement which will trip the Parser.
In 4.5 it has not been an issue because many other things have been an issue. We have added support for many many syntax -- but this also made parsing certain statements much more complex.

[manticore-projects]

Why JSqlParser is failing to parse it? I don't know smile

Can you provide an illustration of the Postgres AST for this please? JSON in RDBMS is my arch nemesis and I need to understand first, what this thing is supposed to mean. Thanks for helping!

[llehtinen]

Maybe this helps. The first -> just extracts the value of obj, i.e. {"field": "value"} from the original json.

Then, in the original query, the subsequent ->> gets the value of field.

As for the differences between -> and ->> operators: https://www.postgresql.org/docs/9.3/functions-json.html.

As mentioned in the issue, this silly query is

heavily reduced from a large query with many nested cases

I just tried to boil it down to something that caused the behavior we observed.

[manticore-projects]

As far as I understand it, this kind of chaining of JSON Expressions has not been considered/implemented.
I would try to get it working tomorrow.

[llehtinen]

I played a bit with your suggestion and noticed that it took twice as long as the timeout value I provided.

On closer look, somewhat unexpectedly, the parsing was attempted twice (each time in its own single-use executor).

        // first, try to parse fast and simple
        try {
            CCJSqlParser parser = newParser(sql).withAllowComplexParsing(false);
            if (consumer != null) {
                consumer.accept(parser);
            }
            statement = parseStatement(parser);
        } catch (JSQLParserException ex) {
            if (getNestingDepth(sql)<=ALLOWED_NESTING_DEPTH) {
                CCJSqlParser parser = newParser(sql).withAllowComplexParsing(true);
                if (consumer != null) {
                    consumer.accept(parser);
                }
                statement = parseStatement(parser);
            }
        }

[manticore-projects]

Yes, but you can avoid this by dis-allowing COMPLEX parsing:

CCJSqlParserUtil.parse(sqlStr, parser -> {
                        parser.withTimeOut(1000);
                        parser.withAllowComplexParsing(false);
                    });

[llehtinen]

With 4.6, the example you provided, there are two attempts to parse the statement that time out.

On the second attempt, complex parsing setting is overridden to false, but there's still an attempt, and it still times out.

In total, it takes a little over 2 seconds.