cockroach icon indicating copy to clipboard operation
cockroach copied to clipboard
verified publisher icon cockroachdb

pkg/ccl/testccl/sqlccl/sqlccl_test: TestExplainRedactDDL failed

Open cockroach-teamcity opened this issue 1 year ago • 1 comments

pkg/ccl/testccl/sqlccl/sqlccl_test.TestExplainRedactDDL failed with artifacts on release-24.2 @ aeeae592c24abc9ec7010fbc8c5b0de1257a4c64:

Fatal error:

panic: test timed out after 4m57s
running tests:
	TestExplainRedactDDL (4m57s)
	TestExplainRedactDDL/ExplainAnalyze (4m55s)
	TestExplainRedactDDL/ExplainAnalyze/Plan (2m51s)
	TestExplainRedactDDL/ExplainAnalyze/Plan/Types (31s)

Stack:

goroutine 38482 [running]:
testing.(*M).startAlarm.func1()
	GOROOT/src/testing/testing.go:2366 +0x30c
created by time.goFunc
	GOROOT/src/time/sleep.go:177 +0x38
Log preceding fatal error 

        						((-18778):::INT8, '':::VOID, B'00101010101000010'),
        						(10251:::INT8, NULL, B'11110100101001001')
        				)
        					AS tab_9 (col_12, col_13, col_14)
        		)
        SELECT
        	cte_ref_1.col_12 AS col_15,
        	tab_10.col1_0 AS col_16,
        	B'00011010100010100' AS col_17,
        	cte_ref_1.col_13 AS col_18,
        	tab_10.tableoid AS col_19,
        	tab_10.crdb_internal_mvcc_timestamp AS col_20
        FROM
        	with_3 AS cte_ref_1, defaultdb.public."t/able_1"@[0] AS tab_10
        WHERE
        	true
        ORDER BY
        	tab_10.tableoid ASC NULLS FIRST, cte_ref_1.col_12 DESC NULLS FIRST
        
    explain_test_util.go:132: encountered non-internal error: pq: query execution canceled due to statement timeout
        EXPLAIN ANALYZE (PLAN, TYPES, REDACT) WITH
        	with_5 (col_24) AS (SELECT * FROM (VALUES ('':::VOID), ('':::VOID), ('':::VOID)) AS tab_13 (col_24)),
        	with_6 (col_25)
        		AS (
        			SELECT
        				*
        			FROM
        				(
        					VALUES
        						(
        							(uuid_generate_v1()::UUID::UUID || st_ashexewkb('0101000060E61000008AFC8BE73D9F60C030F7DB78B99C52402276F072F6A1E541':::GEOGRAPHY::GEOGRAPHY, e'pachycephalosaurus@|"$"\nTM':::STRING::STRING)::STRING::STRING)::STRING COLLATE da_DK
        						),
        						(e'\U000EE2B6\U0007D9D2' COLLATE da_DK),
        						(NULL)
        				)
        					AS tab_14 (col_25)
        		)
        SELECT
        	stddev(tab_15.crdb_internal_mvcc_timestamp::DECIMAL)::DECIMAL AS col_26,
        	st_union(tab_15.col1_0::GEOMETRY)::GEOMETRY AS col_27
        FROM
        	defaultdb.public."t/able_1" AS tab_15
        GROUP BY
        	tab_15.crdb_internal_mvcc_timestamp, tab_15.col1_0
        HAVING
        	every(true::BOOL)::BOOL
        
    explain_test_util.go:132: encountered non-internal error: pq: query execution canceled due to statement timeout
        EXPLAIN ANALYZE (PLAN, TYPES, REDACT) UPDATE defaultdb.public."t/able_1" AS tab_16 SET col1_0 = tab_16.col1_0 ORDER BY tab_16.tableoid DESC LIMIT 78:::INT8
Help

See also: How To Investigate a Go Test Failure (internal)

This test on roachdash | Improve this report!

Jira issue: CRDB-41720

cockroach-teamcity avatar Aug 28 '24 15:08 cockroach-teamcity 

W240828 15:11:49.781513 2874 kv/kvclient/kvcoord/txn_interceptor_pipeliner.go:731 ⋮ [T10,Vtest-tenant,n1,client=127.0.0.1:52968,hostssl,user=root] 622  a transaction has hit the intent tracking limit (kv.transaction.max_intents_bytes); is it a bulk operation? Intent cleanup will be slower. txn: "sql txn" meta={id=66bd5d37 key=/Tenant/10/Table/104/1/‹998727709601103873›/‹0› iso=Serializable pri=0.04176088 epo=0 ts=1724857907.748275295,0 min=1724857907.748275295,0 seq=50000} lock=true stat=PENDING rts=1724857907.748275295,0 wto=false gul=1724857908.248275295,0 ba: ‹10000 CPut›

and after that, the logs are filled with:

