def-
commented
2 years ago [dfelsing@dev-server-dfelsing ~]$ ps aux|grep postgres
dfelsing 3418204 0.0 0.1 267180 43264 ? S Aug24 0:02 /nfusr/dev-server/dfelsing/code/yugabyte-db/build/release-clang13-linuxbrew-dynamic-ninja/postgres/bin/postgres -D /nfusr/dev-server/dfelsing/yugabyte-data/node-3/disk-1/pg_data -p 5433 -h 127.0.0.3 -k /tmp/.yb.896641872422930295 -c unix_socket_permissions=0700 -c logging_collector=on -c log_directory=/nfusr/dev-server/dfelsing/yugabyte-data/node-3/disk-1/yb-data/tserver/logs -c yb_pg_metrics.node_name=dev-server-dfelsing:9000 -c yb_pg_metrics.port=13000 -c config_file=/nfusr/dev-server/dfelsing/yugabyte-data/node-3/disk-1/pg_data/ysql_pg.conf -c hba_file=/nfusr/dev-server/dfelsing/yugabyte-data/node-3/disk-1/pg_data/ysql_hba.conf
dfelsing 3418234 0.0 0.1 267180 42632 ? S Aug24 0:02 /nfusr/dev-server/dfelsing/code/yugabyte-db/build/release-clang13-linuxbrew-dynamic-ninja/postgres/bin/postgres -D /nfusr/dev-server/dfelsing/yugabyte-data/node-2/disk-1/pg_data -p 5433 -h 127.0.0.2 -k /tmp/.yb.1895829667009633833 -c unix_socket_permissions=0700 -c logging_collector=on -c log_directory=/nfusr/dev-server/dfelsing/yugabyte-data/node-2/disk-1/yb-data/tserver/logs -c yb_pg_metrics.node_name=dev-server-dfelsing:9000 -c yb_pg_metrics.port=13000 -c config_file=/nfusr/dev-server/dfelsing/yugabyte-data/node-2/disk-1/pg_data/ysql_pg.conf -c hba_file=/nfusr/dev-server/dfelsing/yugabyte-data/node-2/disk-1/pg_data/ysql_hba.conf
dfelsing 3418264 0.0 0.1 267180 43992 ? S Aug24 0:02 /nfusr/dev-server/dfelsing/code/yugabyte-db/build/release-clang13-linuxbrew-dynamic-ninja/postgres/bin/postgres -D /nfusr/dev-server/dfelsing/yugabyte-data/node-1/disk-1/pg_data -p 5433 -h 127.0.0.1 -k /tmp/.yb.9427142463175692966 -c unix_socket_permissions=0700 -c logging_collector=on -c log_directory=/nfusr/dev-server/dfelsing/yugabyte-data/node-1/disk-1/yb-data/tserver/logs -c yb_pg_metrics.node_name=dev-server-dfelsing:9000 -c yb_pg_metrics.port=13000 -c config_file=/nfusr/dev-server/dfelsing/yugabyte-data/node-1/disk-1/pg_data/ysql_pg.conf -c hba_file=/nfusr/dev-server/dfelsing/yugabyte-data/node-1/disk-1/pg_data/ysql_hba.conf
dfelsing 3418294 0.3 0.0 122584 13756 ? Ss Aug24 3:24 postgres: logger
dfelsing 3418296 0.0 0.0 275376 20972 ? Ssl Aug24 0:04 postgres: YSQL webserver
dfelsing 3418298 0.0 0.0 267180 14952 ? Ss Aug24 0:00 postgres: checkpointer
dfelsing 3418299 0.0 0.0 124700 13864 ? Ss Aug24 0:04 postgres: stats collector
dfelsing 3418300 0.4 0.0 122584 13764 ? Ss Aug24 4:20 postgres: logger
dfelsing 3418302 0.0 0.0 275376 20912 ? Ssl Aug24 0:05 postgres: YSQL webserver
dfelsing 3418304 0.3 0.0 122584 14128 ? Ss Aug24 3:29 postgres: logger
dfelsing 3418305 0.0 0.0 267180 14952 ? Ss Aug24 0:00 postgres: checkpointer
dfelsing 3418306 0.0 0.0 124700 13728 ? Ss Aug24 0:05 postgres: stats collector
dfelsing 3418308 0.0 0.0 275376 21660 ? Ssl Aug24 0:04 postgres: YSQL webserver
dfelsing 3418310 0.0 0.0 267180 15764 ? Ss Aug24 0:00 postgres: checkpointer
dfelsing 3418311 0.0 0.0 124700 14092 ? Ss Aug24 0:05 postgres: stats collector
dfelsing 3590709 0.9 0.3 390712 95552 ? Ssl 07:37 0:45 postgres: yugabyte db_lst_719764 127.0.0.1(33030) idle
dfelsing 3590713 6.5 0.8 552504 249820 ? Ssl 07:37 5:27 postgres: yugabyte db_lst_719764 127.0.0.1(33036) idle
dfelsing 3590716 1.1 0.3 401976 99892 ? Ssl 07:37 0:57 postgres: yugabyte db_lst_719764 127.0.0.1(50036) CREATE INDEX
dfelsing 3590721 1.5 0.3 394808 100472 ? Ssl 07:37 1:15 postgres: yugabyte db_lst_719764 127.0.0.1(42778) idle
dfelsing 3590738 1.0 0.3 390712 94476 ? Ssl 07:37 0:52 postgres: yugabyte db_lst_719764 127.0.0.1(33060) idle
dfelsing 3590739 6.7 0.7 532664 225832 ? Ssl 07:37 5:34 postgres: yugabyte db_lst_719764 127.0.0.1(50060) idle in transaction
dfelsing 3590742 5.9 0.7 533328 231976 ? Ssl 07:37 4:55 postgres: yugabyte db_lst_719764 127.0.0.1(33066) idle
dfelsing 3613572 0.3 1.0 655992 334204 ? Ssl 08:17 0:07 postgres: postgres db_lst_719764 [local] BACKFILL INDEX
dfelsing 3613666 0.1 0.3 431056 120532 ? Ssl 08:18 0:04 postgres: postgres db_lst_719764 [local] BACKFILL INDEX
dfelsing 3613791 0.1 0.3 429008 116640 ? Ssl 08:19 0:04 postgres: postgres db_lst_719764 [local] BACKFILL INDEX
dfelsing 3613875 0.1 0.3 426960 115028 ? Ssl 08:20 0:04 postgres: postgres db_lst_719764 [local] BACKFILL INDEX
dfelsing 3616910 0.0 0.0 12140 1164 pts/2 S+ 09:00 0:00 grep --color=auto postgresIn the postgres logs there are some occurences of catalog cache misses:
2022-08-25 08:17:03.335 UTC [3590716] LOG: Catalog cache miss on cache with id 50:
Target rel: pg_class (oid : 1259), index oid 2663
Search keys: idx_tg0_0_c0_varchar_c22_int_c15_date_c1_smallint_c2_int_c3_num, 2200
@ 0x9b5748 errmsg
@ 0x98beb2 SearchCatCacheMiss
@ 0x98ae85 SearchCatCacheInternal
@ 0x9adf69 GetSysCacheOid
@ 0x582e53 index_create
@ 0x648ef7 DefineIndex
@ 0x85a938 ProcessUtilitySlow
@ 0x858ec0 standard_ProcessUtility
@ 0x8584ae YBProcessUtilityDefaultHook
@ 0x7f953e09fe70 pgss_ProcessUtility
@ 0x7f953e096ad7 ybpgm_ProcessUtility
@ 0x7f953e07a72e pg_hint_plan_ProcessUtility
@ 0x9e4b07 YBTxnDdlProcessUtility
@ 0x8580fa PortalRunUtility
@ 0x8577e7 PortalRunMulti
@ 0x8570a6 PortalRun
@ 0x854826 yb_exec_simple_query_impl
@ 0x854dc6 yb_exec_query_wrapper_one_attempt
@ 0x85193b PostgresMain
@ 0x7bda3c BackendRun
@ 0x7bce90 ServerLoop
@ 0x7b944b PostmasterMain
@ 0x719c1d PostgresServerProcessMain
@ 0x71a0c2 main
@ 0x7f954293a825 __libc_start_main
@ 0x4c6ed9 _start
2022-08-25 08:17:03.335 UTC [3590716] STATEMENT: CREATE INDEX CONCURRENTLY idx_tg0_0_c0_varchar_c22_int_c15_date_c1_smallint_c2_int_c3_numeric ON tg0_0 USING lsm (c0_varchar DESC NULLS LAST, c22_int ASC NULLS LAST, c15_date ASC NULLS FIRST, c1_smallint ASC NULLS LAST, c2_int ASC NULLS LAST, c3_numeric DESC NULLS LAST);Tserver logs around this time:
I0825 08:16:59.135116 3445811 libpq_utils.cc:207] Connected to PG (host=/tmp/.yb.9427142463175692966 port=5433 dbname='db_lst_719764' connect_timeout=58 user='postgres' password=<REDACTED>), time taken: 2.400s
[...]
I0825 08:17:03.362573 3418004 pg_create_table.cc:90] PgCreateTable: creating a transactional index: db_lst_719764.idx_tg0_0_c0_varchar_c22_int_c15_date_c1_smallint_c2_int_c3_num/{ database_oid: 20034 object_oid: 2
0522 }
I0825 08:17:03.478680 3424869 tablet.cc:1965] T 27ca2aad50c945f5be8bdf65cdc63f54 P b544631ca71c4083b396dd88b3535098: Alter schema from Schema [
0:ybrowid[binary NOT NULL NOT A PARTITION KEY],
1:c0_varchar[string NULLABLE NOT A PARTITION KEY],
2:c1_smallint[int16 NULLABLE NOT A PARTITION KEY],
3:c2_int[int32 NULLABLE NOT A PARTITION KEY],
4:c3_numeric[decimal NULLABLE NOT A PARTITION KEY],
5:c4_daterange[binary NULLABLE NOT A PARTITION KEY],
6:c5_date[int32 NULLABLE NOT A PARTITION KEY],
7:c6_varchar[string NULLABLE NOT A PARTITION KEY],
8:c7_int8range[binary NULLABLE NOT A PARTITION KEY],
9:c8_daterange[binary NULLABLE NOT A PARTITION KEY],
10:c9_int4range[binary NULLABLE NOT A PARTITION KEY],
11:c10_int[int32 NULLABLE NOT A PARTITION KEY],
12:c11_json[binary NULLABLE NOT A PARTITION KEY],
13:c12_float4[float NULLABLE NOT A PARTITION KEY],
14:c13_jsonb[binary NULLABLE NOT A PARTITION KEY],
15:c14_smallint[int16 NULLABLE NOT A PARTITION KEY],
16:c15_date[int32 NULLABLE NOT A PARTITION KEY],
17:c16_date[int32 NULLABLE NOT A PARTITION KEY],
18:c17_int4range[binary NULLABLE NOT A PARTITION KEY],
19:c18_int4range[binary NULLABLE NOT A PARTITION KEY],
20:c19_float4[float NULLABLE NOT A PARTITION KEY],
21:c20_numeric[decimal NULLABLE NOT A PARTITION KEY],
22:c21_int8range[binary NULLABLE NOT A PARTITION KEY],
23:c22_int[int32 NULLABLE NOT A PARTITION KEY],
24:c23_numrange[binary NULLABLE NOT A PARTITION KEY],
25:c24_smallint[int16 NULLABLE NOT A PARTITION KEY],
26:c25_varchar[string NULLABLE NOT A PARTITION KEY],
27:c26_date[int32 NULLABLE NOT A PARTITION KEY],
28:c27_date[int32 NULLABLE NOT A PARTITION KEY]
]
properties: contain_counters: false is_transactional: true consistency_level: STRONG use_mangled_column_name: false is_ysql_catalog_table: false retain_delete_markers: false partitioning_version: 1
colocation_id: 814432576 version 122 to Schema [
0:ybrowid[binary NOT NULL NOT A PARTITION KEY],
1:c0_varchar[string NULLABLE NOT A PARTITION KEY],
2:c1_smallint[int16 NULLABLE NOT A PARTITION KEY],
3:c2_int[int32 NULLABLE NOT A PARTITION KEY],
4:c3_numeric[decimal NULLABLE NOT A PARTITION KEY],
5:c4_daterange[binary NULLABLE NOT A PARTITION KEY],
6:c5_date[int32 NULLABLE NOT A PARTITION KEY],
7:c6_varchar[string NULLABLE NOT A PARTITION KEY],
8:c7_int8range[binary NULLABLE NOT A PARTITION KEY],
9:c8_daterange[binary NULLABLE NOT A PARTITION KEY],
10:c9_int4range[binary NULLABLE NOT A PARTITION KEY],
11:c10_int[int32 NULLABLE NOT A PARTITION KEY],
12:c11_json[binary NULLABLE NOT A PARTITION KEY],
13:c12_float4[float NULLABLE NOT A PARTITION KEY],
14:c13_jsonb[binary NULLABLE NOT A PARTITION KEY],
15:c14_smallint[int16 NULLABLE NOT A PARTITION KEY],
16:c15_date[int32 NULLABLE NOT A PARTITION KEY],
17:c16_date[int32 NULLABLE NOT A PARTITION KEY],
18:c17_int4range[binary NULLABLE NOT A PARTITION KEY],
19:c18_int4range[binary NULLABLE NOT A PARTITION KEY],
20:c19_float4[float NULLABLE NOT A PARTITION KEY],
21:c20_numeric[decimal NULLABLE NOT A PARTITION KEY],
22:c21_int8range[binary NULLABLE NOT A PARTITION KEY],
23:c22_int[int32 NULLABLE NOT A PARTITION KEY],
24:c23_numrange[binary NULLABLE NOT A PARTITION KEY],
25:c24_smallint[int16 NULLABLE NOT A PARTITION KEY],
26:c25_varchar[string NULLABLE NOT A PARTITION KEY],
27:c26_date[int32 NULLABLE NOT A PARTITION KEY],
28:c27_date[int32 NULLABLE NOT A PARTITION KEY]
]
properties: contain_counters: false is_transactional: true consistency_level: STRONG use_mangled_column_name: false is_ysql_catalog_table: false retain_delete_markers: false partitioning_version: 1
colocation_id: 814432576 version 123
I0825 08:17:03.479979 3424869 meta_data_cache.cc:77] Creating a metadata cache without a permissions cache
I0825 08:17:03.636530 3418004 table_creator.cc:363] Created index db_lst_719764.idx_tg0_0_c0_varchar_c22_int_c15_date_c1_smallint_c2_int_c3_num of type PGSQL_TABLE_TYPE
I0825 08:17:06.251971 3420376 tablet.cc:2175] Begin BackfillIndexesForYsql at { physical: 1661415426219233 } from <start-of-the-tablet> for [table_id: "00004e4200003000800000000000502a" version: 0 is_local: false hash_column_count: 0 range_column_count: 0 is_unique: false indexed_table_id: "00004e42000030008000000000004e82" use_mangled_column_name: false index_permissions: INDEX_PERM_WRITE_AND_DELETE backfill_error_message: ""]
I0825 08:17:08.091812 3420376 libpq_utils.cc:207] Connected to PG (host=/tmp/.yb.9427142463175692966 port=5433 dbname='db_lst_719764' connect_timeout=59 user='postgres' password=<REDACTED>), time taken: 1.840s
tedyu
Jira Link: DB-3296
Description
Usually at the end of an LST run all queries will be finished or aborted by timeout, and thus LST can finish too. In the last few days I noticed that sometimes LST just stays stuck at the end, which means some queries are still stuck probably:
max_connections is set to 20 to figure out https://github.com/yugabyte/yugabyte-db/issues/13546. Maybe this bug is also related to it. LST run log:
After waiting for 10 minutes nothing else happens. All queries from LST are running with a timeout (
'options': '-c statement_timeout=300000'} # in ms), so it is unexpected for them to just get stuck like this:Both the
CREATE INDEXandUPDATEqueries appear to be stuck for >40 minutes already. I'll provide yugabyte-data directory in case it helps, accessible from within Yugabyte org: https://drive.google.com/file/d/19c17iCJ7X86PD9tqJpkC8n4r3Y2ZIQXD/view?usp=sharing CC @tedyu The create index being involved might point to a relation to recent DDL changes.