How to debug a connection that's "active" but hanging? - Mailing list pgsql-general

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