pkg/ccl/testccl/workload/schemachange/schemachange_test: TestWorkload failed #92043

cockroach-teamcity · 2022-11-17T07:36:52Z

pkg/ccl/testccl/workload/schemachange/schemachange_test.TestWorkload failed with artifacts on master @ ea7c52e5a930be203318db6e338edd5dde7537bd:

Fatal error:

panic: test timed out after 14m55s

Stack:

goroutine 80311294 [running]:
testing.(*M).startAlarm.func1()
	GOROOT/src/testing/testing.go:2036 +0x8e
created by time.goFunc
	GOROOT/src/time/sleep.go:176 +0x32

Log preceding fatal error

I221117 07:36:13.109321 1010786 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40760,user=testuser] 74466 ={"Timestamp":1668670567304195816,"EventType":"query_execute","Statement":"WITH tab_json AS (SELECT crdb_internal.pb_to_json('desc', descriptor)->'table' AS t FROM \"\".system.descriptor WHERE id = $1::REGCLASS), columns_json AS (SELECT json_array_elements(t->'columns') AS c FROM \"\".\"\".tab_json), columns AS (SELECT c->>'computeExpr' AS generation_expression, c->>'name' AS column_name FROM \"\".\"\".columns_json) SELECT show_columns.column_name, show_columns.data_type, show_columns.is_nullable, columns.generation_expression IS NOT NULL AS is_generated, COALESCE(columns.generation_expression, '') AS generated_expression FROM [SHOW COLUMNS FROM public.table2785] AS show_columns, \"\".\"\".columns WHERE (show_columns.column_name != 'rowid') AND (show_columns.column_name = columns.column_name)","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","PlaceholderValues":["table2785"],"ExecMode":"exec","NumRows":6,"Age":139.59473,"FullTableScan":true,"TxnCounter":1120}
I221117 07:36:13.119598 1164142 workload/pgx_helpers.go:79  [-] 74467  pgx logger [error]: Query logParams=map[args:[] err:ERROR: relation "public.table2803" does not exist (SQLSTATE 42P01) pid:1764024 sql:SELECT t1.col2048_2052 AS col0,t2.col2785_2789 AS col1,t2.col2785_2789 AS col2,t2.col2785_2791 AS col3,t2.col2785_2788 AS col4,t2.col2785_2790 AS col5,t1.col2048_2055 AS col6,t1.col2048_2052 AS col7,t1.col2048_2049 AS col8,t2.col2785_2790 AS col9,t1.col2048_2053 AS col10,t1.col2048_2056 AS col11,t2.col2785_2788 AS col12,t2.col2785_2788 AS col13 FROM public.table2803 AS t0 ,schema1791.table2048 AS t1 ,public.table2785 AS t2  FETCH FIRST 1 ROWS ONLY]
{
 "workerId": 1,
 "clientTimestamp": "07:36:07.307204",
 "ops": [
  "BEGIN",
  {
   "sql": "SELECT t2.col2470_2472 AS col0,t0.col2494_2509 AS col1,t2.col2470_2482 AS col2,t0.col2470_2475 AS col3,t2.col2470_2475 AS col4,t2.col2470_2479 AS col5,t0.col2470_2476 AS col6,t2.col2470_2473 AS col7,t1.col2606_2616 AS col8,t0.col2396_2401 AS col9,t2.col2470_2479 AS col10,t0.col2494_2506 AS col11 FROM schema1126.table2557 AS t0 ,schema2517.table2606 AS t1 ,schema1791.table2470 AS t2  FETCH FIRST 1 ROWS ONLY",
   "potentialExecErr": "53100,53200"
  },
  {
   "sql": "CREATE SEQUENCE IF NOT EXISTS schema1126.seq2799"
  },
  {
   "sql": "DROP TABLE IF EXISTS schema2800.table2801"
  },
  {
   "sql": "SELECT t0.col2494_2495 AS col0,t0.col2396_2401 AS col1,t0.col2396_2397 AS col2,t0.col2396_2397 AS col3,t0.col2494_2508 AS col4,t0.col2470_2477 AS col5,t0.col2396_2401 AS col6,t0.col2348_2351 AS col7,t0.col2396_2399 AS col8,t0.col2494_2506 AS col9,t0.col2494_2497 AS col10 FROM schema2517.table2765 AS t0  FETCH FIRST 1 ROWS ONLY",
   "potentialExecErr": "53100,53200"
  },
  {
   "sql": "SELECT t1.col2048_2052 AS col0,t2.col2785_2789 AS col1,t2.col2785_2789 AS col2,t2.col2785_2791 AS col3,t2.col2785_2788 AS col4,t2.col2785_2790 AS col5,t1.col2048_2055 AS col6,t1.col2048_2052 AS col7,t1.col2048_2049 AS col8,t2.col2785_2790 AS col9,t1.col2048_2053 AS col10,t1.col2048_2056 AS col11,t2.col2785_2788 AS col12,t2.col2785_2788 AS col13 FROM public.table2803 AS t0 ,schema1791.table2048 AS t1 ,public.table2785 AS t2  FETCH FIRST 1 ROWS ONLY",
   "expectedExecErr": "42P01",
   "potentialExecErr": "53100,53200"
  }
 ],
 "expectedExecErrors": "42P01",
 "expectedCommitErrors": "",
 "message": "ROLLBACK; Successfully got expected execution error.: ERROR: relation \"public.table2803\" does not exist (SQLSTATE 42P01)"
}
I221117 07:36:13.136569 80294352 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 74468 ={"Timestamp":1668670573111252366,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-17 07:00:00'","'\\xc50c4a507d16949c'","'\\xf5917d8cff1b7f58'","'\\xf9b1d7aa099ac256'","'schemachange'","1","'01:00:00'","'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": false, \"implicitTxn\": false, \"query\": \"SELECT EXISTS (SELECT sequence_name FROM information_schema.sequences WHERE (sequence_schema = $1) AND (sequence_name = $1))\", \"querySummary\": \"SELECT EXISTS (SELECT ...)\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"firstAttemptCnt\": 1, \"idleLat\": {\"mean\": 0.88614526, \"sqDiff\": 0}, \"lastExecAt\": \"2022-11-17T07:21:36.744315356Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 1, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.000008676999999999904, \"sqDiff\": 0}, \"parseLat\": {\"mean\": 0, \"sqDiff\": 0}, \"planGists\": [\"AgH2/f//nxoAAAwAAAADFwICAgYC\"], \"planLat\": {\"mean\": 0.000366264, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.001827902, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.002202843, \"sqDiff\": 0}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":25.056383}
I221117 07:36:13.153693 1010786 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40760,user=testuser] 74469 ={"Timestamp":1668670573142777199,"EventType":"query_execute","Statement":"SELECT session_id FROM [SHOW session_id]","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","ExecMode":"exec","NumRows":1,"Age":9.943495,"TxnCounter":1121}
I221117 07:36:13.172702 80297934 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 74470 ={"Timestamp":1668670573153856848,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-17 07:00:00'","'\\x8f177fab1f8bfeaa'","'\\xcecd6b02efe5382d'","'\\x4f428bf7eb4ebed8'","'schemachange'","1","'01:00:00'","'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": false, \"implicitTxn\": false, \"query\": \"SELECT EXISTS (SELECT schema_name FROM information_schema.schemata WHERE schema_name = $1)\", \"querySummary\": \"SELECT EXISTS (SELECT ...)\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"firstAttemptCnt\": 1, \"idleLat\": {\"mean\": 1.600154426, \"sqDiff\": 0}, \"lastExecAt\": \"2022-11-17T07:29:28.451220728Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 1, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.000008512999999999923, \"sqDiff\": 0}, \"parseLat\": {\"mean\": 0, \"sqDiff\": 0}, \"planGists\": [\"AgH6/f//nxoAAAQAAAADFwICAgYC\"], \"planLat\": {\"mean\": 0.000395172, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.008027983, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.008431668, \"sqDiff\": 0}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":18.518314}
I221117 07:36:13.188679 1004126 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40752,user=testuser] 74471 ={"Timestamp":1668670572818079329,"EventType":"query_execute","Statement":"SELECT * FROM _.crdb_internal.invalid_objects ORDER BY id","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","ExecMode":"exec","Age":365.54752,"TxnCounter":866}
I221117 07:36:13.194188 1004126 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40752,user=testuser] 74472 ={"Timestamp":1668670572818079329,"EventType":"query_execute","Statement":"SELECT 'validating all objects', crdb_internal.validate_multi_region_zone_configs()","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","ExecMode":"exec","NumRows":1,"Age":2.083525,"TxnCounter":866}
I221117 07:36:13.230040 80301311 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 74473 ={"Timestamp":1668670573186529158,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-17 07:00:00'","'\\x79c9b6fe1e67152d'","'\\x3d646e183c1da8db'","'\\xd51f6ad99fe0af47'","'schemachange'","1","'01:00:00'","'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": false, \"implicitTxn\": false, \"query\": \"SELECT session_id FROM [SHOW session_id]\", \"querySummary\": \"SELECT session_id FROM [SHOW session_id]\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"firstAttemptCnt\": 1, \"idleLat\": {\"mean\": 0.001924174, \"sqDiff\": 0}, \"lastExecAt\": \"2022-11-17T07:30:29.809904931Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 1, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.000005360999999999951, \"sqDiff\": 0}, \"parseLat\": {\"mean\": 0, \"sqDiff\": 0}, \"planGists\": [\"AisHAgYC\"], \"planLat\": {\"mean\": 0.000169552, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.000455241, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.000630154, \"sqDiff\": 0}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":17.555592}
I221117 07:36:13.232040 1004126 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40752,user=testuser] 74474 ={"Timestamp":1668670572818079329,"EventType":"query_execute","Statement":"SELECT schema_name FROM information_schema.schemata WHERE (schema_name LIKE 'schema%') OR (schema_name = 'public') ORDER BY random() LIMIT 1","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","ExecMode":"exec","NumRows":1,"Age":35.492702,"TxnCounter":866}
I221117 07:36:13.243506 1010786 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40760,user=testuser] 74475 ={"Timestamp":1668670573142777199,"EventType":"query_execute","Statement":"SELECT sequence_schema, sequence_name FROM [SHOW SEQUENCES] WHERE sequence_name LIKE 'seq%%' ORDER BY random() LIMIT 1","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","ExecMode":"exec","NumRows":1,"Age":70.59498,"TxnCounter":1121}
I221117 07:36:13.251559 1010786 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40760,user=testuser] 74476 ={"Timestamp":1668670573142777199,"EventType":"query_execute","Statement":"SELECT EXISTS (SELECT sequence_name FROM information_schema.sequences WHERE (sequence_schema = $1) AND (sequence_name = $2))","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","PlaceholderValues":["'schema1724'","'seq2771'"],"ExecMode":"exec","NumRows":1,"Age":6.498352,"TxnCounter":1121}
I221117 07:36:13.260244 1004126 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40752,user=testuser] 74477 ={"Timestamp":1668670572818079329,"EventType":"query_execute","Statement":"SELECT EXISTS (SELECT * FROM [SHOW REGIONS FROM DATABASE])","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","ExecMode":"exec","NumRows":1,"Age":17.585648,"TxnCounter":866}
I221117 07:36:13.262137 80304514 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 74478 ={"Timestamp":1668670573244590620,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-17 07:00:00'","'\\xad65867376abcb04'","'\\x770f18a80523cf1d'","'\\x76ab846aae692c5b'","'schemachange'","1","'01:00:00'","'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": false, \"implicitTxn\": false, \"query\": \"SELECT EXISTS (SELECT * FROM [SHOW REGIONS FROM DATABASE])\", \"querySummary\": \"SELECT EXISTS (SELECT ...)\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"firstAttemptCnt\": 1, \"idleLat\": {\"mean\": 0.761891642, \"sqDiff\": 0}, \"lastExecAt\": \"2022-11-17T07:29:33.943584482Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 1, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.000013217000000002865, \"sqDiff\": 0}, \"parseLat\": {\"mean\": 0, \"sqDiff\": 0}, \"planGists\": [\"AgH4/v//nxoAAAYAAAAHBAHU////nxoAAHQAAAADGgIXBwgJAgICAAEXAgICBgI=\"], \"planLat\": {\"mean\": 0.001308233, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.035888388, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.037209838, \"sqDiff\": 0}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":17.177431}
I221117 07:36:13.271156 80306750 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40752,user=testuser,intExec=read-setting] 74479 ={"Timestamp":1668670573262725820,"EventType":"query_execute","Statement":"SELECT value FROM \"\".system.settings WHERE name = $1","Tag":"SELECT","User":"root","ApplicationName":"$ internal-read-setting","PlaceholderValues":["'version'"],"ExecMode":"exec-internal","NumRows":1,"Age":8.27421}
I221117 07:36:13.272388 1004126 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40752,user=testuser] 74480 ={"Timestamp":1668670572818079329,"EventType":"query_execute","Statement":"SHOW CLUSTER SETTING version","Tag":"SHOW","User":"testuser","ApplicationName":"schemachange","ExecMode":"exec","NumRows":1,"Age":10.521956,"TxnCounter":866}
I221117 07:36:13.279380 1010786 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40760,user=testuser] 74481 ={"Timestamp":1668670573142777199,"EventType":"query_execute","Statement":"SELECT EXISTS (SELECT schema_name FROM information_schema.schemata WHERE schema_name = $1)","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","PlaceholderValues":["'schema1724'"],"ExecMode":"exec","NumRows":1,"Age":26.702528,"TxnCounter":1121}
I221117 07:36:13.280015 80307922 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40752,user=testuser,intExec=read-setting] 74482 ={"Timestamp":1668670573275634486,"EventType":"query_execute","Statement":"SELECT value FROM \"\".system.settings WHERE name = $1","Tag":"SELECT","User":"root","ApplicationName":"$ internal-read-setting","PlaceholderValues":["'version'"],"ExecMode":"exec-internal","NumRows":1,"Age":4.227276}
I221117 07:36:13.283359 1004126 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40752,user=testuser] 74483 ={"Timestamp":1668670572818079329,"EventType":"query_execute","Statement":"SHOW CLUSTER SETTING version","Tag":"SHOW","User":"testuser","ApplicationName":"schemachange","ExecMode":"exec","NumRows":1,"Age":8.392261,"TxnCounter":866}
I221117 07:36:13.283912 1010786 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40760,user=testuser] 74484 ={"Timestamp":1668670573142777199,"EventType":"query_execute","Statement":"SELECT EXISTS (SELECT sequence_name FROM information_schema.sequences WHERE (sequence_schema = $1) AND (sequence_name = $2))","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","PlaceholderValues":["'schema1724'","'seq2807'"],"ExecMode":"exec","NumRows":1,"Age":3.515441,"TxnCounter":1121}
I221117 07:36:13.296365 1010786 sql/table.go:184  [n1,client=127.0.0.1:40760,user=testuser] 74485  queued new schema-change job 814613047857381377 for table 736, mutation 0
I221117 07:36:13.303380 1010786 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40760,user=testuser] 74486 ={"Timestamp":1668670573142777199,"EventType":"query_execute","Statement":"ALTER SEQUENCE schema1724.seq2771 RENAME TO schema1724.seq2807","Tag":"ALTER SEQUENCE","User":"testuser","ApplicationName":"schemachange","ExecMode":"exec","Age":10.580098,"TxnCounter":1121}

