opt: exec timeout due to excessive exploration during planning

[cockroach-teamcity]

sql/tests.TestRandomSyntaxSQLSmith failed with artifacts on master @ dee0558010170d938ead781d82514fd0bb3b0b88:

Random syntax error:

    rsg_test.go:758: Crash detected: server panic: statement exec timeout

Query:

        WITH
        	with_186941 (col_1103773, col_1103774)
        		AS (
        			SELECT
        				*
        			FROM
        				(
        					VALUES
        						(
        							'clvl':::rand_typ_2,
        							st_zmflag('01020000000300000061E7C39F4D2DF4C1093ABD17665CF3C15063C1421B88D5411C9F6E198EDEF3414EEEFB25DF0EF2C1B4850B796774FE41':::GEOMETRY::GEOMETRY)::INT2
        						),
        						(
        							'n':::rand_typ_2,
        							(
        								SELECT
        									tab_455284.col1_6 AS col_1103772
        								FROM
        									defaultdb.public.table1@[0] AS tab_455284
        								ORDER BY
        									tab_455284.col1_2 DESC, tab_455284.col1_1 DESC
        								LIMIT
        									1:::INT8
        							)
        						),
        						(NULL, 6736:::INT8)
        				)
        					AS tab_455285 (col_1103773, col_1103774)
        		),
        	with_186942 (col_1103775) AS (SELECT * FROM (VALUES ('yk':::rand_typ_3), (NULL)) AS tab_455286 (col_1103775))
        SELECT
        	0:::OID AS col_1103776,
        	((-32244820164.24410487):::DECIMAL::DECIMAL + tab_455291.col1_10::INT8)::DECIMAL AS col_1103777,
        	tab_455287._bool AS col_1103778
        FROM
        	with_186942 AS cte_ref_54113,
        	defaultdb.public.seed@[0] AS tab_455287
        	JOIN defaultdb.public.seed AS tab_455288
        		JOIN defaultdb.public.seed AS tab_455289 ON
        				(tab_455288._int8) = (tab_455289._int8)
        				AND (tab_455288._date) = (tab_455289._date)
        				AND (tab_455288._float8) = (tab_455289._float8)
        		JOIN defaultdb.public.table1@[0] AS tab_455290
        			JOIN defaultdb.public.table1@primary AS tab_455291
        				JOIN defaultdb.public.table1@[0] AS tab_455295
        					JOIN defaultdb.public.seed AS tab_455296
        						JOIN defaultdb.public.seed AS tab_455297 ON
        								(tab_455296._int8) = (tab_455297._int8) AND (tab_455296._date) = (tab_455297._date) ON
        							(tab_455295.col1_5) = (tab_455297._float8)
        							AND (tab_455295.col1_5) = (tab_455296._float8)
        							AND (tab_455295.col1_5) = (tab_455297._float8)
        							AND (tab_455295.col1_5) = (tab_455297._float8) ON
        						(tab_455291.col1_2) = (tab_455295.tableoid) AND (tab_455291.col1_7) = (tab_455295.col1_1) ON
        					(tab_455290.col1_2) = (tab_455291.col1_9) AND (tab_455290.col1_7) = (tab_455291.col1_7) ON
        				(tab_455289._float8) = (tab_455296._float8) ON
        			(tab_455287._float4) = (tab_455290.col1_5)
        			AND (tab_455287.tableoid) = (tab_455295.col1_9)
        			AND (tab_455287._bool) = (tab_455295.col1_7);