W240828 15:12:02.977984 5167 kv/kvclient/kvcoord/dist_sender.go:2756 ⋮ [T1,Vsystem,n1,s1] 623  slow replica RPC: have been waiting 10.01s (0 attempts) for RPC ResolveIntent [/Tenant/10/Table/104/1/‹998727720985952257›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720985985025›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720986017793›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720986050561›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720986083329›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720986116097›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720986148865›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720986181633›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720986214401›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720986247169›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720986279937›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720986312705›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720986345473›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720986378241›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720986411009›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720986443777›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720986476545›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720986509313›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720986542081›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720986574849›/‹0›],... 75 skipped ..., ResolveIntent [/Tenant/10/Table/104/1/‹998727720989065217›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720989097985›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720989130753›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720989163521›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720989196289›/‹0›], [max_span_request_keys: 0], [target_bytes: 4194304] to replica (n1,s1):1; resp: ‹(err: <nil>), *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, ... 75 skipped ..., *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse›
W240828 15:12:02.995788 5173 kv/kvclient/kvcoord/dist_sender.go:2756 ⋮ [T1,Vsystem,n1,s1] 624  slow replica RPC: have been waiting 10.03s (0 attempts) for RPC ResolveIntent [/Tenant/10/Table/104/1/‹998727721005613057›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721005645825›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721005678593›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721005711361›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721005744129›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721005776897›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721005809665›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721005842433›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721005875201›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721005907969›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721005940737›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721005973505›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721006006273›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721006039041›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721006071809›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721006104577›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721006137345›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721006170113›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721006202881›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721006235649›/‹0›],... 75 skipped ..., ResolveIntent [/Tenant/10/Table/104/1/‹998727721008726017›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721008758785›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721008791553›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721008824321›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721008857089›/‹0›], [max_span_request_keys: 0], [target_bytes: 4194304] to replica (n1,s1):1; resp: ‹(err: <nil>), *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, ... 75 skipped ..., *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse›
W240828 15:12:03.013911 5157 kv/kvclient/kvcoord/dist_sender.go:2756 ⋮ [T1,Vsystem,n1,s1] 625  slow replica RPC: have been waiting 10.04s (0 attempts) for RPC ResolveIntent [/Tenant/10/Table/104/1/‹998727719933378561›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719933411329›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719933444097›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719933476865›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719933509633›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719933542401›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719933575169›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719933607937›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719933640705›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719933673473›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719933706241›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719933739009›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719933771777›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719933804545›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719933837313›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719933870081›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719933902849›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719933935617›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719933968385›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719934001153›/‹0›],... 75 skipped ..., ResolveIntent [/Tenant/10/Table/104/1/‹998727719936491521›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719936524289›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719936557057›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719936589825›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719936622593›/‹0›], [max_span_request_keys: 0], [target_bytes: 4194304] to replica (n1,s1):1; resp: ‹(err: <nil>), *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, ... 75 skipped ..., *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse›
W240828 15:12:03.031778 5171 kv/kvclient/kvcoord/dist_sender.go:2756 ⋮ [T1,Vsystem,n1,s1] 626  slow replica RPC: have been waiting 10.06s (0 attempts) for RPC ResolveIntent [/Tenant/10/Table/104/1/‹998727720999059457›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720999092225›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720999124993›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720999157761›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720999190529›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720999223297›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720999256065›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720999288833›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720999321601›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720999354369›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720999387137›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720999419905›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720999452673›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720999485441›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720999518209›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720999550977›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720999583745›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720999616513›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720999649281›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727720999682049›/‹0›],... 75 skipped ..., ResolveIntent [/Tenant/10/Table/104/1/‹998727721002172417›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721002205185›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721002237953›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721002270721›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727721002303489›/‹0›], [max_span_request_keys: 0], [target_bytes: 4194304] to replica (n1,s1):1; resp: ‹(err: <nil>), *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, ... 75 skipped ..., *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse›
W240828 15:12:03.049575 5164 kv/kvclient/kvcoord/dist_sender.go:2756 ⋮ [T1,Vsystem,n1,s1] 627  slow replica RPC: have been waiting 10.08s (0 attempts) for RPC ResolveIntent [/Tenant/10/Table/104/1/‹998727719956316161›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719956348929›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719956381697›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719956414465›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719956447233›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719956480001›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719956512769›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719956545537›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719956578305›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719956611073›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719956643841›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719956676609›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719956709377›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719956742145›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719956774913›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719956807681›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719956840449›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719956873217›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719956905985›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719956938753›/‹0›],... 75 skipped ..., ResolveIntent [/Tenant/10/Table/104/1/‹998727719959429121›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719959461889›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719959494657›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719959527425›/‹0›], ResolveIntent [/Tenant/10/Table/104/1/‹998727719959560193›/‹0›], [max_span_request_keys: 0], [target_bytes: 4194304] to replica (n1,s1):1; resp: ‹(err: <nil>), *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, ... 75 skipped ..., *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse, *kvpb.ResolveIntentResponse›

DrewKimball avatar Aug 28 '24 23:08 DrewKimball

This has only failed once (I don't see any links to duplicate failures). I'm going to close and if it starts to reproduce more often then we can address it.

mgartner avatar Oct 31 '24 15:10 mgartner