Hi everyone,
We are in the process of upgrading from PostgreSQL 9.6 to 13. When our
database gets created in our regression tests, we run some unit tests
first. We see one of those tests hang.
It seems the client is waiting on more data to arrive from the
PostgreSQL server. A thread dump shows it waiting on the socket.
On the server, I see the connection from the client. Looking at
pg_stat_activity, I see it is in state 'active'. I have seen query_start
be as old as eight hours ago. The documentation states that 'active'
means a query is being executed. The query in question is:
select distinct(constraint_name) CONSTRAINT_NAME from
information_schema.key_column_usage where constraint_name in (select
rc.constraint_name from information_schema.referential_constraints rc
inner join information_schema.table_constraints tc on tc.constraint_name
= rc.constraint_name inner join information_schema.table_constraints tc2
on tc2.constraint_name = rc.unique_constraint_name where
tc2.constraint_type = 'PRIMARY KEY') and lower(column_name) like 'xxx_%';
This query should be fast to execute. When I run it myself using
'explain analyze', I get results like "(cost=4892.35..4892.35 rows=1
width=64) (actual time=1669.432..1669.447 rows=0 loops=1)".
Looking at pg_locks, I only see locks with granted = true for the PID.
There is nothing in the logs as far as I can see. Configuration
variables log_min_messages and log_min_error_statement are on 'debug1'.
This is a snippet of the logs:
2021-07-09 20:35:16.374 CEST [30399] STATEMENT: START TRANSACTION
2021-07-09 20:35:18.703 CEST [30399] WARNING: there is already a
transaction in progress
2021-07-09 20:35:18.703 CEST [30399] STATEMENT: START TRANSACTION
2021-07-09 20:35:26.398 CEST [30977] DEBUG: rehashing catalog cache id
7 for pg_attribute; 257 tups, 128 buckets
2021-07-09 20:35:26.398 CEST [30977] STATEMENT: select
distinct(constraint_name) CONSTRAINT_NAME from
information_schema.key_column_usage where constraint_name in (select
rc.constraint_name from information_schema.referential_constraints
rc inner join information_schema.table_constraints tc on
tc.constraint_name = rc.constraint_name inner join
information_schema.table_constraints tc2 on tc2.constraint_name =
rc.unique_constraint_name where tc2.constraint_type = 'PRIMARY
KEY') and lower(column_name) like 'xxx_%'
2021-07-09 20:35:26.399 CEST [30977] DEBUG: rehashing catalog cache id
7 for pg_attribute; 513 tups, 256 buckets
2021-07-09 20:35:26.399 CEST [30977] STATEMENT: select
distinct(constraint_name) CONSTRAINT_NAME from
information_schema.key_column_usage where constraint_name in (select
rc.constraint_name from information_schema.referential_constraints
rc inner join information_schema.table_constraints tc on
tc.constraint_name = rc.constraint_name inner join
information_schema.table_constraints tc2 on tc2.constraint_name =
rc.unique_constraint_name where tc2.constraint_type = 'PRIMARY
KEY') and lower(column_name) like 'xxx_%'
2021-07-09 20:35:33.170 CEST [31010] DEBUG: autovacuum: processing
database "wildfly"
2021-07-09 20:35:33.520 CEST [31010] DEBUG: rehashing catalog cache id
12 for pg_cast; 513 tups, 256 buckets
2021-07-09 20:35:33.520 CEST [31010] DEBUG: rehashing catalog cache id
14 for pg_opclass; 17 tups, 8 buckets
2021-07-09 20:35:33.648 CEST [31010] DEBUG: rehashing catalog cache id
7 for pg_attribute; 257 tups, 128 buckets
2021-07-09 20:36:03.182 CEST [31199] DEBUG: autovacuum: processing
database "postgres"
2021-07-09 20:36:33.200 CEST [31387] DEBUG: autovacuum: processing
database "wildfly"
I am a bit out of ideas - does anyone have any tips where I should look
to see what is causing the query to hang?
With kind regards,
Jurrie