Schema:

    rsg_test.go:575: To reproduce, use schema:
    rsg_test.go:577: 
        SET CLUSTER SETTING sql.defaults.drop_enum_value.enabled = true;
        SET enable_drop_enum_value = true;
        
        		SET CLUSTER SETTING sql.stats.automatic_collection.enabled = false;
        		SET CLUSTER SETTING sql.stats.histogram_collection.enabled = false;
        		SET CLUSTER SETTING sql.defaults.interleaved_tables.enabled = true;
        	CREATE TABLE table1 (col1_0 CHAR NOT NULL, col1_1 BOOL NOT NULL, col1_2 REGPROC NOT NULL, col1_3 REGPROCEDURE NOT NULL, col1_4 TIMETZ NOT NULL, col1_5 FLOAT8 NULL, col1_6 INT2 NOT NULL, col1_7 BOOL, col1_8 BOX2D NOT NULL, col1_9 REGNAMESPACE NOT NULL, PRIMARY KEY (col1_8 DESC, col1_9 DESC, col1_4 DESC, col1_1, col1_2 ASC, col1_3 DESC, col1_0 DESC, col1_6), col1_10 INT2 NOT NULL AS (col1_6 + 22798:::INT8) VIRTUAL, FAMILY (col1_4), FAMILY (col1_0, col1_5), FAMILY (col1_1), FAMILY (col1_8, col1_3, col1_9, col1_7), FAMILY (col1_2), FAMILY (col1_6));
        ALTER TABLE table1 INJECT STATISTICS '[{"columns": ["col1_1"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 0, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 0}, {"columns": ["col1_3"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 0, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 0}, {"columns": ["col1_5"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 0, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 0}, {"columns": ["col1_6"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 0, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 0}, {"columns": ["col1_0"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 0, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 0}, {"columns": ["col1_2"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 0, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 0}, {"columns": ["col1_4"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 0, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 0}, {"columns": ["col1_7"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 0, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 0}, {"columns": ["col1_8"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 0, "histo_buckets": [{"distinct_range": 0, "num_eq": 10000, "num_range": 0, "upper_bound": "BOX(-10 -10,10 10)"}, {"distinct_range": 80000000, "num_eq": 400000, "num_range": 80000000, "upper_bound": "BOX(-2.047411080418742 -0.7244478039064473,0.5089714550246708 0.018071822061174414)"}, {"distinct_range": 0, "num_eq": 8000000000, "num_range": 5989342388077183799, "upper_bound": "BOX(-1.7565984260464864 -0.22461265918951656,0.3378908234793202 0.05434080126933499)"}], "histo_col_type": "BOX2D", "name": "__auto__", "null_count": 0, "row_count": 0}, {"columns": ["col1_9"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 0, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 0}, {"columns": ["col1_10"], "created_at": "2000-01-01 00:00:00+00:00", "distinct_count": 0, "histo_col_type": "", "name": "__auto__", "null_count": 0, "row_count": 0}]':::JSONB;
        CREATE TYPE rand_typ_0 AS ENUM ('hqerb', 'pvo', 'yjc', 'q', 'f', 'uo');
        CREATE TYPE rand_typ_1 AS ENUM ('ul', 'uteo', 'r', 'c', 'p');
        CREATE TYPE rand_typ_2 AS ENUM ('kl', 'ls', 'jz', 'clvl', 'hrtt', 'n');
        CREATE TYPE rand_typ_3 AS ENUM ('yk');
        ;
    rsg_test.go:577: 
        SET CLUSTER SETTING sql.defaults.drop_enum_value.enabled = true;
        SET enable_drop_enum_value = true;
        
        CREATE TYPE greeting AS ENUM ('hello', 'howdy', 'hi', 'good day', 'morning');
        CREATE TABLE IF NOT EXISTS seed AS
        	SELECT
        		g::INT2 AS _int2,
        		g::INT4 AS _int4,
        		g::INT8 AS _int8,
        		g::FLOAT4 AS _float4,
        		g::FLOAT8 AS _float8,
        		'2001-01-01'::DATE + g AS _date,
        		'2001-01-01'::TIMESTAMP + g * '1 day'::INTERVAL AS _timestamp,
        		'2001-01-01'::TIMESTAMPTZ + g * '1 day'::INTERVAL AS _timestamptz,
        		g * '1 day'::INTERVAL AS _interval,
        		g % 2 = 1 AS _bool,
        		g::DECIMAL AS _decimal,
        		g::STRING AS _string,
        		g::STRING::BYTES AS _bytes,
        		substring('00000000-0000-0000-0000-' || g::STRING || '00000000000', 1, 36)::UUID AS _uuid,
        		'0.0.0.0'::INET + g AS _inet,
        		g::STRING::JSONB AS _jsonb,
        		enum_range('hello'::greeting)[g] as _enum
        	FROM
        		generate_series(1, 5) AS g;
        
        INSERT INTO seed DEFAULT VALUES;
        CREATE INDEX on seed (_int8, _float8, _date);
        CREATE INVERTED INDEX on seed (_jsonb);
        ;
    rsg_test.go:579: 
    rsg_test.go:580: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestRandomSyntaxSQLSmith052073609
--- FAIL: TestRandomSyntaxSQLSmith (300.50s)

Reproduce

To reproduce, try:

make stressrace TESTS=TestRandomSyntaxSQLSmith PKG=./pkg/sql/tests TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Same failure on other branches

• sql/tests: TestRandomSyntaxSQLSmith failed #64592 sql/tests: TestRandomSyntaxSQLSmith failed [C-test-failure O-robot branch-release-21.1]