Parameters: TAGS=bazel,gss,deadlock

Help

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

/cc @cockroachdb/sql-schema _{This test on roachdash | Improve this report!

Jira issue: CRDB-21537}

The text was updated successfully, but these errors were encountered:

cockroach-teamcity · 2022-11-18T06:53:35Z

pkg/ccl/testccl/workload/schemachange/schemachange_test.TestWorkload failed with artifacts on master @ a035d2e6e7ea57b30115ecc8ee1a5d553a9e3412:

Fatal error:

panic: test timed out after 14m55s

Stack:

goroutine 70617788 [running]:
testing.(*M).startAlarm.func1()
	GOROOT/src/testing/testing.go:2036 +0x8e
created by time.goFunc
	GOROOT/src/time/sleep.go:176 +0x32

Log preceding fatal error

W221118 06:52:50.417508 33647 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 89077  failed to flush transaction statistics: flushing transaction 2230654635992180126's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221118 06:52:50.423974 70607102 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89078 ={"Timestamp":1668754370419161248,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":5.242686,"TxnCounter":1}
I221118 06:52:50.431757 70607448 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89079 ={"Timestamp":1668754370425563033,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":6.509448,"TxnCounter":1}
I221118 06:52:50.442889 70607057 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 89080 ={"Timestamp":1668754370417668004,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-18 06:00:00'","'\\xdf499f2920c3f04c'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"1fad80169c94c7e7\", \"4e3e2c37fc3f54d5\", \"28cc019f26414da6\", \"28cc019f26414da6\", \"28cc019f26414da6\", \"ec3b2def2cfc1387\", \"cf892ea44c511827\", \"b7a916d460d21220\", \"6e939058cec3245a\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 1.024E+4, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.036393909, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 11, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.746211578, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":24.92726}
W221118 06:52:50.444441 33647 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 89081  failed to flush transaction statistics: flushing transaction 16089566142749995084's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221118 06:52:50.452240 70608101 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89082 ={"Timestamp":1668754370446829012,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":5.808573,"TxnCounter":1}
I221118 06:52:50.460666 70608447 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89083 ={"Timestamp":1668754370455022891,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":6.026779,"TxnCounter":1}
I221118 06:52:50.469547 70608054 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 89084 ={"Timestamp":1668754370444794712,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-18 06:00:00'","'\\x8309b098c97c18f9'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"1fad80169c94c7e7\", \"3c3acd1f6d89ef16\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"b7a916d460d21220\", \"6e939058cec3245a\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"ede05f673c36c454\", \"82720f9ff00ba027\", \"b7a916d460d21220\", \"8f177fab1f8bfeaa\", \"ec6ad1e57d15541b\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 1.024E+4, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.064722857, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 25, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 1.324906988, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":24.336126}
W221118 06:52:50.470615 33647 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 89085  failed to flush transaction statistics: flushing transaction 9442272264020826361's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221118 06:52:50.476813 70609106 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89086 ={"Timestamp":1668754370472164476,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":5.008531,"TxnCounter":1}
I221118 06:52:50.483297 70609455 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89087 ={"Timestamp":1668754370478919861,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.92665,"TxnCounter":1}
I221118 06:52:50.497837 70609059 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 89088 ={"Timestamp":1668754370470776089,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-18 06:00:00'","'\\x79720eedcf82f002'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"b7a916d460d21220\", \"8f177fab1f8bfeaa\", \"15ec88c2554dd3da\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 1.024E+4, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.011834856, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 3, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.102225086, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":26.754383}
W221118 06:52:50.498789 33647 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 89089  failed to flush transaction statistics: flushing transaction 8751073440485797890's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221118 06:52:50.505075 70610110 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89090 ={"Timestamp":1668754370500375575,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":5.074188,"TxnCounter":1}
I221118 06:52:50.511767 70610555 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89091 ={"Timestamp":1668754370507189965,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.847862,"TxnCounter":1}
I221118 06:52:50.521533 70610069 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 89092 ={"Timestamp":1668754370498959572,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-18 06:00:00'","'\\x8d5c728d49c22901'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"b7a916d460d21220\", \"6e939058cec3245a\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"b7a916d460d21220\", \"6e939058cec3245a\", \"a73bb8e9f02bfafe\", \"b7a916d460d21220\", \"8f177fab1f8bfeaa\", \"ec6ad1e57d15541b\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.03069539, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 17, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.42672787, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":22.265726}
W221118 06:52:50.522705 33647 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 89093  failed to flush transaction statistics: flushing transaction 10186142408358635777's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221118 06:52:50.528911 70611213 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89094 ={"Timestamp":1668754370524383206,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.946894,"TxnCounter":1}
I221118 06:52:50.535212 70611559 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89095 ={"Timestamp":1668754370531074734,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.611251,"TxnCounter":1}
I221118 06:52:50.545493 70611166 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 89096 ={"Timestamp":1668754370522873532,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-18 06:00:00'","'\\xcb94b4b57674c0ba'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"b7a916d460d21220\", \"8f177fab1f8bfeaa\", \"c50c4a507d16949c\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"d584e1b1fc29839d\", \"e17d4125eca79e37\", \"4c315e867d5ac032\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 9.728E+5, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.055596735, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 2E+1, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 1.130316838, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":22.31241}
W221118 06:52:50.549776 33647 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 89097  failed to flush transaction statistics: flushing transaction 14669548577721991354's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221118 06:52:50.555775 70612203 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89098 ={"Timestamp":1668754370551346493,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.788179,"TxnCounter":1}
I221118 06:52:50.561778 70612549 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89099 ={"Timestamp":1668754370557558712,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.571757,"TxnCounter":1}
I221118 06:52:50.625409 70612156 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 89100 ={"Timestamp":1668754370549951915,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-18 06:00:00'","'\\xbd6de1c3f0fec905'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"ec3b2def2cfc1387\", \"cf892ea44c511827\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"ec3b2def2cfc1387\", \"cf892ea44c511827\", \"b7a916d460d21220\", \"8f177fab1f8bfeaa\", \"04f85b9bf033ba8a\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"286eae569e8f1f72\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"88c4741dd9ff6481\", \"e6d83150b391e176\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 1.49504E+6, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 290112, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.020993276, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 3E+1, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 3.3E+2, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 1.185196086, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":75.09905}
W221118 06:52:50.626592 33647 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 89101  failed to flush transaction statistics: flushing transaction 13649814277307943173's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221118 06:52:50.633011 70613298 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89102 ={"Timestamp":1668754370628239084,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":5.124671,"TxnCounter":1}
I221118 06:52:50.641300 70613663 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89103 ={"Timestamp":1668754370635887885,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":5.759433,"TxnCounter":1}
I221118 06:52:50.655378 70613251 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 89104 ={"Timestamp":1668754370626769103,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-18 06:00:00'","'\\x5a47344ed7e67b14'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"ef6b804479f1af4d\", \"6c41694da40fcb9d\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 2.048E+4, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 2, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 138348, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.000190228, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 12, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 1.7E+2, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.528633383, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":28.255348}
W221118 06:52:50.656750 33647 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 89105  failed to flush transaction statistics: flushing transaction 6505225699994270484's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221118 06:52:50.663080 70614326 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89106 ={"Timestamp":1668754370658797272,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.664956,"TxnCounter":1}
I221118 06:52:50.669834 70614672 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89107 ={"Timestamp":1668754370665339226,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.766806,"TxnCounter":1}
I221118 06:52:50.679003 70614276 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 89108 ={"Timestamp":1668754370657142249,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-18 06:00:00'","'\\x68fc0c17789b55a5'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"0baf12855ff43fd9\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"0baf12855ff43fd9\", \"824e5dce60371339\", \"3f019e1c2ddbb9aa\", \"ec3b2def2cfc1387\", \"cf892ea44c511827\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"b7a916d460d21220\", \"6e939058cec3245a\"]}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 2.3575E+5, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.001229287, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 26, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 352, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 2.046545556, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":21.479998}
W221118 06:52:50.679978 33647 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 89109  failed to flush transaction statistics: flushing transaction 7564934769022817701's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221118 06:52:50.687964 70615337 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89110 ={"Timestamp":1668754370683434780,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.975114,"TxnCounter":1}
I221118 06:52:50.695583 70615679 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89111 ={"Timestamp":1668754370690228002,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":6.060518,"TxnCounter":1}
I221118 06:52:50.709949 70615280 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 89112 ={"Timestamp":1668754370680158864,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-18 06:00:00'","'\\x970e87ef3910a49f'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"a918b4f1417f679f\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"a73bb8e9f02bfafe\", \"b7a916d460d21220\", \"8f177fab1f8bfeaa\", \"ec6ad1e57d15541b\", \"0e0f32fcf2bf4ea0\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"286eae569e8f1f72\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"a92755fa48d4d979\", \"f45c4054fdd33ab8\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 4.096E+4, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 2, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 270914, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.049019755, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 28, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 292, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 1.9998967460000001, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":27.827984}
W221118 06:52:50.711397 33647 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 89113  failed to flush transaction statistics: flushing transaction 10884786810925393055's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221118 06:52:50.717909 70616420 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89114 ={"Timestamp":1668754370713349445,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":5.038101,"TxnCounter":1}
I221118 06:52:50.724614 70616771 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89115 ={"Timestamp":1668754370719994091,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.887518,"TxnCounter":1}
I221118 06:52:50.742700 70616381 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 89116 ={"Timestamp":1668754370711659442,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-18 06:00:00'","'\\x6b9838113013c52d'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"54dfeb3284559b10\", \"01aac5d2f309cd59\", \"ec3b2def2cfc1387\", \"cf892ea44c511827\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 2.048E+4, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 2, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 73591, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.000180614, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 8, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 97, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 1.898819341, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":30.658104}
W221118 06:52:50.743588 33647 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 89117  failed to flush transaction statistics: flushing transaction 7753008404990510381's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221118 06:52:50.749966 70617437 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89118 ={"Timestamp":1668754370745277974,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":5.132234,"TxnCounter":1}
I221118 06:52:50.760023 70617783 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89119 ={"Timestamp":1668754370755377464,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":5.495499,"TxnCounter":1}
I221118 06:52:50.769308 70617393 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 89120 ={"Timestamp":1668754370743773723,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-18 06:00:00'","'\\x3c7b76ff7d37f70e'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"ec3b2def2cfc1387\", \"cf892ea44c511827\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"d6c94f0929cf62de\", \"66d43afd9c888410\", \"b7a916d460d21220\", \"8f177fab1f8bfeaa\", \"ec6ad1e57d15541b\", \"eaa1cc8383f4e3d8\", \"3f019e1c2ddbb9aa\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"1a7c1fb2f8e95ebf\", \"b2c364d50d65bd3a\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 2.048E+4, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 2, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 97904, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.032202179, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 24, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 1.2E+2, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.920392848, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":25.189508}
W221118 06:52:50.776281 33647 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 89121  failed to flush transaction statistics: flushing transaction 4358207904100644622's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221118 06:52:50.785142 70618433 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89122 ={"Timestamp":1668754370780410517,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":6.903841,"TxnCounter":1}
I221118 06:52:50.791994 70618779 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89123 ={"Timestamp":1668754370787081613,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":5.162101,"TxnCounter":1}
I221118 06:52:50.802469 70618386 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 89124 ={"Timestamp":1668754370776623167,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-18 06:00:00'","'\\x739e816a628f6eae'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"b7a916d460d21220\", \"8f177fab1f8bfeaa\", \"c50c4a507d16949c\", \"25b1c3470663f2ff\", \"b7a916d460d21220\", \"8f177fab1f8bfeaa\", \"2fe3de3e7609ec3d\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 1.024E+4, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 1.317E+4, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.000181517, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 7, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 58, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.197021869, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":25.460382}
W221118 06:52:50.804251 33647 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 89125  failed to flush transaction statistics: flushing transaction 8331238654602079918's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221118 06:52:50.811684 70619515 9@util/log/event_log.go:32  [intExec=get-table-statistics] 89126 ={"Timestamp":1668754370806942851,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:39297: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":5.116702,"TxnCounter":1}

Parameters: TAGS=bazel,gss,deadlock

Help

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

_{This test on roachdash | Improve this report!}

cockroach-teamcity · 2022-11-19T07:53:29Z

pkg/ccl/testccl/workload/schemachange/schemachange_test.TestWorkload failed with artifacts on master @ 8357abb668a5adaff781343b394b162fb1b66c6e:

Fatal error:

panic: test timed out after 14m55s

Stack:

goroutine 80617775 [running]:
testing.(*M).startAlarm.func1()
	GOROOT/src/testing/testing.go:2036 +0x8e
created by time.goFunc
	GOROOT/src/time/sleep.go:176 +0x32

Log preceding fatal error

I221119 07:52:46.065512 1071152 9@util/log/event_log.go:32  [n1,client=127.0.0.1:47932,user=testuser] 82729 ={"Timestamp":1668844365520546295,"EventType":"query_execute","Statement":"SELECT schema_name, table_name FROM [SHOW TABLES] WHERE table_name ~ 'table[0-9]+' ORDER BY random() LIMIT 1","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","ExecMode":"exec","NumRows":1,"Age":250.66151,"TxnCounter":895}
I221119 07:52:46.073690 80554169 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 82730 ={"Timestamp":1668844366051942683,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-19 07:00:00'","'\\x1fad80169c94c7e7'","'\\xb6a246fdeabdc9c1'","'\\x6f3814978f3ee915'","'schemachange'","1","'01:00:00'","e'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": false, \"implicitTxn\": false, \"query\": \"SELECT EXISTS (SELECT fd.descriptor_name FROM crdb_internal.forward_dependencies AS fd WHERE ((fd.descriptor_id = (SELECT c.oid FROM pg_catalog.pg_class AS c JOIN pg_catalog.pg_namespace AS ns ON ns.oid = c.relnamespace WHERE (c.relname = $1) AND (ns.nspname = $1))) AND (fd.descriptor_id != fd.dependedonby_id)) AND (fd.dependedonby_type != \\'_\\'))\", \"querySummary\": \"SELECT EXISTS (SELECT ...)\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"firstAttemptCnt\": 1, \"idleLat\": {\"mean\": 0.663691834, \"sqDiff\": 0}, \"lastExecAt\": \"2022-11-19T07:40:05.050405177Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 1, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.000009740000000008076, \"sqDiff\": 0}, \"parseLat\": {\"mean\": 0, \"sqDiff\": 0}, \"planGists\": [\"AgHQ////nxoAADYAAAABpv3//58aAAAOAAAAAwHs/P//nxoAAAYAAAADCQACAgAABQIZAxcCAgIGAg==\"], \"planLat\": {\"mean\": 0.003529624, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.08973897, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.093278334, \"sqDiff\": 0}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":21.433655}
I221119 07:52:46.080203 1071117 9@util/log/event_log.go:32  [n1,client=127.0.0.1:47936,user=testuser] 82731 ={"Timestamp":1668844365316216898,"EventType":"query_execute","Statement":"WITH tab_json AS (SELECT crdb_internal.pb_to_json('desc', descriptor)->'table' AS t FROM \"\".system.descriptor WHERE id = $1::REGCLASS), columns_json AS (SELECT json_array_elements(t->'columns') AS c FROM \"\".\"\".tab_json), columns AS (SELECT c->>'computeExpr' AS generation_expression, c->>'name' AS column_name FROM \"\".\"\".columns_json) SELECT show_columns.column_name, show_columns.data_type, show_columns.is_nullable, columns.generation_expression IS NOT NULL AS is_generated, COALESCE(columns.generation_expression, '') AS generated_expression FROM [SHOW COLUMNS FROM schema1474.table2895] AS show_columns, \"\".\"\".columns WHERE (show_columns.column_name != 'rowid') AND (show_columns.column_name = columns.column_name)","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","PlaceholderValues":["table2895"],"ExecMode":"exec","NumRows":11,"Age":159.95729,"FullTableScan":true,"TxnCounter":1170}
I221119 07:52:46.082730 1071152 9@util/log/event_log.go:32  [n1,client=127.0.0.1:47932,user=testuser] 82732 ={"Timestamp":1668844365520546295,"EventType":"query_execute","Statement":"SELECT EXISTS (SELECT table_name FROM information_schema.tables WHERE (table_schema = $1) AND (table_name = $2))","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","PlaceholderValues":["'schema2344'","'table2540'"],"ExecMode":"exec","NumRows":1,"Age":10.580509,"TxnCounter":895}
I221119 07:52:46.086279 80556910 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 82733 ={"Timestamp":1668844366077484640,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-19 07:00:00'","'\\xf6410bffee5751f4'","'\\xe9bec4996bcb952a'","'\\xd30ebdbc3c6ca889'","'schemachange'","1","'01:00:00'","e'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": true, \"implicitTxn\": false, \"query\": \"WITH tab_json AS (SELECT crdb_internal.pb_to_json(\\'_\\', descriptor)->\\'_\\' AS t FROM system.descriptor WHERE id = $1::REGCLASS), columns_json AS (SELECT json_array_elements(t->\\'_\\') AS c FROM tab_json), columns AS (SELECT c->>\\'_\\' AS generation_expression, c->>\\'_\\' AS column_name FROM columns_json) SELECT show_columns.column_name, show_columns.data_type, show_columns.is_nullable, columns.generation_expression IS NOT NULL AS is_generated, COALESCE(columns.generation_expression, \\'_\\') AS generated_expression FROM [SHOW COLUMNS FROM schema777.table1036] AS show_columns, columns WHERE (show_columns.column_name != \\'_\\') AND (show_columns.column_name = columns.column_name)\", \"querySummary\": \"\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 90309, \"sqDiff\": 0}, \"cnt\": 1, \"firstAttemptCnt\": 1, \"idleLat\": {\"mean\": 0.486230837, \"sqDiff\": 0}, \"lastExecAt\": \"2022-11-19T07:41:07.630423018Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 4, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.000011702000000002322, \"sqDiff\": 0}, \"parseLat\": {\"mean\": 0, \"sqDiff\": 0}, \"planGists\": [\"AgEGAgADAAAAAwcCGgIHAgcEAwHM/v//nxoAAN6DgICAgDQAAAADBQ4NBwYDCQACAgAABwoGCg==\"], \"planLat\": {\"mean\": 0.005230753, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 121, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.114545942, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.119788397, \"sqDiff\": 0}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":8.521076}
I221119 07:52:46.110277 80558801 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 82734 ={"Timestamp":1668844366097801074,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-19 07:00:00'","'\\x28f7c9fd4a42c268'","'\\xcdba988fdfdd7661'","'\\x2f2b5fb2e921f053'","'schemachange'","1","'01:00:00'","'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": true, \"implicitTxn\": false, \"query\": \"CREATE TABLE schema1048.table1216 AS SELECT schema880.table1124.col1124_1129, schema880.table1124.col1124_1125, schema880.table1124.col1124_1134, schema880.table1124.col1124_1128, schema880.table1004.col986_989, schema880.table1004.col843_847, schema880.table1004.col843_851, schema880.table1004.col986_994, schema880.table1004.col843_850 FROM schema880.table1124, schema880.table1004 LIMIT _\", \"querySummary\": \"CREATE TABLE schema1048.table1216 AS SELECT FROM schema880.table1124, schema880.table1004 LIMIT _\", \"stmtTyp\": \"TypeDDL\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 5.12E+4, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"firstAttemptCnt\": 1, \"idleLat\": {\"mean\": 0.000702367, \"sqDiff\": 0}, \"lastExecAt\": \"2022-11-19T07:41:38.594642427Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 0, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.000003574999999998718, \"sqDiff\": 0}, \"parseLat\": {\"mean\": 0.000137595, \"sqDiff\": 0}, \"planGists\": [\"AgHMBQIAmQQAAAABggUCAKcCAAAACQAAAAAAFwcUBhQmnAU=\"], \"planLat\": {\"mean\": 0.001047583, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.019761098, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.020949851, \"sqDiff\": 0}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":12.202817}
I221119 07:52:46.116274 80558474 9@util/log/event_log.go:32  [n1,client=127.0.0.1:47932,user=testuser,intExec=select-comments] 82735 ={"Timestamp":1668844365520546295,"EventType":"query_execute","Statement":"SELECT COALESCE(pc.object_id, sc.object_id) AS object_id, COALESCE(pc.sub_id, sc.sub_id) AS sub_id, COALESCE(pc.comment, sc.comment) AS comment, COALESCE(pc.type, sc.type) AS type FROM (SELECT * FROM \"\".system.comments) AS sc FULL JOIN (SELECT * FROM crdb_internal.predefined_comments) AS pc ON (((pc.object_id = sc.object_id) AND (pc.sub_id = sc.sub_id)) AND (pc.type = sc.type))","Tag":"SELECT","User":"root","ApplicationName":"$ internal-select-comments","ExecMode":"exec-internal","NumRows":281,"Age":22.62094,"FullTableScan":true}
I221119 07:52:46.135240 80561010 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 82736 ={"Timestamp":1668844366115098758,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-19 07:00:00'","'\\x8f177fab1f8bfeaa'","'\\x117f63e728f31847'","'\\x4f428bf7eb4ebed8'","'schemachange'","1","'01:00:00'","'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": false, \"implicitTxn\": false, \"query\": \"SELECT EXISTS (SELECT schema_name FROM information_schema.schemata WHERE schema_name = $1)\", \"querySummary\": \"SELECT EXISTS (SELECT ...)\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"firstAttemptCnt\": 1, \"idleLat\": {\"mean\": 0.332966219, \"sqDiff\": 0}, \"lastExecAt\": \"2022-11-19T07:44:20.59345253Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 1, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.000008554000000000894, \"sqDiff\": 0}, \"parseLat\": {\"mean\": 0, \"sqDiff\": 0}, \"planGists\": [\"AgH6/f//nxoAAAQAAAADFwICAgYC\"], \"planLat\": {\"mean\": 0.000365187, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.019919829, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.02029357, \"sqDiff\": 0}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":19.888845}
I221119 07:52:46.153725 80563920 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 82737 ={"Timestamp":1668844366140113598,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-19 07:00:00'","'\\x34b3ca8721025257'","'\\x102f427af42c2d93'","'\\xa5f89f925067f8c6'","'schemachange'","1","'01:00:00'","e'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": false, \"implicitTxn\": false, \"query\": \"SELECT count(*) > _ FROM crdb_internal.schema_changes WHERE (((type = \\'_\\') AND (table_id = $1::REGCLASS)) AND (target_name = $1)) AND (direction = \\'_\\')\", \"querySummary\": \"SELECT count(*) > _ FROM crdb_internal.schema_changes\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 2, \"firstAttemptCnt\": 2, \"idleLat\": {\"mean\": 0.651899223, \"sqDiff\": 0.01561038764510412}, \"lastExecAt\": \"2022-11-19T07:45:43.479604934Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 1, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.00000891899999999981, \"sqDiff\": 4.90471199999689E-12}, \"parseLat\": {\"mean\": 0, \"sqDiff\": 0}, \"planGists\": [\"AgGY////nxoAANICAAAAAwUADAcCBgI=\"], \"planLat\": {\"mean\": 0.0005245915, \"sqDiff\": 5.5359398644999994E-9}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.0051103965, \"sqDiff\": 0.000017126621400564504}, \"svcLat\": {\"mean\": 0.005643907, \"sqDiff\": 0.000017766653202162}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":13.321704}
I221119 07:52:46.164931 80563409 9@util/log/event_log.go:32  [n1,client=127.0.0.1:47936,user=testuser,intExec=read-roles] 82738 ={"Timestamp":1668844365316216898,"EventType":"query_execute","Statement":"SELECT u.username, \"isRole\", drs.settings, json_object_agg(COALESCE(ro.option, 'null'), ro.value) FROM \"\".system.users AS u LEFT JOIN \"\".system.role_options AS ro ON ro.username = u.username LEFT JOIN \"\".system.database_role_settings AS drs ON (drs.role_name = u.username) AND (drs.database_id = 0) GROUP BY u.username, \"isRole\", drs.settings","Tag":"SELECT","User":"root","ApplicationName":"$ internal-read-roles","ExecMode":"exec-internal","NumRows":3,"Age":27.805536,"FullTableScan":true}
I221119 07:52:46.174426 80566164 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 82739 ={"Timestamp":1668844366160725731,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-19 07:00:00'","'\\x3f019e1c2ddbb9aa'","'\\x92ad329b976d803d'","'\\x5175dfee738e1a06'","'schemachange'","1","'01:00:00'","e'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": false, \"implicitTxn\": false, \"query\": \"SELECT sequence_schema, sequence_name FROM [SHOW SEQUENCES] WHERE sequence_name LIKE \\'_\\' ORDER BY random() LIMIT _\", \"querySummary\": \"SELECT sequence_schema... FROM [SHOW SEQUENCES]\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 2, \"firstAttemptCnt\": 2, \"idleLat\": {\"mean\": 0.2793593635, \"sqDiff\": 0.12496868146194745}, \"lastExecAt\": \"2022-11-19T07:46:03.771401191Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 1, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.000006720000000003893, \"sqDiff\": 7.963219999903227E-13}, \"parseLat\": {\"mean\": 0, \"sqDiff\": 0}, \"planGists\": [\"AgH2/f//nxoAAA4AAAADBwYYBgQ=\"], \"planLat\": {\"mean\": 0.0006736439999999999, \"sqDiff\": 4.9541058000000066E-11}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.0225572005, \"sqDiff\": 0.0008244723053128004}, \"svcLat\": {\"mean\": 0.023237564500000002, \"sqDiff\": 0.0008248253008619406}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":13.4391}
I221119 07:52:46.198128 80569262 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 82740 ={"Timestamp":1668844366183757483,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-19 07:00:00'","'\\x6e939058cec3245a'","'\\x16198ba66e7c02ed'","'\\xfbcf18a29261094d'","'schemachange'","1","'01:00:00'","'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": false, \"implicitTxn\": false, \"query\": \"SELECT EXISTS (SELECT table_name FROM information_schema.tables WHERE (table_schema = $1) AND (table_name = $1))\", \"querySummary\": \"SELECT EXISTS (SELECT ...)\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 3, \"firstAttemptCnt\": 3, \"idleLat\": {\"mean\": 0.6760405063333333, \"sqDiff\": 0.34363621457769683}, \"lastExecAt\": \"2022-11-19T07:47:49.030336557Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 1, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.000010454333333333466, \"sqDiff\": 7.795360666665628E-12}, \"parseLat\": {\"mean\": 0, \"sqDiff\": 0}, \"planGists\": [\"AgHi/f//nxoAAAwAAAADFwICAgYC\"], \"planLat\": {\"mean\": 0.0003517363333333334, \"sqDiff\": 3.140358314666669E-9}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.004161728333333333, \"sqDiff\": 9.669554592286662E-7}, \"svcLat\": {\"mean\": 0.004523919, \"sqDiff\": 9.112879194500007E-7}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":13.527798}
I221119 07:52:46.212234 80571550 9@util/log/event_log.go:32  [n3,intExec=stmt-diag-poll] 82741 ={"Timestamp":1668844366203503990,"EventType":"query_execute","Statement":"SELECT id, statement_fingerprint, min_execution_latency, expires_at, sampling_probability FROM \"\".system.statement_diagnostics_requests WHERE (completed = false) AND ((expires_at IS NULL) OR (expires_at > now()))","Tag":"SELECT","User":"root","ApplicationName":"$ internal-stmt-diag-poll","ExecMode":"exec-internal","Age":9.097625,"TxnCounter":1}
I221119 07:52:46.217366 80571855 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 82742 ={"Timestamp":1668844366204527721,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-19 07:00:00'","'\\xe58de5e49f61fdcb'","'\\x8cc443c6573122ed'","'\\xd30ebdbc3c6ca889'","'schemachange'","1","'01:00:00'","e'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": true, \"implicitTxn\": false, \"query\": \"WITH tab_json AS (SELECT crdb_internal.pb_to_json(\\'_\\', descriptor)->\\'_\\' AS t FROM system.descriptor WHERE id = $1::REGCLASS), columns_json AS (SELECT json_array_elements(t->\\'_\\') AS c FROM tab_json), columns AS (SELECT c->>\\'_\\' AS generation_expression, c->>\\'_\\' AS column_name FROM columns_json) SELECT show_columns.column_name, show_columns.data_type, show_columns.is_nullable, columns.generation_expression IS NOT NULL AS is_generated, COALESCE(columns.generation_expression, \\'_\\') AS generated_expression FROM [SHOW COLUMNS FROM schema1373.table2291] AS show_columns, columns WHERE (show_columns.column_name != \\'_\\') AND (show_columns.column_name = columns.column_name)\", \"querySummary\": \"\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 144911, \"sqDiff\": 0}, \"cnt\": 1, \"firstAttemptCnt\": 1, \"idleLat\": {\"mean\": 1.7175774069999998, \"sqDiff\": 0}, \"lastExecAt\": \"2022-11-19T07:47:53.865047222Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 5, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.000009333000000000258, \"sqDiff\": 0}, \"parseLat\": {\"mean\": 0, \"sqDiff\": 0}, \"planGists\": [\"AgEGAgADAAAAAwcCGgIHAgcEAwHM/v//nxoAAN6DgICAgDQAAAADBQ4NBwYDCQACAgAABwoGCg==\"], \"planLat\": {\"mean\": 0.002900521, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 184, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.194943356, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.19785321, \"sqDiff\": 0}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":12.501589}
I221119 07:52:46.243911 80574742 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 82744 ={"Timestamp":1668844366222177311,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-19 07:00:00'","'\\x28cc019f26414da6'","'\\x67b1439bdf1232e8'","'\\x853af18ef5811abf'","'schemachange'","1","'01:00:00'","e'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": false, \"implicitTxn\": false, \"query\": \"SELECT schema_name, table_name FROM [SHOW TABLES] WHERE table_name ~ \\'_\\' ORDER BY random() LIMIT _\", \"querySummary\": \"SELECT schema_name, ta... FROM [SHOW TABLES]\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 9, \"firstAttemptCnt\": 9, \"idleLat\": {\"mean\": 0.30337094477777776, \"sqDiff\": 0.4351895041600063}, \"lastExecAt\": \"2022-11-19T07:39:05.771200939Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 0, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.000009291444444448071, \"sqDiff\": 8.258120422226661E-11}, \"parseLat\": {\"mean\": 0, \"sqDiff\": 0}, \"planGists\": [\"AgGK////nxoAAAIAAAAByPz//58aAAACAAAAAez8//+fGgAABgAAAAMBpv3//58aAADOgBAAAAADCQACAgAACQICAgAABwgJAgICAAAHBgGM////nxoGAJIgAgAACQECAgAABwYYBgQ=\"], \"planLat\": {\"mean\": 0.006475683555555556, \"sqDiff\": 0.00012921492145123422}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.05283966933333333, \"sqDiff\": 0.004777408226703781}, \"svcLat\": {\"mean\": 0.05932464433333332, \"sqDiff\": 0.005072565923833903}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":21.264807}
I221119 07:52:46.241217 1071152 9@util/log/event_log.go:32  [n1,client=127.0.0.1:47932,user=testuser] 82743 ={"Timestamp":1668844365520546295,"EventType":"query_execute","Statement":"WITH tab_json AS (SELECT crdb_internal.pb_to_json('desc', descriptor)->'table' AS t FROM \"\".system.descriptor WHERE id = $1::REGCLASS), columns_json AS (SELECT json_array_elements(t->'columns') AS c FROM \"\".\"\".tab_json), columns AS (SELECT c->>'computeExpr' AS generation_expression, c->>'name' AS column_name FROM \"\".\"\".columns_json) SELECT show_columns.column_name, show_columns.data_type, show_columns.is_nullable, columns.generation_expression IS NOT NULL AS is_generated, COALESCE(columns.generation_expression, '') AS generated_expression FROM [SHOW COLUMNS FROM schema2344.table2540] AS show_columns, \"\".\"\".columns WHERE (show_columns.column_name != 'rowid') AND (show_columns.column_name = columns.column_name)","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","PlaceholderValues":["table2540"],"ExecMode":"exec","NumRows":8,"Age":152.6506,"FullTableScan":true,"TxnCounter":895}
I221119 07:52:46.265808 80577610 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 82745 ={"Timestamp":1668844366254608984,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-19 07:00:00'","'\\x79c9b6fe1e67152d'","'\\xee7dba1ff89732b5'","'\\xd51f6ad99fe0af47'","'schemachange'","1","'01:00:00'","'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": false, \"implicitTxn\": false, \"query\": \"SELECT session_id FROM [SHOW session_id]\", \"querySummary\": \"SELECT session_id FROM [SHOW session_id]\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"firstAttemptCnt\": 1, \"idleLat\": {\"mean\": 0.000585878, \"sqDiff\": 0}, \"lastExecAt\": \"2022-11-19T07:39:53.732008063Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 1, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.0000033610000000000107, \"sqDiff\": 0}, \"parseLat\": {\"mean\": 0, \"sqDiff\": 0}, \"planGists\": [\"AisHAgYC\"], \"planLat\": {\"mean\": 0.000147244, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.000373088, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.000523693, \"sqDiff\": 0}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":10.838427}
I221119 07:52:46.285527 80579694 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 82746 ={"Timestamp":1668844366275198385,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-19 07:00:00'","'\\x371a3bda163b8eed'","'\\x2b45d53b3fd171b9'","'\\x02b44e2f348e4ac1'","'schemachange'","1","'01:00:00'","e'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": false, \"implicitTxn\": false, \"query\": \"SELECT array_agg(index_name) FROM (SELECT index_name FROM crdb_internal.table_indexes WHERE (index_type = \\'_\\') AND (descriptor_id = $1::REGCLASS))\", \"querySummary\": \"SELECT array_agg(index...) FROM (SELECT FROM crdb_internal.tab...)\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 2, \"firstAttemptCnt\": 2, \"idleLat\": {\"mean\": 0.8864120625, \"sqDiff\": 0.15557285703774404}, \"lastExecAt\": \"2022-11-19T07:40:14.627712106Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 1, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.000006902500000000424, \"sqDiff\": 5.362812499997376E-12}, \"parseLat\": {\"mean\": 0, \"sqDiff\": 0}, \"planGists\": [\"AgGO////nxoAADIAAAADBQIMBgI=\"], \"planLat\": {\"mean\": 0.0003675375, \"sqDiff\": 9.505585080500006E-9}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.0076632205, \"sqDiff\": 0.00006119284935962451}, \"svcLat\": {\"mean\": 0.0080376605, \"sqDiff\": 0.00005964123028290051}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":9.688464}
I221119 07:52:46.296942 80566756 9@util/log/event_log.go:32  [n1,client=127.0.0.1:47936,user=testuser,intExec=crdb-internal-statistics-table] 82747 ={"Timestamp":1668844356168380442,"EventType":"query_execute","Statement":"SELECT s.\"tableID\", max(s.\"rowCount\") FROM \"\".system.table_statistics AS s JOIN (SELECT \"tableID\", max(\"createdAt\") AS last_dt FROM \"\".system.table_statistics GROUP BY \"tableID\") AS l ON (l.\"tableID\" = s.\"tableID\") AND (l.last_dt = s.\"createdAt\") AS OF SYSTEM TIME '-10s' GROUP BY s.\"tableID\"","Tag":"SELECT","User":"root","ApplicationName":"$ internal-crdb-internal-statistics-table","ExecMode":"exec-internal","NumRows":71,"Age":129.86028,"FullTableScan":true,"TxnCounter":1}
I221119 07:52:46.314813 80582428 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 82748 ={"Timestamp":1668844366300210450,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-19 07:00:00'","'\\xad65867376abcb04'","'\\x319f8fd6e599c7f6'","'\\x76ab846aae692c5b'","'schemachange'","1","'01:00:00'","'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": false, \"implicitTxn\": false, \"query\": \"SELECT EXISTS (SELECT * FROM [SHOW REGIONS FROM DATABASE])\", \"querySummary\": \"SELECT EXISTS (SELECT ...)\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"firstAttemptCnt\": 1, \"idleLat\": {\"mean\": 1.188030286, \"sqDiff\": 0}, \"lastExecAt\": \"2022-11-19T07:39:33.300510248Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 1, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.000015447000000001765, \"sqDiff\": 0}, \"parseLat\": {\"mean\": 0, \"sqDiff\": 0}, \"planGists\": [\"AgH4/v//nxoAAAYAAAAHBAHU////nxoAAHQAAAADGgIXBwgJAgICAAEXAgICBgI=\"], \"planLat\": {\"mean\": 0.009644197, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.012608294, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.022267938, \"sqDiff\": 0}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":14.302933}
I221119 07:52:46.319429 80581991 9@util/log/event_log.go:32  [n1,client=127.0.0.1:47932,user=testuser,intExec=read-roles] 82749 ={"Timestamp":1668844365520546295,"EventType":"query_execute","Statement":"SELECT u.username, \"isRole\", drs.settings, json_object_agg(COALESCE(ro.option, 'null'), ro.value) FROM \"\".system.users AS u LEFT JOIN \"\".system.role_options AS ro ON ro.username = u.username LEFT JOIN \"\".system.database_role_settings AS drs ON (drs.role_name = u.username) AND (drs.database_id = 0) GROUP BY u.username, \"isRole\", drs.settings","Tag":"SELECT","User":"root","ApplicationName":"$ internal-read-roles","ExecMode":"exec-internal","NumRows":3,"Age":22.647972,"FullTableScan":true}
I221119 07:52:46.334195 80585056 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 82750 ={"Timestamp":1668844366320956029,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-19 07:00:00'","'\\xc90ea64f6a1ec744'","'\\xdff0efc4c496ac04'","'\\xd30ebdbc3c6ca889'","'schemachange'","1","'01:00:00'","e'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": true, \"implicitTxn\": false, \"query\": \"WITH tab_json AS (SELECT crdb_internal.pb_to_json(\\'_\\', descriptor)->\\'_\\' AS t FROM system.descriptor WHERE id = $1::REGCLASS), columns_json AS (SELECT json_array_elements(t->\\'_\\') AS c FROM tab_json), columns AS (SELECT c->>\\'_\\' AS generation_expression, c->>\\'_\\' AS column_name FROM columns_json) SELECT show_columns.column_name, show_columns.data_type, show_columns.is_nullable, columns.generation_expression IS NOT NULL AS is_generated, COALESCE(columns.generation_expression, \\'_\\') AS generated_expression FROM [SHOW COLUMNS FROM schema777.table1454] AS show_columns, columns WHERE (show_columns.column_name != \\'_\\') AND (show_columns.column_name = columns.column_name)\", \"querySummary\": \"\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 151955, \"sqDiff\": 0}, \"cnt\": 1, \"firstAttemptCnt\": 1, \"idleLat\": {\"mean\": 3.373822142, \"sqDiff\": 0}, \"lastExecAt\": \"2022-11-19T07:43:04.168126999Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 3, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.000010888000000000564, \"sqDiff\": 0}, \"parseLat\": {\"mean\": 0, \"sqDiff\": 0}, \"planGists\": [\"AgEGAgADAAAAAwcCGgIHAgcEAwHM/v//nxoAAN6DgICAgDQAAAADBQ4NBwYDCQACAgAABwoGCg==\"], \"planLat\": {\"mean\": 0.006212364, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 1.7E+2, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.091348865, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.097572117, \"sqDiff\": 0}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":12.544468}
I221119 07:52:46.343926 1071117 9@util/log/event_log.go:32  [n1,client=127.0.0.1:47936,user=testuser] 82751 ={"Timestamp":1668844365316216898,"EventType":"query_execute","Statement":"SELECT schema_name, table_name FROM [SHOW TABLES] WHERE table_name ~ 'table[0-9]+' ORDER BY random() LIMIT 1","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","ExecMode":"exec","NumRows":1,"Age":246.36983,"TxnCounter":1170}
I221119 07:52:46.350465 1071117 9@util/log/event_log.go:32  [n1,client=127.0.0.1:47936,user=testuser] 82752 ={"Timestamp":1668844365316216898,"EventType":"query_execute","Statement":"SELECT EXISTS (SELECT table_name FROM information_schema.tables WHERE (table_schema = $1) AND (table_name = $2))","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","PlaceholderValues":["'schema2631'","'table3156'"],"ExecMode":"exec","NumRows":1,"Age":5.629858,"TxnCounter":1170}
I221119 07:52:46.360399 1063750 9@util/log/event_log.go:32  [n1,client=127.0.0.1:47928,user=testuser] 82753 ={"Timestamp":1668844366326774336,"EventType":"query_execute","Statement":"SELECT active_queries, kv_txn FROM crdb_internal.cluster_sessions WHERE session_id = $1","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","PlaceholderValues":["'1728ec4ee7b8cd150000000000000001'"],"ExecMode":"exec","NumRows":1,"Age":33.659523,"TxnCounter":797}
I221119 07:52:46.364386 80587485 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 82754 ={"Timestamp":1668844366339133691,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-19 07:00:00'","'\\x79c9b6fe1e67152d'","'\\x67421f11ad713d5f'","'\\xd51f6ad99fe0af47'","'schemachange'","1","'01:00:00'","'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": false, \"implicitTxn\": false, \"query\": \"SELECT session_id FROM [SHOW session_id]\", \"querySummary\": \"SELECT session_id FROM [SHOW session_id]\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"firstAttemptCnt\": 1, \"idleLat\": {\"mean\": 0.004751933, \"sqDiff\": 0}, \"lastExecAt\": \"2022-11-19T07:45:36.097627044Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 1, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.000008742999999999967, \"sqDiff\": 0}, \"parseLat\": {\"mean\": 0, \"sqDiff\": 0}, \"planGists\": [\"AisHAgYC\"], \"planLat\": {\"mean\": 0.000184381, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.000569975, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.000763099, \"sqDiff\": 0}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":25.008564}
W221119 07:52:46.367467 191225 2@rpc/clock_offset.go:223  [n1,rnode=3,raddr=127.0.0.1:45437,class=system,rpc] 82755  latency jump (prev avg 1.87ms, current 3.80ms)
I221119 07:52:46.386348 80590139 9@util/log/event_log.go:32  [n1,client=127.0.0.1:47936,user=testuser,intExec=select-comments] 82756 ={"Timestamp":1668844365316216898,"EventType":"query_execute","Statement":"SELECT COALESCE(pc.object_id, sc.object_id) AS object_id, COALESCE(pc.sub_id, sc.sub_id) AS sub_id, COALESCE(pc.comment, sc.comment) AS comment, COALESCE(pc.type, sc.type) AS type FROM (SELECT * FROM \"\".system.comments) AS sc FULL JOIN (SELECT * FROM crdb_internal.predefined_comments) AS pc ON (((pc.object_id = sc.object_id) AND (pc.sub_id = sc.sub_id)) AND (pc.type = sc.type))","Tag":"SELECT","User":"root","ApplicationName":"$ internal-select-comments","ExecMode":"exec-internal","NumRows":281,"Age":19.477795,"FullTableScan":true}
I221119 07:52:46.388480 80591050 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 82757 ={"Timestamp":1668844366374532369,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-19 07:00:00'","'\\xdd5ce53052c8073d'","'\\x0a32e7806cb6e066'","'\\x08328607b4eb6cac'","'schemachange'","1","'01:00:00'","'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": false, \"implicitTxn\": false, \"query\": \"DROP SEQUENCE schema880.seq1033\", \"querySummary\": \"DROP SEQUENCE schema880.seq1033\", \"stmtTyp\": \"TypeDDL\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"firstAttemptCnt\": 1, \"idleLat\": {\"mean\": 0.000268276, \"sqDiff\": 0}, \"lastExecAt\": \"2022-11-19T07:41:30.91505652Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 0, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.000004566999999999592, \"sqDiff\": 0}, \"parseLat\": {\"mean\": 0.000031093, \"sqDiff\": 0}, \"planGists\": [\"Ais=\"], \"planLat\": {\"mean\": 0.000368719, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.005449346, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.005853725, \"sqDiff\": 0}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":13.689211}
I221119 07:52:46.409242 80593212 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 82758 ={"Timestamp":1668844366396063563,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-19 07:00:00'","'\\x371a3bda163b8eed'","'\\xe79c386b30a1ddea'","'\\x02b44e2f348e4ac1'","'schemachange'","1","'01:00:00'","e'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": false, \"implicitTxn\": false, \"query\": \"SELECT array_agg(index_name) FROM (SELECT index_name FROM crdb_internal.table_indexes WHERE (index_type = \\'_\\') AND (descriptor_id = $1::REGCLASS))\", \"querySummary\": \"SELECT array_agg(index...) FROM (SELECT FROM crdb_internal.tab...)\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"firstAttemptCnt\": 1, \"idleLat\": {\"mean\": 0.796899078, \"sqDiff\": 0}, \"lastExecAt\": \"2022-11-19T07:46:04.834064984Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 1, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.000006185000000000565, \"sqDiff\": 0}, \"parseLat\": {\"mean\": 0, \"sqDiff\": 0}, \"planGists\": [\"AgGO////nxoAADIAAAADBQIMBgI=\"], \"planLat\": {\"mean\": 0.000322969, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.003427366, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.00375652, \"sqDiff\": 0}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":12.90073}
I221119 07:52:46.424941 80596361 13@kv/kvserver/replicate_queue.go:1772  [n3,replicate,s3,r180/3:/Table/62{5-6}] 82759  no suitable rebalance target for voters
I221119 07:52:46.426778 80596361 13@kv/kvserver/replicate_queue.go:1791  [n3,replicate,s3,r180/3:/Table/62{5-6}] 82760  no suitable rebalance target for non-voters
I221119 07:52:46.427184 80596361 13@kv/kvserver/replicate_queue.go:2029  [n3,replicate,s3,r180/3:/Table/62{5-6}] 82761  transferring lease to s1
I221119 07:52:46.435797 80596242 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 82762 ={"Timestamp":1668844366421858222,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-19 07:00:00'","'\\xf520e89dc94cad29'","'\\x24bbd2a03ea179a1'","'\\xd30ebdbc3c6ca889'","'schemachange'","1","'01:00:00'","e'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": true, \"implicitTxn\": false, \"query\": \"WITH tab_json AS (SELECT crdb_internal.pb_to_json(\\'_\\', descriptor)->\\'_\\' AS t FROM system.descriptor WHERE id = $1::REGCLASS), columns_json AS (SELECT json_array_elements(t->\\'_\\') AS c FROM tab_json), columns AS (SELECT c->>\\'_\\' AS generation_expression, c->>\\'_\\' AS column_name FROM columns_json) SELECT show_columns.column_name, show_columns.data_type, show_columns.is_nullable, columns.generation_expression IS NOT NULL AS is_generated, COALESCE(columns.generation_expression, \\'_\\') AS generated_expression FROM [SHOW COLUMNS FROM schema1912.table2106] AS show_columns, columns WHERE (show_columns.column_name != \\'_\\') AND (show_columns.column_name = columns.column_name)\", \"querySummary\": \"\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 144907, \"sqDiff\": 0}, \"cnt\": 1, \"firstAttemptCnt\": 1, \"idleLat\": {\"mean\": 0.425376067, \"sqDiff\": 0}, \"lastExecAt\": \"2022-11-19T07:47:52.451592334Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 18, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.000010611999999993182, \"sqDiff\": 0}, \"parseLat\": {\"mean\": 0, \"sqDiff\": 0}, \"planGists\": [\"AgEGAgADAAAAAwcCGgIHAgcEAwHM/v//nxoAAN6DgICAgDQAAAADBQ4NBwYDCQACAgAABwoGCg==\"], \"planLat\": {\"mean\": 0.002668009, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 184, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.146577388, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.149256009, \"sqDiff\": 0}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":13.592604}
I221119 07:52:46.451947 80598900 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 82763 ={"Timestamp":1668844366441362962,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-19 07:00:00'","'\\xd0988e1d6e9f31d9'","'\\x7ffb3351e89e8606'","'\\x3c503c7f9468e824'","'schemachange'","1","'01:00:00'","'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": false, \"implicitTxn\": false, \"query\": \"SHOW CLUSTER SETTING version\", \"querySummary\": \"SHOW CLUSTER SETTING version\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 1.024E+4, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"firstAttemptCnt\": 1, \"idleLat\": {\"mean\": 0.009047693, \"sqDiff\": 0}, \"lastExecAt\": \"2022-11-19T07:38:07.95498998Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 1, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.000005207000000000128, \"sqDiff\": 0}, \"parseLat\": {\"mean\": 0, \"sqDiff\": 0}, \"planGists\": [\"AisGAg==\"], \"planLat\": {\"mean\": 0.000301727, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.00682128, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.007128214, \"sqDiff\": 0}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":10.333997}
I221119 07:52:46.476331 80601862 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 82764 ={"Timestamp":1668844366461942806,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-19 07:00:00'","'\\x095683b68889b381'","'\\x68f6ad5653ad0f2d'","'\\xd30ebdbc3c6ca889'","'schemachange'","1","'01:00:00'","e'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": true, \"implicitTxn\": false, \"query\": \"WITH tab_json AS (SELECT crdb_internal.pb_to_json(\\'_\\', descriptor)->\\'_\\' AS t FROM system.descriptor WHERE id = $1::REGCLASS), columns_json AS (SELECT json_array_elements(t->\\'_\\') AS c FROM tab_json), columns AS (SELECT c->>\\'_\\' AS generation_expression, c->>\\'_\\' AS column_name FROM columns_json) SELECT show_columns.column_name, show_columns.data_type, show_columns.is_nullable, columns.generation_expression IS NOT NULL AS is_generated, COALESCE(columns.generation_expression, \\'_\\') AS generated_expression FROM [SHOW COLUMNS FROM schema199.table317] AS show_columns, columns WHERE (show_columns.column_name != \\'_\\') AND (show_columns.column_name = columns.column_name)\", \"querySummary\": \"\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 49849, \"sqDiff\": 0}, \"cnt\": 2, \"firstAttemptCnt\": 2, \"idleLat\": {\"mean\": 0.375264559, \"sqDiff\": 0.023716448079787466}, \"lastExecAt\": \"2022-11-19T07:39:00.232431855Z\", \"maxRetries\": 0, \"nodes\": [1], \"numRows\": {\"mean\": 19, \"sqDiff\": 0}, \"ovhLat\": {\"mean\": 0.000011590000000005762, \"sqDiff\": 2.7380000012255005E-15}, \"parseLat\": {\"mean\": 0, \"sqDiff\": 0}, \"planGists\": [\"AgEGAgADAAAAAwcCGgIHAgcEAwHM/v//nxoAAN6DgICAgDQAAAADBQ4NBwYDCQACAgAABwoGCg==\"], \"planLat\": {\"mean\": 0.003305967, \"sqDiff\": 5.449471202000013E-9}, \"rowsRead\": {\"mean\": 74, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"runLat\": {\"mean\": 0.11868783299999999, \"sqDiff\": 0.0008440985595404884}, \"svcLat\": {\"mean\": 0.12200539, \"sqDiff\": 0.0008483965284269524}}}'","'{\"Children\": [], \"Name\": \"\"}'","ARRAY[]"],"ExecMode":"exec-internal","NumRows":1,"Age":14.035399}
I221119 07:52:46.489679 80585065 9@util/log/event_log.go:32  [n1,client=127.0.0.1:47932,user=testuser,intExec=crdb-internal-statistics-table] 82765 ={"Timestamp":1668844356323625131,"EventType":"query_execute","Statement":"SELECT s.\"tableID\", max(s.\"rowCount\") FROM \"\".system.table_statistics AS s JOIN (SELECT \"tableID\", max(\"createdAt\") AS last_dt FROM \"\".system.table_statistics GROUP BY \"tableID\") AS l ON (l.\"tableID\" = s.\"tableID\") AND (l.last_dt = s.\"createdAt\") AS OF SYSTEM TIME '-10s' GROUP BY s.\"tableID\"","Tag":"SELECT","User":"root","ApplicationName":"$ internal-crdb-internal-statistics-table","ExecMode":"exec-internal","NumRows":71,"Age":168.48805,"FullTableScan":true,"TxnCounter":1}
I221119 07:52:46.501206 1071152 9@util/log/event_log.go:32  [n1,client=127.0.0.1:47932,user=testuser] 82766 ={"Timestamp":1668844365520546295,"EventType":"query_execute","Statement":"SELECT schema_name, table_name FROM [SHOW TABLES] WHERE table_name ~ 'table[0-9]+' ORDER BY random() LIMIT 1","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","ExecMode":"exec","NumRows":1,"Age":246.34525,"TxnCounter":895}
I221119 07:52:46.504542 1071117 9@util/log/event_log.go:32  [n1,client=127.0.0.1:47936,user=testuser] 82767 ={"Timestamp":1668844365316216898,"EventType":"query_execute","Statement":"WITH tab_json AS (SELECT crdb_internal.pb_to_json('desc', descriptor)->'table' AS t FROM \"\".system.descriptor WHERE id = $1::REGCLASS), columns_json AS (SELECT json_array_elements(t->'columns') AS c FROM \"\".\"\".tab_json), columns AS (SELECT c->>'computeExpr' AS generation_expression, c->>'name' AS column_name FROM \"\".\"\".columns_json) SELECT show_columns.column_name, show_columns.data_type, show_columns.is_nullable, columns.generation_expression IS NOT NULL AS is_generated, COALESCE(columns.generation_expression, '') AS generated_expression FROM [SHOW COLUMNS FROM schema2631.table3156] AS show_columns, \"\".\"\".columns WHERE (show_columns.column_name != 'rowid') AND (show_columns.column_name = columns.column_name)","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","PlaceholderValues":["table3156"],"ExecMode":"exec","NumRows":5,"Age":142.49945,"FullTableScan":true,"TxnCounter":1170}
I221119 07:52:46.512033 1071152 9@util/log/event_log.go:32  [n1,client=127.0.0.1:47932,user=testuser] 82768 ={"Timestamp":1668844365520546295,"EventType":"query_execute","Statement":"SELECT EXISTS (SELECT table_name FROM information_schema.tables WHERE (table_schema = $1) AND (table_name = $2))","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","PlaceholderValues":["'schema1474'","'table2895'"],"ExecMode":"exec","NumRows":1,"Age":8.567368,"TxnCounter":895}
I221119 07:52:46.512071 80606090 9@util/log/event_log.go:32  [n1,intExec=insert-stmt-stats] 82769 ={"Timestamp":1668844366497323492,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.statement_statistics VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_plan_hash_transaction_fingerprint_id_shard_8, aggregated_ts, fingerprint_id, transaction_fingerprint_id, app_name, plan_hash, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-stmt-stats","PlaceholderValues":["'2022-11-19 07:00:00'","'\\x1fad80169c94c7e7'","'\\xab386ac7c5fde4f9'","'\\x6f3814978f3ee915'","'schemachange'","1","'01:00:00'","e'{\"db\": \"schemachange\", \"distsql\": false, \"failed\": false, \"fullScan\": false, \"implicitTxn\": false, \"query\": \"SELECT EXISTS (SELECT fd.descriptor_name FROM crdb_internal.forward_dependencies AS fd WHERE ((fd.descriptor_id = (SELECT c.oid FROM pg_catalog.pg_class AS c JOIN pg_catalog.pg_namespace AS ns ON ns.oid = c.relnamespace WHERE (c.relname = $1) AND (ns.nspname = $1))) AND (fd.descriptor_id != fd.dependedonby_id)) AND (fd.dependedonby_type != \\'_\\'))\", \"querySummary\": \"SELECT EXISTS (SELECT ...)\", \"stmtTyp\": \"TypeDML\", \"vec\": true}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"index_recommendations\": [], \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0},

cockroach-teamcity · 2022-11-20T08:47:03Z

pkg/ccl/testccl/workload/schemachange/schemachange_test.TestWorkload failed with artifacts on master @ cfb5ae9a96e1770daa4aef1615a46e212b561a84:

Fatal error:

panic: test timed out after 14m55s

Stack:

goroutine 78911351 [running]:
testing.(*M).startAlarm.func1()
	GOROOT/src/testing/testing.go:2036 +0x8e
created by time.goFunc
	GOROOT/src/time/sleep.go:176 +0x32

Log preceding fatal error

I221120 08:46:30.358194 78853957 9@util/log/event_log.go:32  [n1,job=815476211965984769,intExec=select-job] 61672 ={"Timestamp":1668933990331901249,"EventType":"query_execute","Statement":"SELECT status, payload, progress, COALESCE(last_run, created), COALESCE(num_runs, 0) FROM \"\".system.jobs WHERE id = $1","Tag":"SELECT","User":"root","ApplicationName":"$ internal-select-job","PlaceholderValues":["815476211965984769"],"ExecMode":"exec-internal","NumRows":1,"Age":15.670432}
I221120 08:46:30.363996 78855789 9@util/log/event_log.go:32  [n1,job=815476211331072001,intExec=load-job-query] 61673 ={"Timestamp":1668933990355832007,"EventType":"query_execute","Statement":"SELECT payload, progress, created_by_type, created_by_id, status FROM \"\".system.jobs WHERE id = $1","Tag":"SELECT","User":"root","ApplicationName":"$ internal-load-job-query","PlaceholderValues":["815476211331072001"],"ExecMode":"exec-internal","NumRows":1,"Age":7.930358}
I221120 08:46:30.373861 78856892 9@util/log/event_log.go:32  [n1,job=815476211331072001,intExec=select-job] 61674 ={"Timestamp":1668933990355832007,"EventType":"query_execute","Statement":"SELECT status, payload, progress, COALESCE(last_run, created), COALESCE(num_runs, 0) FROM \"\".system.jobs WHERE id = $1","Tag":"SELECT","User":"root","ApplicationName":"$ internal-select-job","PlaceholderValues":["815476211331072001"],"ExecMode":"exec-internal","NumRows":1,"Age":8.988348}
I221120 08:46:30.375915 78856659 9@util/log/event_log.go:32  [n1,job=815476211965984769,intExec=job-update] 61675 ={"Timestamp":1668933990331901249,"EventType":"query_execute","Statement":"UPDATE \"\".system.jobs SET progress = $2 WHERE id = $1","Tag":"UPDATE","User":"root","ApplicationName":"$ internal-job-update","PlaceholderValues":["815476211965984769","'\\x10fdeb96cdafbcfb02220d64656c6574696e672064617461a80194f7fd979adb9eb42d820105120308d104'"],"ExecMode":"exec-internal","NumRows":1,"Age":13.981847}
I221120 08:46:30.407989 1053513 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40090,user=testuser] 61676 ={"Timestamp":1668933990335674705,"EventType":"query_execute","Statement":"SELECT active_queries, kv_txn FROM crdb_internal.cluster_sessions WHERE session_id = $1","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","PlaceholderValues":["'17293dd1bcb48cca0000000000000001'"],"ExecMode":"exec","NumRows":1,"Age":72.381134,"TxnCounter":773}
I221120 08:46:30.427040 78860798 9@util/log/event_log.go:32  [n1,job=815476211965984769,intExec=load-job-query] 61677 ={"Timestamp":1668933990407673775,"EventType":"query_execute","Statement":"SELECT payload, progress, created_by_type, created_by_id, status FROM \"\".system.jobs WHERE id = $1","Tag":"SELECT","User":"root","ApplicationName":"$ internal-load-job-query","PlaceholderValues":["815476211965984769"],"ExecMode":"exec-internal","NumRows":1,"Age":18.839712}
I221120 08:46:30.427537 78858710 9@util/log/event_log.go:32  [n1,job=815476211331072001,intExec=job-update] 61678 ={"Timestamp":1668933990355832007,"EventType":"query_execute","Statement":"UPDATE \"\".system.jobs SET progress = $2 WHERE id = $1","Tag":"UPDATE","User":"root","ApplicationName":"$ internal-job-update","PlaceholderValues":["815476211331072001","'\\x10f8a698cdafbcfb02221277616974696e6720666f722047432054544ca8019ddec0d6b9c483d34c820107120308d1042001'"],"ExecMode":"exec-internal","NumRows":1,"Age":46.994583}
I221120 08:46:30.430273 78820674 sql/gcjob/gc_job_utils.go:289  [n1,job=815476211331072001] 61679  updated progress payload: tables:<id:593 > ranges_unsplit_done:true
I221120 08:46:30.435517 78863254 9@util/log/event_log.go:32  [n1,job=815476211965984769,intExec=select-job] 61680 ={"Timestamp":1668933990407673775,"EventType":"query_execute","Statement":"SELECT status, payload, progress, COALESCE(last_run, created), COALESCE(num_runs, 0) FROM \"\".system.jobs WHERE id = $1","Tag":"SELECT","User":"root","ApplicationName":"$ internal-select-job","PlaceholderValues":["815476211965984769"],"ExecMode":"exec-internal","NumRows":1,"Age":6.278822}
I221120 08:46:30.439573 78863554 9@util/log/event_log.go:32  [n1,job=815476211331072001,intExec=select-job] 61681 ={"Timestamp":1668933990355832007,"EventType":"query_execute","Statement":"SELECT status, payload, progress, COALESCE(last_run, created), COALESCE(num_runs, 0) FROM \"\".system.jobs WHERE id = $1","Tag":"SELECT","User":"root","ApplicationName":"$ internal-select-job","PlaceholderValues":["815476211331072001"],"ExecMode":"exec-internal","NumRows":1,"Age":8.73467}
I221120 08:46:30.449442 78864206 9@util/log/event_log.go:32  [n1,job=815476211965984769,intExec=job-update] 61682 ={"Timestamp":1668933990407673775,"EventType":"query_execute","Statement":"UPDATE \"\".system.jobs SET progress = $2 WHERE id = $1","Tag":"UPDATE","User":"root","ApplicationName":"$ internal-job-update","PlaceholderValues":["815476211965984769","'\\x10fabb9bcdafbcfb02220d64656c6574696e672064617461a80194f7fd979adb9eb42d820107120308d1042001'"],"ExecMode":"exec-internal","NumRows":1,"Age":12.93417}
I221120 08:46:30.450235 1045774 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40084,user=testuser] 61683 ={"Timestamp":1668933990333038009,"EventType":"query_execute","Statement":"SELECT * FROM _.crdb_internal.invalid_objects ORDER BY id","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","ExecMode":"exec","Age":103.92493,"TxnCounter":1301}
I221120 08:46:30.452533 78835974 sql/gcjob/gc_job_utils.go:289  [n1,job=815476211965984769] 61684  updated progress payload: tables:<id:593 > ranges_unsplit_done:true
I221120 08:46:30.453605 1045774 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40084,user=testuser] 61685 ={"Timestamp":1668933990333038009,"EventType":"query_execute","Statement":"SELECT 'validating all objects', crdb_internal.validate_multi_region_zone_configs()","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","ExecMode":"exec","NumRows":1,"Age":2.903573,"TxnCounter":1301}
I221120 08:46:30.462755 78864903 9@util/log/event_log.go:32  [n1,job=815476211331072001,intExec=job-update] 61686 ={"Timestamp":1668933990355832007,"EventType":"query_execute","Statement":"UPDATE \"\".system.jobs SET progress = $2 WHERE id = $1","Tag":"UPDATE","User":"root","ApplicationName":"$ internal-job-update","PlaceholderValues":["815476211331072001","'\\x10f8a698cdafbcfb02220d64656c6574696e672064617461a8019ddec0d6b9c483d34c820107120308d1042001'"],"ExecMode":"exec-internal","NumRows":1,"Age":21.977589}
I221120 08:46:30.464409 78820674 sql/gcjob/gc_job_utils.go:296  [n1,job=815476211331072001] 61687  updated running status: deleting data
I221120 08:46:30.469495 1053251 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40118,user=testuser] 61688 ={"Timestamp":1668933988235685620,"EventType":"query_execute","Statement":"WITH tab_json AS (SELECT crdb_internal.pb_to_json('desc', descriptor)->'table' AS t FROM \"\".system.descriptor WHERE id = $1::REGCLASS), columns_json AS (SELECT json_array_elements(t->'columns') AS c FROM \"\".\"\".tab_json), columns AS (SELECT c->>'computeExpr' AS generation_expression, c->>'name' AS column_name FROM \"\".\"\".columns_json) SELECT show_columns.column_name, show_columns.data_type, show_columns.is_nullable, columns.generation_expression IS NOT NULL AS is_generated, COALESCE(columns.generation_expression, '') AS generated_expression FROM [SHOW COLUMNS FROM schema519.table589] AS show_columns, \"\".\"\".columns WHERE (show_columns.column_name != 'rowid') AND (show_columns.column_name = columns.column_name)","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","PlaceholderValues":["table589"],"ExecMode":"exec","NumRows":8,"Age":593.0846,"FullTableScan":true,"TxnCounter":1042}
I221120 08:46:30.475799 78820674 sql/gcjob/table_garbage_collection.go:207  [n1,job=815476211331072001] 61689  deleting data for table 593
I221120 08:46:30.475794 78866331 9@util/log/event_log.go:32  [n1,job=815476211965984769,intExec=select-job] 61690 ={"Timestamp":1668933990407673775,"EventType":"query_execute","Statement":"SELECT status, payload, progress, COALESCE(last_run, created), COALESCE(num_runs, 0) FROM \"\".system.jobs WHERE id = $1","Tag":"SELECT","User":"root","ApplicationName":"$ internal-select-job","PlaceholderValues":["815476211965984769"],"ExecMode":"exec-internal","NumRows":1,"Age":22.843224}
I221120 08:46:30.477558 1053251 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40118,user=testuser] 61691 ={"Timestamp":1668933988235685620,"EventType":"query_execute","Statement":"SELECT t0.col589_595 AS col0, t0.col589_595 AS col1 FROM \"\".schema519.table589 AS t0 LIMIT 1","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","ExecMode":"exec","Age":5.762204,"TxnCounter":1042}
I221120 08:46:30.497719 78869673 9@util/log/event_log.go:32  [n1,job=815476211331072001,intExec=load-job-query] 61692 ={"Timestamp":1668933990477962840,"EventType":"query_execute","Statement":"SELECT payload, progress, created_by_type, created_by_id, status FROM \"\".system.jobs WHERE id = $1","Tag":"SELECT","User":"root","ApplicationName":"$ internal-load-job-query","PlaceholderValues":["815476211331072001"],"ExecMode":"exec-internal","NumRows":1,"Age":19.496977}
I221120 08:46:30.500786 78869493 9@util/log/event_log.go:32  [n1,job=815476211965984769,intExec=job-update] 61693 ={"Timestamp":1668933990407673775,"EventType":"query_execute","Statement":"UPDATE \"\".system.jobs SET progress = $2 WHERE id = $1","Tag":"UPDATE","User":"root","ApplicationName":"$ internal-job-update","PlaceholderValues":["815476211965984769","'\\x10fabb9bcdafbcfb02221277616974696e6720666f722047432054544ca80194f7fd979adb9eb42d820107120308d1042001'"],"ExecMode":"exec-internal","NumRows":1,"Age":23.365915}
I221120 08:46:30.503517 78835974 sql/gcjob/gc_job_utils.go:296  [n1,job=815476211965984769] 61694  updated running status: waiting for GC TTL
I221120 08:46:30.510370 78871685 9@util/log/event_log.go:32  [n1,job=815476211331072001,intExec=select-job] 61695 ={"Timestamp":1668933990477962840,"EventType":"query_execute","Statement":"SELECT status, payload, progress, COALESCE(last_run, created), COALESCE(num_runs, 0) FROM \"\".system.jobs WHERE id = $1","Tag":"SELECT","User":"root","ApplicationName":"$ internal-select-job","PlaceholderValues":["815476211331072001"],"ExecMode":"exec-internal","NumRows":1,"Age":6.881998}
I221120 08:46:30.517089 78872704 9@util/log/event_log.go:32  [n1,job=815476211965984769,intExec=load-job-query] 61696 ={"Timestamp":1668933990509681430,"EventType":"query_execute","Statement":"SELECT payload, progress, created_by_type, created_by_id, status FROM \"\".system.jobs WHERE id = $1","Tag":"SELECT","User":"root","ApplicationName":"$ internal-load-job-query","PlaceholderValues":["815476211965984769"],"ExecMode":"exec-internal","NumRows":1,"Age":7.211491}
I221120 08:46:30.524802 1045774 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40084,user=testuser] 61697 ={"Timestamp":1668933990333038009,"EventType":"query_execute","Statement":"SELECT sequence_schema, sequence_name FROM [SHOW SEQUENCES] WHERE sequence_name LIKE 'seq%%' ORDER BY random() LIMIT 1","Tag":"SELECT","User":"testuser","ApplicationName":"schemachange","ExecMode":"exec","Age":47.303185,"TxnCounter":1301}
I221120 08:46:30.537194 78874395 9@util/log/event_log.go:32  [n1,job=815476211965984769,intExec=select-job] 61698 ={"Timestamp":1668933990509681430,"EventType":"query_execute","Statement":"SELECT status, payload, progress, COALESCE(last_run, created), COALESCE(num_runs, 0) FROM \"\".system.jobs WHERE id = $1","Tag":"SELECT","User":"root","ApplicationName":"$ internal-select-job","PlaceholderValues":["815476211965984769"],"ExecMode":"exec-internal","NumRows":1,"Age":13.544836}
I221120 08:46:30.539336 78873471 9@util/log/event_log.go:32  [n1,job=815476211331072001,intExec=job-update] 61699 ={"Timestamp":1668933990477962840,"EventType":"query_execute","Statement":"UPDATE \"\".system.jobs SET progress = $2 WHERE id = $1","Tag":"UPDATE","User":"root","ApplicationName":"$ internal-job-update","PlaceholderValues":["815476211331072001","'\\x108be19fcdafbcfb02220d64656c6574696e672064617461a8019ddec0d6b9c483d34c820109120508d10410032001'"],"ExecMode":"exec-internal","NumRows":1,"Age":24.842896}
I221120 08:46:30.548945 78820674 sql/gcjob/gc_job_utils.go:289  [n1,job=815476211331072001] 61700  updated progress payload: tables:<id:593 status:WAITING_FOR_MVCC_GC > ranges_unsplit_done:true
I221120 08:46:30.561649 78875240 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40118,user=testuser,intExec=read-roles] 61701 ={"Timestamp":1668933988235685620,"EventType":"query_execute","Statement":"SELECT u.username, \"isRole\", drs.settings, json_object_agg(COALESCE(ro.option, 'null'), ro.value) FROM \"\".system.users AS u LEFT JOIN \"\".system.role_options AS ro ON ro.username = u.username LEFT JOIN \"\".system.database_role_settings AS drs ON (drs.role_name = u.username) AND (drs.database_id = 0) GROUP BY u.username, \"isRole\", drs.settings","Tag":"SELECT","User":"root","ApplicationName":"$ internal-read-roles","ExecMode":"exec-internal","NumRows":3,"Age":28.693516,"FullTableScan":true}
I221120 08:46:30.562522 78877032 9@util/log/event_log.go:32  [n1,job=815476211331072001,intExec=select-job] 61702 ={"Timestamp":1668933990477962840,"EventType":"query_execute","Statement":"SELECT status, payload, progress, COALESCE(last_run, created), COALESCE(num_runs, 0) FROM \"\".system.jobs WHERE id = $1","Tag":"SELECT","User":"root","ApplicationName":"$ internal-select-job","PlaceholderValues":["815476211331072001"],"ExecMode":"exec-internal","NumRows":1,"Age":13.324695}
I221120 08:46:30.572339 78877257 9@util/log/event_log.go:32  [n1,job=815476211965984769,intExec=job-update] 61703 ={"Timestamp":1668933990509681430,"EventType":"query_execute","Statement":"UPDATE \"\".system.jobs SET progress = $2 WHERE id = $1","Tag":"UPDATE","User":"root","ApplicationName":"$ internal-job-update","PlaceholderValues":["815476211965984769","'\\x10f1d8a1cdafbcfb02221277616974696e6720666f722047432054544ca80194f7fd979adb9eb42d820107120308d1042001'"],"ExecMode":"exec-internal","NumRows":1,"Age":21.382778}
I221120 08:46:30.575821 78835974 sql/gcjob/gc_job_utils.go:289  [n1,job=815476211965984769] 61704  updated progress payload: tables:<id:593 > ranges_unsplit_done:true
I221120 08:46:30.577713 78878706 9@util/log/event_log.go:32  [n1,job=815476211331072001,intExec=job-update] 61705 ={"Timestamp":1668933990477962840,"EventType":"query_execute","Statement":"UPDATE \"\".system.jobs SET progress = $2 WHERE id = $1","Tag":"UPDATE","User":"root","ApplicationName":"$ internal-job-update","PlaceholderValues":["815476211331072001","'\\x108be19fcdafbcfb02221377616974696e6720666f72204d564343204743a8019ddec0d6b9c483d34c820109120508d10410032001'"],"ExecMode":"exec-internal","NumRows":1,"Age":14.063534}
I221120 08:46:30.580670 78820674 sql/gcjob/gc_job_utils.go:296  [n1,job=815476211331072001] 61706  updated running status: waiting for MVCC GC
I221120 08:46:30.593641 78880635 9@util/log/event_log.go:32  [n1,job=815476211965984769,intExec=select-job] 61707 ={"Timestamp":1668933990509681430,"EventType":"query_execute","Statement":"SELECT status, payload, progress, COALESCE(last_run, created), COALESCE(num_runs, 0) FROM \"\".system.jobs WHERE id = $1","Tag":"SELECT","User":"root","ApplicationName":"$ internal-select-job","PlaceholderValues":["815476211965984769"],"ExecMode":"exec-internal","NumRows":1,"Age":17.482862}
I221120 08:46:30.609105 78882959 9@util/log/event_log.go:32  [n1,job=815476211965984769,intExec=job-update] 61708 ={"Timestamp":1668933990509681430,"EventType":"query_execute","Statement":"UPDATE \"\".system.jobs SET progress = $2 WHERE id = $1","Tag":"UPDATE","User":"root","ApplicationName":"$ internal-job-update","PlaceholderValues":["815476211965984769","'\\x10f1d8a1cdafbcfb02220d64656c6574696e672064617461a80194f7fd979adb9eb42d820107120308d1042001'"],"ExecMode":"exec-internal","NumRows":1,"Age":14.61115}
I221120 08:46:30.612324 78835974 sql/gcjob/gc_job_utils.go:296  [n1,job=815476211965984769] 61709  updated running status: deleting data
I221120 08:46:30.629071 78835974 sql/gcjob/table_garbage_collection.go:207  [n1,job=815476211965984769] 61710  deleting data for table 593
I221120 08:46:30.640115 78884488 9@util/log/event_log.go:32  [n1,client=127.0.0.1:40084,user=testuser,intExec=read-roles] 61711 ={"Timestamp":1668933990333038009,"EventType":"query_execute","Statement":"SELECT u.username, \"isRole\", drs.settings, json_object_agg(COALESCE(ro.option, 'null'), ro.value) FROM \"\".system.users AS u LEFT JOIN \"\".system.role_options AS ro ON ro.username = u.username LEFT JOIN \"\".system.database_role_settings AS drs ON (drs.role_name = u.username) AND (drs.database_id = 0) GROUP BY u.username, \"isRole\", drs.settings","Tag":"SELECT","User":"root","ApplicationName":"$ internal-read-roles","ExecMode":"exec-internal","NumRows":3,"Age":39.267506,"FullTableScan":true}
I221120 08:46:30.647680 78888738 9@util/log/event_log.go:32  [n1,job=815476211965984769,intExec=load-job-query] 61712 ={"Timestamp":1668933990633216218,"EventType":"query_execute","Statement":"SELECT payload, progress, created_by_type, created_by_id, status FROM \"\".system.jobs WHERE id = $1","Tag":"SELECT","User":"root","ApplicationName":"$ internal-load-job-query","PlaceholderValues":["815476211965984769"],"ExecMode":"exec-internal","NumRows":1,"Age":14.109908}
I221120 08:46:30.669403 78890311 9@util/log/event_log.go:32  [n1,job=815476211965984769,intExec=select-job] 61713 ={"Timestamp":1668933990633216218,"EventType":"query_execute","Statement":"SELECT status, payload, progress, COALESCE(last_run, created), COALESCE(num_runs, 0) FROM \"\".system.jobs WHERE id = $1","Tag":"SELECT","User":"root","ApplicationName":"$ internal-select-job","PlaceholderValues":["815476211965984769"],"ExecMode":"exec-internal","NumRows":1,"Age":14.109045}
I221120 08:46:30.706392 78892058 9@util/log/event_log.go:32  [n1,job=815476211965984769,intExec=job-update] 61714 ={"Timestamp":1668933990633216218,"EventType":"query_execute","Statement":"UPDATE \"\".system.jobs SET progress = $2 WHERE id = $1","Tag":"UPDATE","User":"root","ApplicationName":"$ internal-job-update","PlaceholderValues":["815476211965984769","'\\x10809ea9cdafbcfb02220d64656c6574696e672064617461a80194f7fd979adb9eb42d820109120508d10410032001'"],"ExecMode":"exec-internal","NumRows":1,"Age":31.007076}
I221120 08:46:30.707707 78835974 sql/gcjob/gc_job_utils.go:289  [n1,job=815476211965984769] 61715  updated progress payload: tables:<id:593 status:WAITING_FOR_MVCC_GC > ranges_unsplit_done:true
I221120 08:46:30.723860 78895017 9@util/log/event_log.go:32  [n1,job=815476211965984769,intExec=select-job] 61716 ={"Timestamp":1668933990633216218,"EventType":"query_execute","Statement":"SELECT status, payload, progress, COALESCE(last_run, created), COALESCE(num_runs, 0) FROM \"\".system.jobs WHERE id = $1","Tag":"SELECT","User":"root","ApplicationName":"$ internal-select-job","PlaceholderValues":["815476211965984769"],"ExecMode":"exec-internal","NumRows":1,"Age":15.780216}
I221120 08:46:30.735640 78896685 9@util/log/event_log.go:32  [n1,job=815476211965984769,intExec=job-update] 61717 ={"Timestamp":1668933990633216218,"EventType":"query_execute","Statement":"UPDATE \"\".system.jobs SET progress = $2 WHERE id = $1","Tag":"UPDATE","User":"root","ApplicationName":"$ internal-job-update","PlaceholderValues":["815476211965984769","'\\x10809ea9cdafbcfb02221377616974696e6720666f72204d564343204743a80194f7fd979adb9eb42d820109120508d10410032001'"],"ExecMode":"exec-internal","NumRows":1,"Age":10.046944}
I221120 08:46:30.736569 78835974 sql/gcjob/gc_job_utils.go:296  [n1,job=815476211965984769] 61718  updated running status: waiting for MVCC GC
I221120 08:46:30.831502 78906117 9@util/log/event_log.go:32  [n1,job=815473283193470977,intExec=protectedts-GetMetadata] 61719 ={"Timestamp":1668933990815484970,"EventType":"query_execute","Statement":"WITH current_meta AS (SELECT version, num_records, num_spans, total_bytes FROM \"\".system.protected_ts_meta UNION ALL SELECT 0 AS version, 0 AS num_records, 0 AS num_spans, 0 AS total_bytes ORDER BY version DESC LIMIT 1) SELECT version, num_records, num_spans, total_bytes FROM \"\".\"\".current_meta","Tag":"SELECT","User":"node","ApplicationName":"$ internal-protectedts-GetMetadata","ExecMode":"exec-internal","NumRows":1,"Age":12.907343,"FullTableScan":true}
I221120 08:46:30.847177 78908275 9@util/log/event_log.go:32  [n1,job=815473283193470977,intExec=protectedts-GetRecords] 61720 ={"Timestamp":1668933990815484970,"EventType":"query_execute","Statement":"SELECT id, ts, meta_type, meta, spans, verified, target FROM \"\".system.protected_ts_records","Tag":"SELECT","User":"node","ApplicationName":"$ internal-protectedts-GetRecords","ExecMode":"exec-internal","Age":9.231945,"FullTableScan":true}
I221120 08:46:30.855981 78909313 9@util/log/event_log.go:32  [n1,job=815473283193470977,intExec=protectedts-GetMetadata] 61721 ={"Timestamp":1668933990815484970,"EventType":"query_execute","Statement":"WITH current_meta AS (SELECT version, num_records, num_spans, total_bytes FROM \"\".system.protected_ts_meta UNION ALL SELECT 0 AS version, 0 AS num_records, 0 AS num_spans, 0 AS total_bytes ORDER BY version DESC LIMIT 1) SELECT version, num_records, num_spans, total_bytes FROM \"\".\"\".current_meta","Tag":"SELECT","User":"node","ApplicationName":"$ internal-protectedts-GetMetadata","ExecMode":"exec-internal","NumRows":1,"Age":7.294161,"FullTableScan":true}

Parameters: TAGS=bazel,gss,deadlock

Help

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

Same failure on other branches

pkg/ccl/testccl/workload/schemachange/schemachange_test: TestWorkload failed #92187 pkg/ccl/testccl/workload/schemachange/schemachange_test: TestWorkload failed [C-test-failure O-robot T-sql-schema branch-release-22.2]

_{This test on roachdash | Improve this report!}

cockroach-teamcity · 2022-11-22T07:20:10Z

pkg/ccl/testccl/workload/schemachange/schemachange_test.TestWorkload failed with artifacts on master @ dca415eddac0d659ae6d76b4e3dfdf4076adbd34:

Fatal error:

panic: test timed out after 14m55s

Stack:

goroutine 76736032 [running]:
testing.(*M).startAlarm.func1()
	GOROOT/src/testing/testing.go:2036 +0x8e
created by time.goFunc
	GOROOT/src/time/sleep.go:176 +0x32

Log preceding fatal error

I221122 07:19:25.931912 76725896 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82494 ={"Timestamp":1669101565927702318,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.644831,"TxnCounter":1}
I221122 07:19:25.938243 76726216 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82495 ={"Timestamp":1669101565934032380,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.441407,"TxnCounter":1}
I221122 07:19:25.948588 76725847 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 82496 ={"Timestamp":1669101565926098328,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-22 07:00:00'","'\\xbf205c87bffa8e25'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"0d757793f66dd32d\", \"461654901be541a8\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"8f177fab1f8bfeaa\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 2.048E+4, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 5.322E+4, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.02386278, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 23, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 7E+1, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.616700526, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":22.163109}
W221122 07:19:25.952105 34896 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 82497  failed to flush transaction statistics: flushing transaction 13772109398610185765's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221122 07:19:25.960210 76726861 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82498 ={"Timestamp":1669101565956111319,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.484057,"TxnCounter":1}
I221122 07:19:25.974622 76727181 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82499 ={"Timestamp":1669101565966650311,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":8.345979,"TxnCounter":1}
I221122 07:19:25.983796 76726813 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 82500 ={"Timestamp":1669101565954433561,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-22 07:00:00'","'\\x54cd60feb9de4745'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"ae1f52e5ea090a9c\", \"8f177fab1f8bfeaa\", \"f962e1294bdb8559\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 1.024E+4, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.00023034, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 3, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.258612619, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":28.778786}
W221122 07:19:25.986204 34896 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 82501  failed to flush transaction statistics: flushing transaction 6110646916567942981's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221122 07:19:25.991987 76727801 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82502 ={"Timestamp":1669101565987745151,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.633122,"TxnCounter":1}
I221122 07:19:25.998111 76728121 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82503 ={"Timestamp":1669101565994132504,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.636901,"TxnCounter":1}
I221122 07:19:26.013956 76727750 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 82504 ={"Timestamp":1669101565986377333,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-22 07:00:00'","'\\x6c8dbeb1751c97fd'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"8f177fab1f8bfeaa\", \"a5a73fcc5e59d80e\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"b7a916d460d21220\", \"6e939058cec3245a\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"71792200d34078d4\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"c18d214381891b25\"]}'","'{\"execution_statistics\": {\"cnt\": 0, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 311932, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.025248052, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 24, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 3.1E+2, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.945835689, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":27.252546}
W221122 07:19:26.014854 34896 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 82505  failed to flush transaction statistics: flushing transaction 7822117797195716605's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221122 07:19:26.020488 76728850 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82506 ={"Timestamp":1669101566016404276,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.51253,"TxnCounter":1}
I221122 07:19:26.026381 76729170 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82507 ={"Timestamp":1669101566022363679,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.279258,"TxnCounter":1}
I221122 07:19:26.043676 76728813 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 82508 ={"Timestamp":1669101566015013302,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-22 07:00:00'","'\\xb8dbca7d02406958'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"28cc019f26414da6\", \"8f177fab1f8bfeaa\", \"7b261d5987beabd4\", \"28cc019f26414da6\", \"b7a916d460d21220\", \"8f177fab1f8bfeaa\", \"c50c4a507d16949c\", \"2f5d2177c93b2bae\", \"b7a916d460d21220\", \"6e939058cec3245a\", \"28cc019f26414da6\", \"3f019e1c2ddbb9aa\", \"c50c4a507d16949c\", \"ea92e611555a0a66\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 1.024E+4, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.031190556, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 9, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.584194029, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":28.329264}
W221122 07:19:26.045125 34896 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 82509  failed to flush transaction statistics: flushing transaction 13320462961135872344's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221122 07:19:26.051137 76729813 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82510 ={"Timestamp":1669101566047095528,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.412501,"TxnCounter":1}
I221122 07:19:26.057230 76730135 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82511 ={"Timestamp":1669101566053101967,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.608571,"TxnCounter":1}
I221122 07:19:26.078538 76729766 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 82512 ={"Timestamp":1669101566045437671,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-22 07:00:00'","'\\x43ff701e3685baed'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"053baee6106cf777\", \"28cc019f26414da6\", \"8f177fab1f8bfeaa\", \"6e939058cec3245a\", \"a5a76c0e994f714a\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 1.19808E+6, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.000234248, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 12, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 1.208856034, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":32.75347}
W221122 07:19:26.091248 34896 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 82513  failed to flush transaction statistics: flushing transaction 4899758194668452589's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221122 07:19:26.107832 76730757 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82514 ={"Timestamp":1669101566092753767,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":15.355206,"TxnCounter":1}
I221122 07:19:26.119695 76731179 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82515 ={"Timestamp":1669101566112107355,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":7.860748,"TxnCounter":1}
I221122 07:19:26.135791 76730715 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 82516 ={"Timestamp":1669101566091434371,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-22 07:00:00'","'\\xc372a6f337e212f2'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"28cc019f26414da6\", \"3f019e1c2ddbb9aa\", \"c50c4a507d16949c\", \"e46a53d41fe83589\", \"28cc019f26414da6\", \"8f177fab1f8bfeaa\", \"3dc5a4e2414072f4\", \"28cc019f26414da6\", \"3f019e1c2ddbb9aa\", \"28cc019f26414da6\", \"28cc019f26414da6\", \"b7a916d460d21220\", \"8f177fab1f8bfeaa\", \"2fe3de3e7609ec3d\", \"12e53d30e533d70d\", \"28cc019f26414da6\", \"b7a916d460d21220\", \"8f177fab1f8bfeaa\", \"c50c4a507d16949c\", \"dd575107287ad29b\", \"28cc019f26414da6\", \"28cc019f26414da6\", \"28cc019f26414da6\", \"28cc019f26414da6\", \"ec3b2def2cfc1387\", \"cf892ea44c511827\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 1.024E+4, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 3879, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": -1.108834845, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 11, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 71, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 1.167180078, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":44.036358}
W221122 07:19:26.136727 34896 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 82517  failed to flush transaction statistics: flushing transaction 14083502548285788914's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221122 07:19:26.142620 76731790 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82518 ={"Timestamp":1669101566138363783,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.620583,"TxnCounter":1}
I221122 07:19:26.148992 76732110 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82519 ={"Timestamp":1669101566144451025,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.797999,"TxnCounter":1}
I221122 07:19:26.172021 76731756 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 82520 ={"Timestamp":1669101566136892131,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-22 07:00:00'","'\\x7e393c9170fbfba2'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"0ca3618818f00e9b\", \"fb9d66e8ad29fd8f\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"0ca3618818f00e9b\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"0ca3618818f00e9b\", \"1b77ac5e705cc090\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"b7a916d460d21220\", \"ad65867376abcb04\", \"d0988e1d6e9f31d9\", \"d0988e1d6e9f31d9\", \"6e939058cec3245a\", \"8f177fab1f8bfeaa\", \"929e6445d9e69582\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 1.71008E+6, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 4, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 399294, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.052593125, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 75, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 579, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 2.019842772, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":34.791386}
W221122 07:19:26.173355 34896 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 82521  failed to flush transaction statistics: flushing transaction 9095367517814913954's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221122 07:19:26.179534 76732747 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82522 ={"Timestamp":1669101566175231350,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.73656,"TxnCounter":1}
I221122 07:19:26.186521 76733067 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82523 ={"Timestamp":1669101566182306106,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.545488,"TxnCounter":1}
I221122 07:19:26.195676 76732690 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 82524 ={"Timestamp":1669101566173602663,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-22 07:00:00'","'\\x4627490d32e9fe3c'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"2a9130c3f81b87ed\", \"2a49d47032bd19e5\", \"ec3b2def2cfc1387\", \"cf892ea44c511827\", \"8f177fab1f8bfeaa\", \"9ffce99b9c7b3c01\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"a918b4f1417f679f\", \"b7a916d460d21220\", \"8f177fab1f8bfeaa\", \"2fe3de3e7609ec3d\", \"0539586301f2d53d\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 2.048E+4, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 43736, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.049712576, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 33, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 75, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 1.739775885, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":21.72924}
W221122 07:19:26.197144 34896 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 82525  failed to flush transaction statistics: flushing transaction 5055089427784269372's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221122 07:19:26.203390 76733710 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82526 ={"Timestamp":1669101566199317944,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.510293,"TxnCounter":1}
I221122 07:19:26.217939 76734030 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82527 ={"Timestamp":1669101566205675677,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":12.636158,"TxnCounter":1}
I221122 07:19:26.230238 76733675 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 82528 ={"Timestamp":1669101566197729313,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-22 07:00:00'","'\\x133f25104e3c5394'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"bd3f3503cab27abb\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"d3d97d6f3db62162\", \"f629ead5a6829ef7\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 4.096E+4, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 2, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 232466, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.000951194, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 42, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 226, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 0.760917103, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":32.160023}
W221122 07:19:26.231518 34896 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 82529  failed to flush transaction statistics: flushing transaction 1386867962215682964's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221122 07:19:26.237315 76734744 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82530 ={"Timestamp":1669101566233055368,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.613988,"TxnCounter":1}
I221122 07:19:26.243280 76735068 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82531 ={"Timestamp":1669101566239095399,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.431483,"TxnCounter":1}
I221122 07:19:26.252872 76734697 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 82532 ={"Timestamp":1669101566231693421,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-22 07:00:00'","'\\x6fda88d32a14573a'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"3f019e1c2ddbb9aa\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"fa5847e85c453c97\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"a36cb3e9006a78b1\", \"8a0404977eb5c322\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"a9af2e301304372e\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"fa5847e85c453c97\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"a9af2e301304372e\", \"13d5ba407026affd\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"fa5847e85c453c97\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"a9af2e301304372e\", \"2cf63d9d7fb95c77\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"b7a916d460d21220\", \"8f177fab1f8bfeaa\", \"c50c4a507d16949c\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"71ddd5233a350ada\", \"e17d4125eca79e37\", \"5ed97baad1bce971\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"b7a916d460d21220\", \"8f177fab1f8bfeaa\", \"2fe3de3e7609ec3d\", \"e66ad0959742e1d5\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 1.4336E+5, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 6, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 951404, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.053963348, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 107, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 976, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 3.7309092120000003, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":20.854456}
W221122 07:19:26.258904 34896 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 82533  failed to flush transaction statistics: flushing transaction 8059904923658377018's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221122 07:19:26.267696 76735707 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82534 ={"Timestamp":1669101566261782945,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":6.420828,"TxnCounter":1}
I221122 07:19:26.274859 76736027 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82535 ={"Timestamp":1669101566270158119,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.967304,"TxnCounter":1}
I221122 07:19:26.289968 76735660 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 82536 ={"Timestamp":1669101566259928212,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-22 07:00:00'","'\\x635614073f3014da'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"371a3bda163b8eed\", \"34b3ca8721025257\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"d0b2630497e3bade\", \"0040e95cfcfe7590\", \"28cc019f26414da6\", \"8f177fab1f8bfeaa\", \"6e939058cec3245a\", \"4eff557849ccc404\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 3.072E+4, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 0, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 0, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.028121495, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 36, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 1.438572615, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":29.688356}
W221122 07:19:26.290924 34896 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 82537  failed to flush transaction statistics: flushing transaction 7157930679109424346's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221122 07:19:26.296765 76736655 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82538 ={"Timestamp":1669101566292564870,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.57243,"TxnCounter":1}
I221122 07:19:26.302520 76736975 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82539 ={"Timestamp":1669101566298493595,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.284605,"TxnCounter":1}
I221122 07:19:26.319852 76736614 9@util/log/event_log.go:32  [n1,intExec=insert-txn-stats] 82540 ={"Timestamp":1669101566291072238,"EventType":"query_execute","Statement":"INSERT INTO \"\".system.transaction_statistics VALUES ($1, $2, $3, $4, $5, $6, $7) ON CONFLICT (crdb_internal_aggregated_ts_app_name_fingerprint_id_node_id_shard_8, aggregated_ts, fingerprint_id, app_name, node_id) DO NOTHING","Tag":"INSERT","User":"node","ApplicationName":"$ internal-insert-txn-stats","PlaceholderValues":["'2022-11-22 07:00:00'","'\\x21f6e4600791b1e2'","'schemachange'","1","'01:00:00'","'{\"stmtFingerprintIDs\": [\"79c9b6fe1e67152d\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"3beb7058b2ba2c24\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"192c769e71b1bc56\", \"28cc019f26414da6\", \"6e939058cec3245a\", \"192c769e71b1bc56\", \"26de15584d4388f8\"]}'","'{\"execution_statistics\": {\"cnt\": 1, \"contentionTime\": {\"mean\": 0, \"sqDiff\": 0}, \"maxDiskUsage\": {\"mean\": 0, \"sqDiff\": 0}, \"maxMemUsage\": {\"mean\": 1.6384E+5, \"sqDiff\": 0}, \"networkBytes\": {\"mean\": 0, \"sqDiff\": 0}, \"networkMsgs\": {\"mean\": 2, \"sqDiff\": 0}}, \"statistics\": {\"bytesRead\": {\"mean\": 374679, \"sqDiff\": 0}, \"cnt\": 1, \"commitLat\": {\"mean\": 0.007370459, \"sqDiff\": 0}, \"maxRetries\": 0, \"numRows\": {\"mean\": 31, \"sqDiff\": 0}, \"retryLat\": {\"mean\": 0, \"sqDiff\": 0}, \"rowsRead\": {\"mean\": 453, \"sqDiff\": 0}, \"rowsWritten\": {\"mean\": 0, \"sqDiff\": 0}, \"svcLat\": {\"mean\": 1.058184197, \"sqDiff\": 0}}}'"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":28.449228}
W221122 07:19:26.320889 34896 sql/sqlstats/persistedsqlstats/flush.go:119  [n1] 82541  failed to flush transaction statistics: flushing transaction 2447394548617425378's statistics: insert-txn-stats: failed to connect to n2 at 127.0.0.1:44111: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]
I221122 07:19:26.326953 76737711 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82542 ={"Timestamp":1669101566322528585,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.830116,"TxnCounter":1}
I221122 07:19:26.333125 76738031 9@util/log/event_log.go:32  [intExec=get-table-statistics] 82543 ={"Timestamp":1669101566328963592,"EventType":"query_execute","Statement":"SELECT \"tableID\", \"statisticID\", name, \"columnIDs\", \"createdAt\", \"rowCount\", \"distinctCount\", \"nullCount\", \"avgSize\", \"partialPredicate\", histogram FROM \"\".system.table_statistics WHERE \"tableID\" = $1 ORDER BY \"createdAt\" DESC, \"columnIDs\" DESC, \"statisticID\" DESC","Tag":"SELECT","User":"root","ApplicationName":"$ internal-get-table-statistics","PlaceholderValues":["43"],"ExecMode":"exec-internal","SQLSTATE":"XXUUU","ErrorText":"failed to connect to n3 at 127.0.0.1:37345: grpc: refusing to dial; node is quiescing [code 7/PermissionDenied]","Age":4.600934,"TxnCounter":1}

Parameters: TAGS=bazel,gss,deadlock

Help

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

Same failure on other branches

pkg/ccl/testccl/workload/schemachange/schemachange_test: TestWorkload failed #92187 pkg/ccl/testccl/workload/schemachange/schemachange_test: TestWorkload failed [C-test-failure O-robot T-sql-schema branch-release-22.2]

_{This test on roachdash | Improve this report!}

ajwerner · 2022-11-29T15:26:47Z

Fixed by #92343.

cockroach-teamcity added branch-master Failures and bugs on the master branch. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels Nov 17, 2022

cockroach-teamcity added this to the 23.1 milestone Nov 17, 2022

blathers-crl bot added the T-sql-schema-deprecated Use T-sql-foundations instead label Nov 17, 2022

cockroach-teamcity mentioned this issue Nov 19, 2022

pkg/ccl/testccl/workload/schemachange/schemachange_test: TestWorkload failed #92187

Closed

ajwerner self-assigned this Nov 22, 2022

cockroach-teamcity mentioned this issue Nov 23, 2022

pkg/ccl/testccl/workload/schemachange/schemachange_test: TestWorkload failed #92386

Closed

ajwerner closed this as completed Nov 29, 2022

exalate-issue-sync bot added T-sql-foundations SQL Foundations Team (formerly SQL Schema + SQL Sessions) and removed T-sql-schema-deprecated Use T-sql-foundations instead labels May 10, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

pkg/ccl/testccl/workload/schemachange/schemachange_test: TestWorkload failed #92043

pkg/ccl/testccl/workload/schemachange/schemachange_test: TestWorkload failed #92043

cockroach-teamcity commented Nov 17, 2022 •

edited by cockroach-jira-scripts

Loading

cockroach-teamcity commented Nov 18, 2022

cockroach-teamcity commented Nov 19, 2022

cockroach-teamcity commented Nov 20, 2022

cockroach-teamcity commented Nov 22, 2022

ajwerner commented Nov 29, 2022

pkg/ccl/testccl/workload/schemachange/schemachange_test: TestWorkload failed #92043

pkg/ccl/testccl/workload/schemachange/schemachange_test: TestWorkload failed #92043

Comments

cockroach-teamcity commented Nov 17, 2022 • edited by cockroach-jira-scripts Loading

cockroach-teamcity commented Nov 18, 2022

cockroach-teamcity commented Nov 19, 2022

cockroach-teamcity commented Nov 20, 2022

cockroach-teamcity commented Nov 22, 2022

ajwerner commented Nov 29, 2022

cockroach-teamcity commented Nov 17, 2022 •

edited by cockroach-jira-scripts

Loading