Internal log

mjibson marked as alumn{us/a}; resolving to rafiss instead

/cc @cockroachdb/sql-queries @rafiss

This test on roachdash | Improve this report!

Jira issue: CRDB-7250

[rytaft]

I ran the above query in cockroach demo and it returned successfully after 73 seconds. Although it didn't time out, this seems unacceptably long. This is pretty much all planning time, since running EXPLAIN took just as long. I was planning to look into avoiding out-of-control exploration this milestone anyway, so I'll take this one.

Here's the explain output:

                                                         info
-----------------------------------------------------------------------------------------------------------------------
  distribution: local
  vectorized: true

  • render
  │
  └── • cross join
      │
      ├── • values
      │     size: 0 columns, 2 rows
      │
      └── • render
          │
          └── • hash join
              │ equality: (col1_2, col1_7, col1_9) = (tableoid, col1_1, col1_2)
              │
              ├── • scan
              │     estimated row count: 1 (100% of the table; stats collected 7797 days ago)
              │     table: table1@primary
              │     spans: FULL SCAN
              │
              └── • lookup join
                  │ table: seed@seed__int8__float8__date_idx
                  │ equality: (_int8, col1_5, _date) = (_int8,_float8,_date)
                  │
                  └── • hash join
                      │ equality: (_float8) = (_float8)
                      │
                      ├── • scan
                      │     missing stats
                      │     table: seed@seed__int8__float8__date_idx
                      │     spans: FULL SCAN
                      │
                      └── • lookup join
                          │ table: seed@seed__int8__float8__date_idx
                          │ equality: (_int8, col1_5, _date) = (_int8,_float8,_date)
                          │
                          └── • hash join
                              │ equality: (_float8) = (col1_5)
                              │
                              ├── • scan
                              │     missing stats
                              │     table: seed@seed__int8__float8__date_idx
                              │     spans: FULL SCAN
                              │
                              └── • hash join
                                  │ equality: (_float4, tableoid, _bool) = (col1_5, col1_9, col1_7)
                                  │
                                  ├── • scan
                                  │     missing stats
                                  │     table: seed@primary
                                  │     spans: FULL SCAN
                                  │
                                  └── • hash join
                                      │ estimated row count: 1
                                      │ equality: (col1_7) = (col1_1)
                                      │
                                      ├── • scan
                                      │     estimated row count: 1 (100% of the table; stats collected 7797 days ago)
                                      │     table: table1@primary
                                      │     spans: FULL SCAN
                                      │
                                      └── • scan
                                            estimated row count: 1 (100% of the table; stats collected 7797 days ago)
                                            table: table1@primary
                                            spans: FULL SCAN
(65 rows)

Time: 73.718s total (execution 73.716s / network 0.001s)

[mgartner]

One of the errors above appears unrelated to the original timeout: internal error: ordering column group (86,107) contains non-equivalent columns (op sort). I've created #65038 to track separately.

[mgartner]

Another error above appears unrelated to the original: internal error: unsupported comparison: inet to timestamptz. I've created #65040 to track separately.

[mgartner]

#65547 only fixed a specific case when a query had a LIMIT 1, so this might be different. I'll see if it's still reproducible.

[mgartner]

It looks like #65547 did fix the last failure. So the only remaining issues above are the timeouts.

[yuzefovich]

The last one is tracked in #65763.

[jordanlewis]

I assigned @yuzefovich because I figured Radu was just assigned at random, but if that was on purpose sorry and please ignore!

[yuzefovich]

Based on this comment Radu was assigned to look into some stuff, but the latest several occurrences are because of minor omission in the case operator refactor (which I'll address shortly), so I'm assigning back to Radu.

[rytaft]

@RaduBerinde I'm guessing the limiting of excessive exploration won't make it into 21.2? Should we move this issue to the backlog / low likelihood bucket?

[RaduBerinde]

Yeah, moved it to backlog.

[yuzefovich]

I randomly stumbled across this issue. @rytaft do you think we should close this given that we now have some cancellation checks in the optimizer? Also, the original repro now is instant, and I looked over all repros, and none of them took long to plan.

[rytaft]

Sounds good to me! There is more work we can do to avoid excessive exploration in the optimizer (to avoid canceling the query altogether and still allow a slightly suboptimal plan to run), but I don't think we need to keep this issue open to track it, since the original repro is fast now. We are tracking the work to avoid excessive exploration in Jira Epic CRDB-10032.