dalibo / temboard

PostgreSQL Remote Control
https://labs.dalibo.com/temboard
Other
453 stars 54 forks source link

Repeatedly Getting "FATAL: connection to client lost" from temboard agent every minute #668

Closed bsislow closed 2 years ago

bsislow commented 5 years ago

While there is a bit of a load on our system at PG 11.4, we are getting the following in the Postgres log file every minute from temboard agent:

2019-08-26 11:50:47 CDT [142572]: [1-1] user=temboard,db=mydb,app=[unknown],client=[local] LOG:  could not send data to client: Broken pipe
2019-08-26 11:50:47 CDT [142572]: [2-1] user=temboard,db=mydb,app=[unknown],client=[local] FATAL:  connection to client lost
2019-08-26 11:51:54 CDT [142847]: [1-1] user=temboard,db=mydb,app=[unknown],client=[local] LOG:  could not send data to client: Broken pipe
2019-08-26 11:51:54 CDT [142847]: [2-1] user=temboard,db=mydb,app=[unknown],client=[local] FATAL:  connection to client lost
2019-08-26 11:52:53 CDT [143073]: [1-1] user=temboard,db=mydb,app=[unknown],client=[local] LOG:  could not send data to client: Broken pipe
2019-08-26 11:52:53 CDT [143073]: [2-1] user=temboard,db=mydb,app=[unknown],client=[local] FATAL:  connection to client lost
2019-08-26 11:53:59 CDT [143285]: [1-1] user=temboard,db=mydb,app=[unknown],client=[local] LOG:  could not send data to client: Broken pipe
2019-08-26 11:53:59 CDT [143285]: [2-1] user=temboard,db=mydb,app=[unknown],client=[local] FATAL:  connection to client lost
2019-08-26 11:55:01 CDT [143503]: [1-1] user=temboard,db=mydb,app=[unknown],client=[local] LOG:  could not send data to client: Broken pipe
2019-08-26 11:55:01 CDT [143503]: [2-1] user=temboard,db=mydb,app=[unknown],client=[local] FATAL:  connection to client lost
2019-08-26 11:56:04 CDT [143718]: [1-1] user=temboard,db=mydb,app=[unknown],client=[local] LOG:  could not send data to client: Broken pipe
2019-08-26 11:56:04 CDT [143718]: [2-1] user=temboard,db=mydb,app=[unknown],client=[local] FATAL:  connection to client lost
2019-08-26 11:57:08 CDT [143937]: [1-1] user=temboard,db=mydb,app=[unknown],client=[local] LOG:  could not send data to client: Broken pipe
2019-08-26 11:57:08 CDT [143937]: [2-1] user=temboard,db=mydb,app=[unknown],client=[local] FATAL:  connection to client lost

FYI:

$ yum list installed | grep temboard-agent
*Note* Spacewalk repositories are not listed below. You must run this command as root to access Spacewalk repositories.
temboard-agent.noarch          4.0-1.el7              @dalibo-temboard

$ psql
psql (11.4)

What other information might you need to diagnose?

julmon commented 5 years ago

Hello,

Could you paste here some extracts (at the same time interval) of temboard-agent.log file please ?

bsislow commented 5 years ago

Here are some of the latest entries:

2019-08-27 12:21:28,658 temboardagent[57391]: [probes] ERROR: Unable to run probe "btree_bloat" on "myhost" on database "mydb"
2019-08-27 12:21:31,389 temboardagent[57616]: [probes] INFO: Loaded probe: locks
2019-08-27 12:21:31,390 temboardagent[57616]: [probes] INFO: Loaded probe: btree_bloat
2019-08-27 12:21:31,390 temboardagent[57616]: [probes] INFO: Loaded probe: process
2019-08-27 12:21:31,390 temboardagent[57616]: [probes] INFO: Loaded probe: replication_lag
2019-08-27 12:21:31,390 temboardagent[57616]: [probes] INFO: Loaded probe: wal_files
2019-08-27 12:21:31,390 temboardagent[57616]: [probes] INFO: Loaded probe: blocks
2019-08-27 12:21:31,391 temboardagent[57616]: [probes] INFO: Loaded probe: replication_connection
2019-08-27 12:21:31,391 temboardagent[57616]: [probes] INFO: Loaded probe: db_size
2019-08-27 12:21:31,391 temboardagent[57616]: [probes] INFO: Loaded probe: tblspc_size
2019-08-27 12:21:31,391 temboardagent[57616]: [probes] INFO: Loaded probe: temp_files_size_delta
2019-08-27 12:21:31,391 temboardagent[57616]: [probes] INFO: Loaded probe: sessions
2019-08-27 12:21:31,392 temboardagent[57616]: [probes] INFO: Loaded probe: xacts
2019-08-27 12:21:31,392 temboardagent[57616]: [probes] INFO: Loaded probe: heap_bloat
2019-08-27 12:21:31,392 temboardagent[57616]: [probes] INFO: Loaded probe: loadavg
2019-08-27 12:21:31,392 temboardagent[57616]: [probes] INFO: Loaded probe: filesystems_size
2019-08-27 12:21:31,392 temboardagent[57616]: [probes] INFO: Loaded probe: cpu
2019-08-27 12:21:31,392 temboardagent[57616]: [probes] INFO: Loaded probe: bgwriter
2019-08-27 12:21:31,393 temboardagent[57616]: [probes] INFO: Loaded probe: memory
2019-08-27 12:22:31,707 temboardagent[57616]: [probes] ERROR: Unable to run probe "btree_bloat" on "myhost" on database "mydb"
2019-08-27 12:22:34,094 temboardagent[57828]: [probes] INFO: Loaded probe: locks
2019-08-27 12:22:34,094 temboardagent[57828]: [probes] INFO: Loaded probe: btree_bloat
2019-08-27 12:22:34,095 temboardagent[57828]: [probes] INFO: Loaded probe: process
2019-08-27 12:22:34,095 temboardagent[57828]: [probes] INFO: Loaded probe: replication_lag
2019-08-27 12:22:34,095 temboardagent[57828]: [probes] INFO: Loaded probe: wal_files
2019-08-27 12:22:34,095 temboardagent[57828]: [probes] INFO: Loaded probe: blocks
2019-08-27 12:22:34,095 temboardagent[57828]: [probes] INFO: Loaded probe: replication_connection
2019-08-27 12:22:34,096 temboardagent[57828]: [probes] INFO: Loaded probe: db_size
2019-08-27 12:22:34,096 temboardagent[57828]: [probes] INFO: Loaded probe: tblspc_size
2019-08-27 12:22:34,096 temboardagent[57828]: [probes] INFO: Loaded probe: temp_files_size_delta
2019-08-27 12:22:34,096 temboardagent[57828]: [probes] INFO: Loaded probe: sessions
2019-08-27 12:22:34,096 temboardagent[57828]: [probes] INFO: Loaded probe: xacts
2019-08-27 12:22:34,097 temboardagent[57828]: [probes] INFO: Loaded probe: heap_bloat
2019-08-27 12:22:34,097 temboardagent[57828]: [probes] INFO: Loaded probe: loadavg
2019-08-27 12:22:34,097 temboardagent[57828]: [probes] INFO: Loaded probe: filesystems_size
2019-08-27 12:22:34,097 temboardagent[57828]: [probes] INFO: Loaded probe: cpu
2019-08-27 12:22:34,097 temboardagent[57828]: [probes] INFO: Loaded probe: bgwriter
2019-08-27 12:22:34,098 temboardagent[57828]: [probes] INFO: Loaded probe: memory
julmon commented 5 years ago

I'd see temboard-agent logs between 2019-08-26 11:50:47 CDT and 2019-08-26 11:57:08 CDT. Thanks

bsislow commented 5 years ago

Same thing; generally uneventful (see below).

2019-08-26 11:50:08,366 temboardagent[142556]: [probes] ERROR: Unable to run probe "btree_bloat" on "myhost" on database "mydb"
2019-08-26 11:50:11,336 temboardagent[142836]: [probes] INFO: Loaded probe: locks
2019-08-26 11:50:11,337 temboardagent[142836]: [probes] INFO: Loaded probe: btree_bloat
2019-08-26 11:50:11,337 temboardagent[142836]: [probes] INFO: Loaded probe: process
2019-08-26 11:50:11,337 temboardagent[142836]: [probes] INFO: Loaded probe: replication_lag
2019-08-26 11:50:11,337 temboardagent[142836]: [probes] INFO: Loaded probe: wal_files
2019-08-26 11:50:11,338 temboardagent[142836]: [probes] INFO: Loaded probe: blocks
2019-08-26 11:50:11,338 temboardagent[142836]: [probes] INFO: Loaded probe: replication_connection
2019-08-26 11:50:11,338 temboardagent[142836]: [probes] INFO: Loaded probe: db_size
2019-08-26 11:50:11,338 temboardagent[142836]: [probes] INFO: Loaded probe: tblspc_size
2019-08-26 11:50:11,338 temboardagent[142836]: [probes] INFO: Loaded probe: temp_files_size_delta
2019-08-26 11:50:11,338 temboardagent[142836]: [probes] INFO: Loaded probe: sessions
2019-08-26 11:50:11,339 temboardagent[142836]: [probes] INFO: Loaded probe: xacts
2019-08-26 11:50:11,339 temboardagent[142836]: [probes] INFO: Loaded probe: heap_bloat
2019-08-26 11:50:11,339 temboardagent[142836]: [probes] INFO: Loaded probe: loadavg
2019-08-26 11:50:11,339 temboardagent[142836]: [probes] INFO: Loaded probe: filesystems_size
2019-08-26 11:50:11,339 temboardagent[142836]: [probes] INFO: Loaded probe: cpu
2019-08-26 11:50:11,340 temboardagent[142836]: [probes] INFO: Loaded probe: bgwriter
2019-08-26 11:50:11,340 temboardagent[142836]: [probes] INFO: Loaded probe: memory
2019-08-26 11:51:11,638 temboardagent[142836]: [probes] ERROR: Unable to run probe "btree_bloat" on "myhost" on database "mydb"
2019-08-26 11:51:14,647 temboardagent[143057]: [probes] INFO: Loaded probe: locks
2019-08-26 11:51:14,648 temboardagent[143057]: [probes] INFO: Loaded probe: btree_bloat
2019-08-26 11:51:14,648 temboardagent[143057]: [probes] INFO: Loaded probe: process
2019-08-26 11:51:14,648 temboardagent[143057]: [probes] INFO: Loaded probe: replication_lag
2019-08-26 11:51:14,648 temboardagent[143057]: [probes] INFO: Loaded probe: wal_files
2019-08-26 11:51:14,649 temboardagent[143057]: [probes] INFO: Loaded probe: blocks
2019-08-26 11:51:14,649 temboardagent[143057]: [probes] INFO: Loaded probe: replication_connection
2019-08-26 11:51:14,649 temboardagent[143057]: [probes] INFO: Loaded probe: db_size
2019-08-26 11:51:14,649 temboardagent[143057]: [probes] INFO: Loaded probe: tblspc_size
2019-08-26 11:51:14,649 temboardagent[143057]: [probes] INFO: Loaded probe: temp_files_size_delta
2019-08-26 11:51:14,650 temboardagent[143057]: [probes] INFO: Loaded probe: sessions
2019-08-26 11:51:14,650 temboardagent[143057]: [probes] INFO: Loaded probe: xacts
2019-08-26 11:51:14,650 temboardagent[143057]: [probes] INFO: Loaded probe: heap_bloat
2019-08-26 11:51:14,650 temboardagent[143057]: [probes] INFO: Loaded probe: loadavg
2019-08-26 11:51:14,650 temboardagent[143057]: [probes] INFO: Loaded probe: filesystems_size
2019-08-26 11:51:14,650 temboardagent[143057]: [probes] INFO: Loaded probe: cpu
2019-08-26 11:51:14,651 temboardagent[143057]: [probes] INFO: Loaded probe: bgwriter
2019-08-26 11:51:14,651 temboardagent[143057]: [probes] INFO: Loaded probe: memory
2019-08-26 11:52:14,970 temboardagent[143057]: [probes] ERROR: Unable to run probe "btree_bloat" on "myhost" on database "mydb"
2019-08-26 11:52:18,160 temboardagent[143275]: [probes] INFO: Loaded probe: locks
2019-08-26 11:52:18,160 temboardagent[143275]: [probes] INFO: Loaded probe: btree_bloat
2019-08-26 11:52:18,160 temboardagent[143275]: [probes] INFO: Loaded probe: process
2019-08-26 11:52:18,161 temboardagent[143275]: [probes] INFO: Loaded probe: replication_lag
2019-08-26 11:52:18,161 temboardagent[143275]: [probes] INFO: Loaded probe: wal_files
2019-08-26 11:52:18,161 temboardagent[143275]: [probes] INFO: Loaded probe: blocks
2019-08-26 11:52:18,161 temboardagent[143275]: [probes] INFO: Loaded probe: replication_connection
2019-08-26 11:52:18,161 temboardagent[143275]: [probes] INFO: Loaded probe: db_size
2019-08-26 11:52:18,162 temboardagent[143275]: [probes] INFO: Loaded probe: tblspc_size
2019-08-26 11:52:18,162 temboardagent[143275]: [probes] INFO: Loaded probe: temp_files_size_delta
2019-08-26 11:52:18,162 temboardagent[143275]: [probes] INFO: Loaded probe: sessions
2019-08-26 11:52:18,162 temboardagent[143275]: [probes] INFO: Loaded probe: xacts
2019-08-26 11:52:18,162 temboardagent[143275]: [probes] INFO: Loaded probe: heap_bloat
2019-08-26 11:52:18,162 temboardagent[143275]: [probes] INFO: Loaded probe: loadavg
2019-08-26 11:52:18,163 temboardagent[143275]: [probes] INFO: Loaded probe: filesystems_size
2019-08-26 11:52:18,163 temboardagent[143275]: [probes] INFO: Loaded probe: cpu
2019-08-26 11:52:18,163 temboardagent[143275]: [probes] INFO: Loaded probe: bgwriter
2019-08-26 11:52:18,163 temboardagent[143275]: [probes] INFO: Loaded probe: memory
2019-08-26 11:53:18,456 temboardagent[143275]: [probes] ERROR: Unable to run probe "btree_bloat" on "myhost" on database "mydb"
2019-08-26 11:53:20,864 temboardagent[143488]: [probes] INFO: Loaded probe: locks
2019-08-26 11:53:20,865 temboardagent[143488]: [probes] INFO: Loaded probe: btree_bloat
2019-08-26 11:53:20,865 temboardagent[143488]: [probes] INFO: Loaded probe: process
2019-08-26 11:53:20,865 temboardagent[143488]: [probes] INFO: Loaded probe: replication_lag
2019-08-26 11:53:20,865 temboardagent[143488]: [probes] INFO: Loaded probe: wal_files
2019-08-26 11:53:20,866 temboardagent[143488]: [probes] INFO: Loaded probe: blocks
2019-08-26 11:53:20,866 temboardagent[143488]: [probes] INFO: Loaded probe: replication_connection
2019-08-26 11:53:20,866 temboardagent[143488]: [probes] INFO: Loaded probe: db_size
2019-08-26 11:53:20,866 temboardagent[143488]: [probes] INFO: Loaded probe: tblspc_size
2019-08-26 11:53:20,866 temboardagent[143488]: [probes] INFO: Loaded probe: temp_files_size_delta
2019-08-26 11:53:20,867 temboardagent[143488]: [probes] INFO: Loaded probe: sessions
2019-08-26 11:53:20,867 temboardagent[143488]: [probes] INFO: Loaded probe: xacts
2019-08-26 11:53:20,867 temboardagent[143488]: [probes] INFO: Loaded probe: heap_bloat
2019-08-26 11:53:20,867 temboardagent[143488]: [probes] INFO: Loaded probe: loadavg
2019-08-26 11:53:20,867 temboardagent[143488]: [probes] INFO: Loaded probe: filesystems_size
2019-08-26 11:53:20,867 temboardagent[143488]: [probes] INFO: Loaded probe: cpu
2019-08-26 11:53:20,868 temboardagent[143488]: [probes] INFO: Loaded probe: bgwriter
2019-08-26 11:53:20,868 temboardagent[143488]: [probes] INFO: Loaded probe: memory
2019-08-26 11:54:21,185 temboardagent[143488]: [probes] ERROR: Unable to run probe "btree_bloat" on "myhost" on database "mydb"
2019-08-26 11:54:23,876 temboardagent[143708]: [probes] INFO: Loaded probe: locks
2019-08-26 11:54:23,876 temboardagent[143708]: [probes] INFO: Loaded probe: btree_bloat
2019-08-26 11:54:23,877 temboardagent[143708]: [probes] INFO: Loaded probe: process
2019-08-26 11:54:23,877 temboardagent[143708]: [probes] INFO: Loaded probe: replication_lag
2019-08-26 11:54:23,877 temboardagent[143708]: [probes] INFO: Loaded probe: wal_files
2019-08-26 11:54:23,877 temboardagent[143708]: [probes] INFO: Loaded probe: blocks
2019-08-26 11:54:23,878 temboardagent[143708]: [probes] INFO: Loaded probe: replication_connection
2019-08-26 11:54:23,878 temboardagent[143708]: [probes] INFO: Loaded probe: db_size
2019-08-26 11:54:23,878 temboardagent[143708]: [probes] INFO: Loaded probe: tblspc_size
2019-08-26 11:54:23,878 temboardagent[143708]: [probes] INFO: Loaded probe: temp_files_size_delta
2019-08-26 11:54:23,878 temboardagent[143708]: [probes] INFO: Loaded probe: sessions
2019-08-26 11:54:23,879 temboardagent[143708]: [probes] INFO: Loaded probe: xacts
2019-08-26 11:54:23,879 temboardagent[143708]: [probes] INFO: Loaded probe: heap_bloat
2019-08-26 11:54:23,879 temboardagent[143708]: [probes] INFO: Loaded probe: loadavg
2019-08-26 11:54:23,879 temboardagent[143708]: [probes] INFO: Loaded probe: filesystems_size
2019-08-26 11:54:23,879 temboardagent[143708]: [probes] INFO: Loaded probe: cpu
2019-08-26 11:54:23,879 temboardagent[143708]: [probes] INFO: Loaded probe: bgwriter
2019-08-26 11:54:23,880 temboardagent[143708]: [probes] INFO: Loaded probe: memory
2019-08-26 11:55:24,174 temboardagent[143708]: [probes] ERROR: Unable to run probe "btree_bloat" on "myhost" on database "mydb"
2019-08-26 11:55:26,577 temboardagent[143921]: [probes] INFO: Loaded probe: locks
2019-08-26 11:55:26,578 temboardagent[143921]: [probes] INFO: Loaded probe: btree_bloat
2019-08-26 11:55:26,578 temboardagent[143921]: [probes] INFO: Loaded probe: process
2019-08-26 11:55:26,578 temboardagent[143921]: [probes] INFO: Loaded probe: replication_lag
2019-08-26 11:55:26,579 temboardagent[143921]: [probes] INFO: Loaded probe: wal_files
2019-08-26 11:55:26,579 temboardagent[143921]: [probes] INFO: Loaded probe: blocks
2019-08-26 11:55:26,579 temboardagent[143921]: [probes] INFO: Loaded probe: replication_connection
2019-08-26 11:55:26,579 temboardagent[143921]: [probes] INFO: Loaded probe: db_size
2019-08-26 11:55:26,579 temboardagent[143921]: [probes] INFO: Loaded probe: tblspc_size
2019-08-26 11:55:26,579 temboardagent[143921]: [probes] INFO: Loaded probe: temp_files_size_delta
2019-08-26 11:55:26,580 temboardagent[143921]: [probes] INFO: Loaded probe: sessions
2019-08-26 11:55:26,580 temboardagent[143921]: [probes] INFO: Loaded probe: xacts
2019-08-26 11:55:26,580 temboardagent[143921]: [probes] INFO: Loaded probe: heap_bloat
2019-08-26 11:55:26,580 temboardagent[143921]: [probes] INFO: Loaded probe: loadavg
2019-08-26 11:55:26,580 temboardagent[143921]: [probes] INFO: Loaded probe: filesystems_size
2019-08-26 11:55:26,581 temboardagent[143921]: [probes] INFO: Loaded probe: cpu
2019-08-26 11:55:26,581 temboardagent[143921]: [probes] INFO: Loaded probe: bgwriter
2019-08-26 11:55:26,581 temboardagent[143921]: [probes] INFO: Loaded probe: memory
2019-08-26 11:56:26,894 temboardagent[143921]: [probes] ERROR: Unable to run probe "btree_bloat" on "myhost" on database "mydb"
2019-08-26 11:56:29,894 temboardagent[144148]: [probes] INFO: Loaded probe: locks
2019-08-26 11:56:29,895 temboardagent[144148]: [probes] INFO: Loaded probe: btree_bloat
2019-08-26 11:56:29,895 temboardagent[144148]: [probes] INFO: Loaded probe: process
2019-08-26 11:56:29,895 temboardagent[144148]: [probes] INFO: Loaded probe: replication_lag
2019-08-26 11:56:29,895 temboardagent[144148]: [probes] INFO: Loaded probe: wal_files
2019-08-26 11:56:29,895 temboardagent[144148]: [probes] INFO: Loaded probe: blocks
2019-08-26 11:56:29,896 temboardagent[144148]: [probes] INFO: Loaded probe: replication_connection
2019-08-26 11:56:29,896 temboardagent[144148]: [probes] INFO: Loaded probe: db_size
2019-08-26 11:56:29,896 temboardagent[144148]: [probes] INFO: Loaded probe: tblspc_size
2019-08-26 11:56:29,896 temboardagent[144148]: [probes] INFO: Loaded probe: temp_files_size_delta
2019-08-26 11:56:29,896 temboardagent[144148]: [probes] INFO: Loaded probe: sessions
2019-08-26 11:56:29,897 temboardagent[144148]: [probes] INFO: Loaded probe: xacts
2019-08-26 11:56:29,897 temboardagent[144148]: [probes] INFO: Loaded probe: heap_bloat
2019-08-26 11:56:29,897 temboardagent[144148]: [probes] INFO: Loaded probe: loadavg
2019-08-26 11:56:29,897 temboardagent[144148]: [probes] INFO: Loaded probe: filesystems_size
2019-08-26 11:56:29,897 temboardagent[144148]: [probes] INFO: Loaded probe: cpu
2019-08-26 11:56:29,897 temboardagent[144148]: [probes] INFO: Loaded probe: bgwriter
2019-08-26 11:56:29,898 temboardagent[144148]: [probes] INFO: Loaded probe: memory
2019-08-26 11:57:30,197 temboardagent[144148]: [probes] ERROR: Unable to run probe "btree_bloat" on "myhost" on database "mydb"
2019-08-26 11:57:33,199 temboardagent[144361]: [probes] INFO: Loaded probe: locks
2019-08-26 11:57:33,200 temboardagent[144361]: [probes] INFO: Loaded probe: btree_bloat
2019-08-26 11:57:33,200 temboardagent[144361]: [probes] INFO: Loaded probe: process
2019-08-26 11:57:33,200 temboardagent[144361]: [probes] INFO: Loaded probe: replication_lag
2019-08-26 11:57:33,201 temboardagent[144361]: [probes] INFO: Loaded probe: wal_files
2019-08-26 11:57:33,201 temboardagent[144361]: [probes] INFO: Loaded probe: blocks
2019-08-26 11:57:33,201 temboardagent[144361]: [probes] INFO: Loaded probe: replication_connection
2019-08-26 11:57:33,201 temboardagent[144361]: [probes] INFO: Loaded probe: db_size
2019-08-26 11:57:33,201 temboardagent[144361]: [probes] INFO: Loaded probe: tblspc_size
2019-08-26 11:57:33,202 temboardagent[144361]: [probes] INFO: Loaded probe: temp_files_size_delta
2019-08-26 11:57:33,202 temboardagent[144361]: [probes] INFO: Loaded probe: sessions
2019-08-26 11:57:33,202 temboardagent[144361]: [probes] INFO: Loaded probe: xacts
2019-08-26 11:57:33,202 temboardagent[144361]: [probes] INFO: Loaded probe: heap_bloat
2019-08-26 11:57:33,202 temboardagent[144361]: [probes] INFO: Loaded probe: loadavg
2019-08-26 11:57:33,203 temboardagent[144361]: [probes] INFO: Loaded probe: filesystems_size
2019-08-26 11:57:33,203 temboardagent[144361]: [probes] INFO: Loaded probe: cpu
2019-08-26 11:57:33,203 temboardagent[144361]: [probes] INFO: Loaded probe: bgwriter
2019-08-26 11:57:33,203 temboardagent[144361]: [probes] INFO: Loaded probe: memory
bsislow commented 5 years ago

I'm fairly certain this temboard agent query is taking a very long time and possibly timing out? Could this be the cause? I've been monitoring it using temboard itself and it will run for over a minute - while on other instances in our environment is runs in far less time (<10 seconds or so):


SELECT current_database() AS dbname, CASE WHEN SUM(relpages) > SUM(est_pages_ff) THEN SUM(relpages-est_pages_ff)::FLOAT/SUM(relpages)::FLOAT*100 ELSE 0 END AS ratio FROM ( SELECT coalesce(1 + ceil(reltuples/floor((bs-pageopqdata-pagehdr)/(4+nulldatahdrwidth)::float)), 0 ) AS est_pages, coalesce(1 + ceil(reltuples/floor((bs-pageopqdata-pagehdr)*fillfactor/(100*(4+nulldatahdrwidth)::float))), 0 ) AS est_pages_ff, bs, nspname, table_oid, tblname, idxname, relpages, fillfactor, is_na FROM ( SELECT maxalign, bs, nspname, tblname, idxname, reltuples, relpages, relam, table_oid, fillfactor, ( index_tuple_hdr_bm + maxalign - CASE -- Add padding to the index tuple header to align on MAXALIGN WHEN index_tuple_hdr_bm%maxalign = 0 THEN maxalign ELSE index_tuple_hdr_bm%maxalign END + nulldatawidth + maxalign - CASE -- Add padding to the data to align on MAXALIGN WHEN nulldataw```
pgiraud commented 5 years ago

@bsislow Is it possible for you to run an explain analyze for this query?

cd /tmp
curl https://pastebin.com/raw/7t0hXW6z --output explain.sql
psql -qAt -f explain.sql > analyze.json
pgiraud commented 5 years ago

Ideally this should be done on the database for which you think the performance of this query is the worse (many tables and indexes).

bsislow commented 5 years ago

analyze.zip

pgiraud commented 5 years ago

This is very fast. As expected. Can you do the same for other databases on this postgres instance? Tip: use -d thedatabase in the psql command.

bsislow commented 5 years ago

analyze.zip above was simply for the default "postgres" database.

the following is for the database where performance suffers. there are many table shards (64), many children partitions (3968), and an index per shard (64). this may be hampering performance...?

analyze_2.zip

pgiraud commented 5 years ago

There's something strange in this execution plan that we don't understand. Would you mind execute the same EXPLAIN ANALYZE but in TEXT format instead? Here's a new pastebin for convenience: https://pastebin.com/raw/e96rruKR

bsislow commented 5 years ago
                                                                QUERY PLAN

---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=60040.95..60040.97 rows=1 width=72) (actual time=170339.352..170339.352 rows=1 loops=1)
   Output: current_database(), CASE WHEN ((sum(sq.relpages))::double precision > sum(COALESCE(('1'::double precision + ceil((sq.reltuples / floor((((((((current_setting('block_size'::text))
::numeric) - ((16))::numeric) - ((24))::numeric) * (sq.fillfactor)::numeric))::double precision / ('100'::double precision * (('4'::numeric + ((((((((CASE WHEN (max(COALESCE(s.null_frac, '0
'::real)) = '0'::double precision) THEN 2 ELSE 6 END) + (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END)) - CASE WHEN ((
(CASE WHEN (max(COALESCE(s.null_frac, '0'::real)) = '0'::double precision) THEN 2 ELSE 6 END) % (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::t
ext)) THEN 8 ELSE 4 END)) = 0) THEN (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END) ELSE ((CASE WHEN (max(COALESCE(s.nu
ll_frac, '0'::real)) = '0'::double precision) THEN 2 ELSE 6 END) % (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END)) END
))::double precision + (sum((('1'::double precision - COALESCE(s.null_frac, '0'::real)) * (COALESCE(s.avg_width, 1024))::double precision)))) + ((CASE WHEN ((version() ~ 'mingw32'::text) OR
 (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END))::double precision) - (CASE WHEN ((sum((('1'::double precision - COALESCE(s.null_frac, '0'::real)) * (COALESCE(s.av
g_width, 1024))::double precision))) = '0'::double precision) THEN 0 WHEN ((((sum((('1'::double precision - COALESCE(s.null_frac, '0'::real)) * (COALESCE(s.avg_width, 1024))::double precisi
on))))::integer % (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END)) = 0) THEN (CASE WHEN ((version() ~ 'mingw32'::text)
OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END) ELSE (((sum((('1'::double precision - COALESCE(s.null_frac, '0'::real)) * (COALESCE(s.avg_width, 1024))::double p
recision))))::integer % (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END)) END)::double precision))::numeric))::double pr
ecision)))))), '0'::double precision))) THEN ((sum(((sq.relpages)::double precision - COALESCE(('1'::double precision + ceil((sq.reltuples / floor((((((((current_setting('block_size'::text)
)::numeric) - ((16))::numeric) - ((24))::numeric) * (sq.fillfactor)::numeric))::double precision / ('100'::double precision * (('4'::numeric + ((((((((CASE WHEN (max(COALESCE(s.null_frac, '
0'::real)) = '0'::double precision) THEN 2 ELSE 6 END) + (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END)) - CASE WHEN (
((CASE WHEN (max(COALESCE(s.null_frac, '0'::real)) = '0'::double precision) THEN 2 ELSE 6 END) % (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::
text)) THEN 8 ELSE 4 END)) = 0) THEN (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END) ELSE ((CASE WHEN (max(COALESCE(s.n
ull_frac, '0'::real)) = '0'::double precision) THEN 2 ELSE 6 END) % (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END)) EN
D))::double precision + (sum((('1'::double precision - COALESCE(s.null_frac, '0'::real)) * (COALESCE(s.avg_width, 1024))::double precision)))) + ((CASE WHEN ((version() ~ 'mingw32'::text) O
R (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END))::double precision) - (CASE WHEN ((sum((('1'::double precision - COALESCE(s.null_frac, '0'::real)) * (COALESCE(s.a
vg_width, 1024))::double precision))) = '0'::double precision) THEN 0 WHEN ((((sum((('1'::double precision - COALESCE(s.null_frac, '0'::real)) * (COALESCE(s.avg_width, 1024))::double precis
ion))))::integer % (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END)) = 0) THEN (CASE WHEN ((version() ~ 'mingw32'::text)
 OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END) ELSE (((sum((('1'::double precision - COALESCE(s.null_frac, '0'::real)) * (COALESCE(s.avg_width, 1024))::double
precision))))::integer % (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END)) END)::double precision))::numeric))::double p
recision)))))), '0'::double precision))) / (sum(sq.relpages))::double precision) * '100'::double precision) ELSE '0'::double precision END
   Buffers: shared hit=223645
   ->  Hash Join  (cost=60038.91..60040.77 rows=1 width=68) (actual time=170309.805..170326.585 rows=3977 loops=1)
         Output: sq.relpages, sq.reltuples, ((current_setting('block_size'::text))::numeric), (16), (24), sq.fillfactor, (CASE WHEN (max(COALESCE(s.null_frac, '0'::real)) = '0'::double prec
ision) THEN 2 ELSE 6 END), (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END), (sum((('1'::double precision - COALESCE(s.n
ull_frac, '0'::real)) * (COALESCE(s.avg_width, 1024))::double precision)))
         Inner Unique: true
         Hash Cond: (sq.relam = am.oid)
         Buffers: shared hit=223645
         ->  GroupAggregate  (cost=60037.83..60039.38 rows=23 width=269) (actual time=170309.711..170325.601 rows=3977 loops=1)
               Output: sq.nspname, sq.tblname, sq.idxname, sq.reltuples, sq.relpages, sq.relam, sq.attrelid, ((current_setting('block_size'::text))::numeric), sq.fillfactor, CASE WHEN ((ver
sion() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END, 24, 16, CASE WHEN (max(COALESCE(s.null_frac, '0'::real)) = '0'::double precision) THEN
2 ELSE 6 END, sum((('1'::double precision - COALESCE(s.null_frac, '0'::real)) * (COALESCE(s.avg_width, 1024))::double precision)), NULL::boolean
               Group Key: sq.nspname, sq.tblname, sq.idxname, sq.reltuples, sq.relpages, sq.relam, sq.attrelid, ((current_setting('block_size'::text))::numeric), sq.fillfactor
               Buffers: shared hit=223644
               ->  Sort  (cost=60037.83..60037.88 rows=23 width=252) (actual time=170309.405..170309.720 rows=4032 loops=1)
                     Output: sq.nspname, sq.tblname, sq.idxname, sq.reltuples, sq.relpages, sq.relam, sq.attrelid, ((current_setting('block_size'::text))::numeric), sq.fillfactor, s.null_fr
ac, s.avg_width
                     Sort Key: sq.nspname, sq.tblname, sq.idxname, sq.reltuples, sq.relpages, sq.relam, sq.attrelid, sq.fillfactor
                     Sort Method: quicksort  Memory: 1168kB
                     Buffers: shared hit=223644
                     ->  Nested Loop  (cost=44832.31..60037.31 rows=23 width=252) (actual time=768.246..170300.695 rows=4032 loops=1)
                           Output: sq.nspname, sq.tblname, sq.idxname, sq.reltuples, sq.relpages, sq.relam, sq.attrelid, (current_setting('block_size'::text))::numeric, sq.fillfactor, s.nul
l_frac, s.avg_width
                           Inner Unique: true
                           Buffers: shared hit=223635
                           ->  Merge Join  (cost=44832.02..60029.40 rows=23 width=224) (actual time=768.200..170266.644 rows=4032 loops=1)
                                 Output: sq.nspname, sq.tblname, sq.idxname, sq.reltuples, sq.relpages, sq.relam, sq.attrelid, sq.fillfactor, sq.atttypid, s.null_frac, s.avg_width
                                 Merge Cond: (s.schemaname = sq.nspname)
                                 Join Filter: (((s.tablename = sq.tblname) AND ((s.attname)::text = pg_get_indexdef(sq.attrelid, (sq.attnum)::integer, true))) OR ((s.tablename = sq.idxname)
 AND (s.attname = sq.attname)))
                                 Rows Removed by Join Filter: 813056483
                                 Buffers: shared hit=215570
                                 ->  Sort  (cost=36484.07..36495.72 rows=4658 width=200) (actual time=422.313..480.242 rows=192836 loops=1)
                                       Output: s.null_frac, s.avg_width, s.schemaname, s.tablename, s.attname
                                       Sort Key: s.schemaname
                                       Sort Method: quicksort  Memory: 56536kB
                                       Buffers: shared hit=99381
                                       ->  Subquery Scan on s  (cost=9803.24..36200.27 rows=4658 width=200) (actual time=215.675..359.935 rows=192836 loops=1)
                                             Output: s.null_frac, s.avg_width, s.schemaname, s.tablename, s.attname
                                             Buffers: shared hit=99381
                                             ->  Gather  (cost=9803.24..36153.69 rows=4658 width=401) (actual time=215.674..352.397 rows=192836 loops=1)
                                                   Output: n.nspname, c.relname, a.attname, NULL::boolean, s_1.stanullfrac, s_1.stawidth, NULL::real, NULL::anyarray, NULL::real[], NULL::any
array, NULL::real, NULL::anyarray, NULL::real[], NULL::real[]
                                                   Workers Planned: 2
                                                   Workers Launched: 2
                                                   Buffers: shared hit=99381
                                                   ->  Hash Left Join  (cost=8803.24..34687.89 rows=1941 width=401) (actual time=207.039..319.017 rows=64279 loops=3)
                                                         Output: n.nspname, c.relname, a.attname, NULL::boolean, s_1.stanullfrac, s_1.stawidth, NULL::real, NULL::anyarray, NULL::real[], NUL
L::anyarray, NULL::real, NULL::anyarray, NULL::real[], NULL::real[]
                                                         Inner Unique: true
                                                         Hash Cond: (c.relnamespace = n.oid)
                                                         Buffers: shared hit=99381
                                                         Worker 0: actual time=204.014..349.926 rows=86155 loops=1
                                                           Buffers: shared hit=36381
                                                         Worker 1: actual time=203.572..349.966 rows=85609 loops=1
                                                           Buffers: shared hit=34989
                                                         ->  Parallel Hash Join  (cost=8802.11..34678.06 rows=1941 width=140) (actual time=207.002..306.173 rows=64279 loops=3)
                                                               Output: s_1.stanullfrac, s_1.stawidth, c.relname, c.relnamespace, a.attname
                                                               Hash Cond: ((s_1.starelid = c.oid) AND (s_1.staattnum = a.attnum))
                                                               Buffers: shared hit=99378
                                                               Worker 0: actual time=203.972..332.202 rows=86155 loops=1
                                                                 Buffers: shared hit=36380
                                                               Worker 1: actual time=203.532..332.299 rows=85609 loops=1
                                                                 Buffers: shared hit=34988
                                                               ->  Parallel Seq Scan on pg_catalog.pg_statistic s_1  (cost=0.00..25122.93 rows=74493 width=14) (actual time=0.005..30.552 row
s=64279 loops=3)
                                                                     Output: s_1.starelid, s_1.staattnum, s_1.stainherit, s_1.stanullfrac, s_1.stawidth, s_1.stadistinct, s_1.stakind1, s_1.s
takind2, s_1.stakind3, s_1.stakind4, s_1.stakind5, s_1.staop1, s_1.staop2, s_1.staop3, s_1.staop4, s_1.staop5, s_1.stanumbers1, s_1.stanumbers2, s_1.stanumbers3, s_1.stanumbers4, s_1.stanum
bers5, s_1.stavalues1, s_1.stavalues2, s_1.stavalues3, s_1.stavalues4, s_1.stavalues5
                                                                     Buffers: shared hit=24378
                                                                     Worker 0: actual time=0.006..39.530 rows=86155 loops=1
                                                                       Buffers: shared hit=10905
                                                                     Worker 1: actual time=0.006..39.385 rows=85609 loops=1
                                                                       Buffers: shared hit=10820
                                                               ->  Parallel Hash  (cost=8198.96..8198.96 rows=40210 width=142) (actual time=206.242..206.242 rows=96419 loops=3)
                                                                     Output: c.relname, c.oid, c.relnamespace, a.attname, a.attrelid, a.attnum
                                                                     Buckets: 524288 (originally 131072)  Batches: 1 (originally 1)  Memory Usage: 56992kB
                                                                     Buffers: shared hit=74875
                                                                     Worker 0: actual time=203.644..203.644 rows=99209 loops=1
                                                                       Buffers: shared hit=25414
                                                                     Worker 1: actual time=203.176..203.176 rows=93257 loops=1
                                                                       Buffers: shared hit=24107
                                                                     ->  Hash Join  (cost=1332.97..8198.96 rows=40210 width=142) (actual time=22.327..134.284 rows=96419 loops=3)
                                                                           Output: c.relname, c.oid, c.relnamespace, a.attname, a.attrelid, a.attnum
                                                                           Inner Unique: true
                                                                           Hash Cond: (a.attrelid = c.oid)
                                                                           Join Filter: has_column_privilege(c.oid, a.attnum, 'select'::text)
                                                                           Buffers: shared hit=74875
                                                                           Worker 0: actual time=22.247..132.342 rows=99209 loops=1
                                                                             Buffers: shared hit=25414
                                                                           Worker 1: actual time=22.376..132.298 rows=93257 loops=1
                                                                             Buffers: shared hit=24107
                                                                           ->  Parallel Seq Scan on pg_catalog.pg_attribute a  (cost=0.00..6549.30 rows=120630 width=70) (actual time=0.017..
39.731 rows=96419 loops=3)
                                                                                 Output: a.attrelid, a.attname, a.atttypid, a.attstattarget, a.attlen, a.attnum, a.attndims, a.attcacheoff, a
.atttypmod, a.attbyval, a.attstorage, a.attalign, a.attnotnull, a.atthasdef, a.atthasmissing, a.attidentity, a.attisdropped, a.attislocal, a.attinhcount, a.attcollation, a.attacl, a.attopti
ons, a.attfdwoptions, a.attmissingval
                                                                                 Filter: (NOT a.attisdropped)
                                                                                 Buffers: shared hit=5343
                                                                                 Worker 0: actual time=0.020..39.584 rows=99209 loops=1
                                                                                   Buffers: shared hit=1834
                                                                                 Worker 1: actual time=0.018..39.469 rows=93257 loops=1
                                                                                   Buffers: shared hit=1721
                                                                           ->  Hash  (cost=1101.49..1101.49 rows=18519 width=72) (actual time=22.042..22.042 rows=17371 loops=3)
                                                                                 Output: c.relname, c.oid, c.relnamespace
                                                                                 Buckets: 32768  Batches: 1  Memory Usage: 2021kB
                                                                                 Buffers: shared hit=2610
                                                                                 Worker 0: actual time=21.980..21.981 rows=17371 loops=1
                                                                                   Buffers: shared hit=870
                                                                                 Worker 1: actual time=22.081..22.081 rows=17371 loops=1
                                                                                   Buffers: shared hit=870
                                                                                 ->  Seq Scan on pg_catalog.pg_class c  (cost=0.00..1101.49 rows=18519 width=72) (actual time=0.007..15.270 r
ows=17371 loops=3)
                                                                                       Output: c.relname, c.oid, c.relnamespace
                                                                                       Filter: ((NOT c.relrowsecurity) OR (NOT row_security_active(c.oid)))
                                                                                       Buffers: shared hit=2610
                                                                                       Worker 0: actual time=0.007..15.521 rows=17371 loops=1
                                                                                         Buffers: shared hit=870
                                                                                       Worker 1: actual time=0.008..14.823 rows=17371 loops=1
                                                                                         Buffers: shared hit=870
                                                         ->  Hash  (cost=1.06..1.06 rows=6 width=68) (actual time=0.025..0.025 rows=6 loops=3)
                                                               Output: n.nspname, n.oid
                                                               Buckets: 1024  Batches: 1  Memory Usage: 9kB
                                                               Buffers: shared hit=3
                                                               Worker 0: actual time=0.030..0.030 rows=6 loops=1
                                                                 Buffers: shared hit=1
                                                               Worker 1: actual time=0.029..0.029 rows=6 loops=1
                                                                 Buffers: shared hit=1
                                                               ->  Seq Scan on pg_catalog.pg_namespace n  (cost=0.00..1.06 rows=6 width=68) (actual time=0.014..0.015 rows=6 loops=3)
                                                                     Output: n.nspname, n.oid
                                                                     Buffers: shared hit=3
                                                                     Worker 0: actual time=0.018..0.019 rows=6 loops=1
                                                                       Buffers: shared hit=1
                                                                     Worker 1: actual time=0.017..0.019 rows=6 loops=1
                                                                       Buffers: shared hit=1
                                 ->  Sort  (cost=8347.95..8398.07 rows=20047 width=282) (actual time=39.290..35051.869 rows=813060136 loops=1)
                                       Output: sq.nspname, sq.tblname, sq.idxname, sq.reltuples, sq.relpages, sq.relam, sq.attrelid, sq.fillfactor, sq.attnum, sq.attname, sq.atttypid
                                       Sort Key: sq.nspname
                                       Sort Method: quicksort  Memory: 2471kB
                                       Buffers: shared hit=31494
                                       ->  Subquery Scan on sq  (cost=6314.07..6915.48 rows=20047 width=282) (actual time=5.633..36.558 rows=4418 loops=1)
                                             Output: sq.nspname, sq.tblname, sq.idxname, sq.reltuples, sq.relpages, sq.relam, sq.attrelid, sq.fillfactor, sq.attnum, sq.attname, sq.atttypid
                                             Buffers: shared hit=31494
                                             ->  CTE Scan on q  (cost=6314.07..6715.01 rows=20047 width=453) (actual time=5.632..35.899 rows=4418 loops=1)
                                                   Output: q.nspname, q.tblname, q.idxname, q.reltuples, q.relpages, q.relam, NULL::oid, NULL::oid, q.fillfactor, q.attrelid, q.attname, q.at
ttypid, NULL::integer, NULL::smallint, q.attnum, NULL::integer, NULL::integer, NULL::integer, NULL::boolean, NULL::"char", NULL::"char", NULL::boolean, NULL::boolean, NULL::boolean, NULL::"
char", NULL::boolean, NULL::boolean, NULL::integer, NULL::oid, NULL::aclitem[], NULL::text[], NULL::text[], NULL::anyarray
                                                   Buffers: shared hit=31494
                                                   CTE q
                                                     ->  Nested Loop  (cost=1160.57..6314.07 rows=20047 width=454) (actual time=5.625..30.341 rows=4418 loops=1)
                                                           Output: pg_namespace.nspname, tbl.relname, idx.relname, idx.reltuples, idx.relpages, idx.relam, pg_index.indrelid, pg_index.indexr
elid, COALESCE((("substring"(array_to_string(idx.reloptions, ' '::text), 'fillfactor=([0-9]+)'::text))::smallint)::integer, 90), a_1.attrelid, a_1.attname, a_1.atttypid, a_1.attstattarget,
a_1.attlen, a_1.attnum, a_1.attndims, a_1.attcacheoff, a_1.atttypmod, a_1.attbyval, a_1.attstorage, a_1.attalign, a_1.attnotnull, a_1.atthasdef, a_1.atthasmissing, a_1.attidentity, a_1.atti
sdropped, a_1.attislocal, a_1.attinhcount, a_1.attcollation, a_1.attacl, a_1.attoptions, a_1.attfdwoptions, a_1.attmissingval
                                                           Buffers: shared hit=31494
                                                           ->  Hash Join  (cost=1160.15..2602.95 rows=1559 width=265) (actual time=5.581..19.496 rows=4341 loops=1)
                                                                 Output: pg_index.indrelid, pg_index.indexrelid, idx.relname, idx.reltuples, idx.relpages, idx.relam, idx.reloptions, idx.oid
, tbl.relname, pg_namespace.nspname
                                                                 Inner Unique: true
                                                                 Hash Cond: (idx.relnamespace = pg_namespace.oid)
                                                                 Buffers: shared hit=14102
                                                                 ->  Nested Loop  (cost=1159.01..2594.83 rows=1559 width=205) (actual time=5.545..18.331 rows=4341 loops=1)
                                                                       Output: pg_index.indrelid, pg_index.indexrelid, idx.relname, idx.reltuples, idx.relpages, idx.relam, idx.reloptions, i
dx.oid, idx.relnamespace, tbl.relname
                                                                       Inner Unique: true
                                                                       Buffers: shared hit=14101
                                                                       ->  Hash Join  (cost=1158.72..1462.46 rows=2169 width=72) (actual time=5.515..9.805 rows=4341 loops=1)
                                                                             Output: pg_index.indrelid, pg_index.indexrelid, tbl.relname
                                                                             Inner Unique: true
                                                                             Hash Cond: (pg_index.indrelid = tbl.oid)
                                                                             Buffers: shared hit=1063
                                                                             ->  Seq Scan on pg_catalog.pg_index  (cost=0.00..280.71 rows=8771 width=8) (actual time=0.005..2.700 rows=8649 l
oops=1)
                                                                                   Output: pg_index.indexrelid, pg_index.indrelid, pg_index.indnatts, pg_index.indnkeyatts, pg_index.indisuni
que, pg_index.indisprimary, pg_index.indisexclusion, pg_index.indimmediate, pg_index.indisclustered, pg_index.indisvalid, pg_index.indcheckxmin, pg_index.indisready, pg_index.indislive, pg_
index.indisreplident, pg_index.indkey, pg_index.indcollation, pg_index.indclass, pg_index.indoption, pg_index.indexprs, pg_index.indpred
                                                                                   Filter: pg_index.indisvalid
                                                                                   Buffers: shared hit=193
                                                                             ->  Hash  (cost=1101.49..1101.49 rows=4579 width=68) (actual time=5.444..5.444 rows=4295 loops=1)
                                                                                   Output: tbl.relname, tbl.oid
                                                                                   Buckets: 8192  Batches: 1  Memory Usage: 484kB
                                                                                   Buffers: shared hit=870
                                                                                   ->  Seq Scan on pg_catalog.pg_class tbl  (cost=0.00..1101.49 rows=4579 width=68) (actual time=0.005..4.574
 rows=4295 loops=1)
                                                                                         Output: tbl.relname, tbl.oid
                                                                                         Filter: (tbl.relkind = 'r'::"char")
                                                                                         Rows Removed by Filter: 13076
                                                                                         Buffers: shared hit=870
                                                                       ->  Index Scan using pg_class_oid_index on pg_catalog.pg_class idx  (cost=0.29..0.52 rows=1 width=133) (actual time=0.
002..0.002 rows=1 loops=4341)
                                                                             Output: idx.relname, idx.reltuples, idx.relpages, idx.relam, idx.reloptions, idx.oid, idx.relnamespace
                                                                             Index Cond: (idx.oid = pg_index.indexrelid)
                                                                             Filter: (idx.relpages > 0)
                                                                             Buffers: shared hit=13038
                                                                 ->  Hash  (cost=1.06..1.06 rows=6 width=68) (actual time=0.024..0.024 rows=6 loops=1)
                                                                       Output: pg_namespace.nspname, pg_namespace.oid
                                                                       Buckets: 1024  Batches: 1  Memory Usage: 9kB
                                                                       Buffers: shared hit=1
                                                                       ->  Seq Scan on pg_catalog.pg_namespace  (cost=0.00..1.06 rows=6 width=68) (actual time=0.018..0.020 rows=6 loops=1)
                                                                             Output: pg_namespace.nspname, pg_namespace.oid
                                                                             Buffers: shared hit=1
                                                           ->  Index Scan using pg_attribute_relid_attnum_index on pg_catalog.pg_attribute a_1  (cost=0.42..1.93 rows=29 width=238) (actual t
ime=0.002..0.002 rows=1 loops=4341)
                                                                 Output: a_1.attrelid, a_1.attname, a_1.atttypid, a_1.attstattarget, a_1.attlen, a_1.attnum, a_1.attndims, a_1.attcacheoff, a
_1.atttypmod, a_1.attbyval, a_1.attstorage, a_1.attalign, a_1.attnotnull, a_1.atthasdef, a_1.atthasmissing, a_1.attidentity, a_1.attisdropped, a_1.attislocal, a_1.attinhcount, a_1.attcollat
ion, a_1.attacl, a_1.attoptions, a_1.attfdwoptions, a_1.attmissingval
                                                                 Index Cond: ((a_1.attrelid = idx.oid) AND (a_1.attnum > 0))
                                                                 Buffers: shared hit=17392
                           ->  Index Only Scan using pg_type_oid_index on pg_catalog.pg_type t  (cost=0.29..0.34 rows=1 width=4) (actual time=0.003..0.003 rows=1 loops=4032)
                                 Output: t.oid
                                 Index Cond: (t.oid = sq.atttypid)
                                 Heap Fetches: 0
                                 Buffers: shared hit=8065
         ->  Hash  (cost=1.07..1.07 rows=1 width=4) (actual time=0.018..0.018 rows=1 loops=1)
               Output: am.oid
               Buckets: 1024  Batches: 1  Memory Usage: 9kB
               Buffers: shared hit=1
               ->  Seq Scan on pg_catalog.pg_am am  (cost=0.00..1.07 rows=1 width=4) (actual time=0.009..0.011 rows=1 loops=1)
                     Output: am.oid
                     Filter: (am.amname = 'btree'::name)
                     Rows Removed by Filter: 5
                     Buffers: shared hit=1
 Planning Time: 7.969 ms
 Execution Time: 170366.386 ms
(195 rows)
pgiraud commented 5 years ago

@bsislow May I ask you to do the same with the following request? https://pastebin.com/raw/yiRtt174 It contains the changes proposed in https://github.com/dalibo/temboard-agent/pull/352. This should drastically improve the performance.

bsislow commented 5 years ago

Unfortunately, it doesn't seem to be drastic...

                                                                QUERY PLAN

---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=60302.62..60302.65 rows=1 width=72) (actual time=157764.726..157764.726 rows=1 loops=1)
   Output: current_database(), CASE WHEN ((sum(sq.relpages))::double precision > sum(COALESCE(('1'::double precision + ceil((sq.reltuples / floor((((((((current_setting('block_size'::text))
::numeric) - ((16))::numeric) - ((24))::numeric) * (sq.fillfactor)::numeric))::double precision / ('100'::double precision * (('4'::numeric + ((((((((CASE WHEN (max(COALESCE(s.null_frac, '0
'::real)) = '0'::double precision) THEN 2 ELSE 6 END) + (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END)) - CASE WHEN ((
(CASE WHEN (max(COALESCE(s.null_frac, '0'::real)) = '0'::double precision) THEN 2 ELSE 6 END) % (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::t
ext)) THEN 8 ELSE 4 END)) = 0) THEN (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END) ELSE ((CASE WHEN (max(COALESCE(s.nu
ll_frac, '0'::real)) = '0'::double precision) THEN 2 ELSE 6 END) % (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END)) END
))::double precision + (sum((('1'::double precision - COALESCE(s.null_frac, '0'::real)) * (COALESCE(s.avg_width, 1024))::double precision)))) + ((CASE WHEN ((version() ~ 'mingw32'::text) OR
 (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END))::double precision) - (CASE WHEN ((sum((('1'::double precision - COALESCE(s.null_frac, '0'::real)) * (COALESCE(s.av
g_width, 1024))::double precision))) = '0'::double precision) THEN 0 WHEN ((((sum((('1'::double precision - COALESCE(s.null_frac, '0'::real)) * (COALESCE(s.avg_width, 1024))::double precisi
on))))::integer % (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END)) = 0) THEN (CASE WHEN ((version() ~ 'mingw32'::text)
OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END) ELSE (((sum((('1'::double precision - COALESCE(s.null_frac, '0'::real)) * (COALESCE(s.avg_width, 1024))::double p
recision))))::integer % (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END)) END)::double precision))::numeric))::double pr
ecision)))))), '0'::double precision))) THEN ((sum(((sq.relpages)::double precision - COALESCE(('1'::double precision + ceil((sq.reltuples / floor((((((((current_setting('block_size'::text)
)::numeric) - ((16))::numeric) - ((24))::numeric) * (sq.fillfactor)::numeric))::double precision / ('100'::double precision * (('4'::numeric + ((((((((CASE WHEN (max(COALESCE(s.null_frac, '
0'::real)) = '0'::double precision) THEN 2 ELSE 6 END) + (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END)) - CASE WHEN (
((CASE WHEN (max(COALESCE(s.null_frac, '0'::real)) = '0'::double precision) THEN 2 ELSE 6 END) % (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::
text)) THEN 8 ELSE 4 END)) = 0) THEN (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END) ELSE ((CASE WHEN (max(COALESCE(s.n
ull_frac, '0'::real)) = '0'::double precision) THEN 2 ELSE 6 END) % (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END)) EN
D))::double precision + (sum((('1'::double precision - COALESCE(s.null_frac, '0'::real)) * (COALESCE(s.avg_width, 1024))::double precision)))) + ((CASE WHEN ((version() ~ 'mingw32'::text) O
R (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END))::double precision) - (CASE WHEN ((sum((('1'::double precision - COALESCE(s.null_frac, '0'::real)) * (COALESCE(s.a
vg_width, 1024))::double precision))) = '0'::double precision) THEN 0 WHEN ((((sum((('1'::double precision - COALESCE(s.null_frac, '0'::real)) * (COALESCE(s.avg_width, 1024))::double precis
ion))))::integer % (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END)) = 0) THEN (CASE WHEN ((version() ~ 'mingw32'::text)
 OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END) ELSE (((sum((('1'::double precision - COALESCE(s.null_frac, '0'::real)) * (COALESCE(s.avg_width, 1024))::double
precision))))::integer % (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END)) END)::double precision))::numeric))::double p
recision)))))), '0'::double precision))) / (sum(sq.relpages))::double precision) * '100'::double precision) ELSE '0'::double precision END
   Buffers: shared hit=233910 read=15
   ->  Hash Join  (cost=60300.43..60302.44 rows=1 width=68) (actual time=157738.241..157753.135 rows=4025 loops=1)
         Output: sq.relpages, sq.reltuples, ((current_setting('block_size'::text))::numeric), (16), (24), sq.fillfactor, (CASE WHEN (max(COALESCE(s.null_frac, '0'::real)) = '0'::double prec
ision) THEN 2 ELSE 6 END), (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END), (sum((('1'::double precision - COALESCE(s.n
ull_frac, '0'::real)) * (COALESCE(s.avg_width, 1024))::double precision)))
         Inner Unique: true
         Hash Cond: (sq.relam = am.oid)
         Buffers: shared hit=233910 read=15
         ->  GroupAggregate  (cost=60299.34..60301.03 rows=25 width=269) (actual time=157738.146..157752.140 rows=4025 loops=1)
               Output: sq.nspname, sq.tblname, sq.idxname, sq.reltuples, sq.relpages, sq.relam, sq.attrelid, ((current_setting('block_size'::text))::numeric), sq.fillfactor, CASE WHEN ((ver
sion() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE 4 END, 24, 16, CASE WHEN (max(COALESCE(s.null_frac, '0'::real)) = '0'::double precision) THEN
2 ELSE 6 END, sum((('1'::double precision - COALESCE(s.null_frac, '0'::real)) * (COALESCE(s.avg_width, 1024))::double precision)), NULL::boolean
               Group Key: sq.nspname, sq.tblname, sq.idxname, sq.reltuples, sq.relpages, sq.relam, sq.attrelid, ((current_setting('block_size'::text))::numeric), sq.fillfactor
               Buffers: shared hit=233909 read=15
               ->  Sort  (cost=60299.34..60299.40 rows=25 width=252) (actual time=157737.859..157738.133 rows=4080 loops=1)
                     Output: sq.nspname, sq.tblname, sq.idxname, sq.reltuples, sq.relpages, sq.relam, sq.attrelid, ((current_setting('block_size'::text))::numeric), sq.fillfactor, s.null_fr
ac, s.avg_width
                     Sort Key: sq.nspname, sq.tblname, sq.idxname, sq.reltuples, sq.relpages, sq.relam, sq.attrelid, sq.fillfactor
                     Sort Method: quicksort  Memory: 1180kB
                     Buffers: shared hit=233909 read=15
                     ->  Nested Loop  (cost=46670.92..60298.76 rows=25 width=252) (actual time=669.159..157732.917 rows=4080 loops=1)
                           Output: sq.nspname, sq.tblname, sq.idxname, sq.reltuples, sq.relpages, sq.relam, sq.attrelid, (current_setting('block_size'::text))::numeric, sq.fillfactor, s.nul
l_frac, s.avg_width
                           Inner Unique: true
                           Buffers: shared hit=233900 read=15
                           ->  Merge Join  (cost=46670.64..60290.17 rows=25 width=224) (actual time=669.115..157718.136 rows=4080 loops=1)
                                 Output: sq.nspname, sq.tblname, sq.idxname, sq.reltuples, sq.relpages, sq.relam, sq.attrelid, sq.fillfactor, sq.atttypid, s.null_frac, s.avg_width
                                 Merge Cond: (s.schemaname = sq.nspname)
                                 Join Filter: (((s.tablename = sq.tblname) AND ((s.attname)::text = sq.indexdef)) OR ((s.tablename = sq.idxname) AND (s.attname = sq.attname)))
                                 Rows Removed by Join Filter: 836241112
                                 Buffers: shared hit=225739 read=15
                                 ->  Sort  (cost=38222.45..38234.78 rows=4932 width=200) (actual time=412.446..463.698 rows=198308 loops=1)
                                       Output: s.null_frac, s.avg_width, s.schemaname, s.tablename, s.attname
                                       Sort Key: s.schemaname
                                       Sort Method: quicksort  Memory: 57990kB
                                       Buffers: shared hit=103228 read=6
                                       ->  Subquery Scan on s  (cost=9803.24..37919.92 rows=4932 width=200) (actual time=212.498..353.714 rows=198308 loops=1)
                                             Output: s.null_frac, s.avg_width, s.schemaname, s.tablename, s.attname
                                             Buffers: shared hit=103228 read=6
                                             ->  Gather  (cost=9803.24..37870.60 rows=4932 width=401) (actual time=212.497..344.826 rows=198308 loops=1)
                                                   Output: n.nspname, c.relname, a.attname, NULL::boolean, s_1.stanullfrac, s_1.stawidth, NULL::real, NULL::anyarray, NULL::real[], NULL::any
array, NULL::real, NULL::anyarray, NULL::real[], NULL::real[]
                                                   Workers Planned: 2
                                                   Workers Launched: 2
                                                   Buffers: shared hit=103228 read=6
                                                   ->  Hash Left Join  (cost=8803.24..36377.40 rows=2055 width=401) (actual time=203.769..307.803 rows=66103 loops=3)
                                                         Output: n.nspname, c.relname, a.attname, NULL::boolean, s_1.stanullfrac, s_1.stawidth, NULL::real, NULL::anyarray, NULL::real[], NUL
L::anyarray, NULL::real, NULL::anyarray, NULL::real[], NULL::real[]
                                                         Inner Unique: true
                                                         Hash Cond: (c.relnamespace = n.oid)
                                                         Buffers: shared hit=103228 read=6
                                                         Worker 0: actual time=200.245..336.161 rows=90901 loops=1
                                                           Buffers: shared hit=36043
                                                         Worker 1: actual time=200.719..337.182 rows=90686 loops=1
                                                           Buffers: shared hit=36264
                                                         ->  Parallel Hash Join  (cost=8802.11..36367.07 rows=2055 width=140) (actual time=203.734..294.884 rows=66103 loops=3)
                                                               Output: s_1.stanullfrac, s_1.stawidth, c.relname, c.relnamespace, a.attname
                                                               Hash Cond: ((s_1.starelid = c.oid) AND (s_1.staattnum = a.attnum))
                                                               Buffers: shared hit=103225 read=6
                                                               Worker 0: actual time=200.203..318.646 rows=90901 loops=1
                                                                 Buffers: shared hit=36042
                                                               Worker 1: actual time=200.680..319.683 rows=90686 loops=1
                                                                 Buffers: shared hit=36263
                                                               ->  Parallel Seq Scan on pg_catalog.pg_statistic s_1  (cost=0.00..26767.70 rows=78870 width=14) (actual time=0.006..30.520 row
s=66108 loops=3)
                                                                     Output: s_1.starelid, s_1.staattnum, s_1.stainherit, s_1.stanullfrac, s_1.stawidth, s_1.stadistinct, s_1.stakind1, s_1.s
takind2, s_1.stakind3, s_1.stakind4, s_1.stakind5, s_1.staop1, s_1.staop2, s_1.staop3, s_1.staop4, s_1.staop5, s_1.stanumbers1, s_1.stanumbers2, s_1.stanumbers3, s_1.stanumbers4, s_1.stanum
bers5, s_1.stavalues1, s_1.stavalues2, s_1.stavalues3, s_1.stavalues4, s_1.stavalues5
                                                                     Buffers: shared hit=25979
                                                                     Worker 0: actual time=0.006..39.728 rows=90901 loops=1
                                                                       Buffers: shared hit=11868
                                                                     Worker 1: actual time=0.005..39.823 rows=90691 loops=1
                                                                       Buffers: shared hit=11867
                                                               ->  Parallel Hash  (cost=8198.96..8198.96 rows=40210 width=142) (actual time=203.002..203.002 rows=96231 loops=3)
                                                                     Output: c.relname, c.oid, c.relnamespace, a.attname, a.attrelid, a.attnum
                                                                     Buckets: 524288 (originally 131072)  Batches: 1 (originally 1)  Memory Usage: 56896kB
                                                                     Buffers: shared hit=77161 read=6
                                                                     Worker 0: actual time=199.968..199.968 rows=93462 loops=1
                                                                       Buffers: shared hit=24133
                                                                     Worker 1: actual time=200.440..200.440 rows=93381 loops=1
                                                                       Buffers: shared hit=24355
                                                                     ->  Hash Join  (cost=1332.97..8198.96 rows=40210 width=142) (actual time=23.691..136.067 rows=96231 loops=3)
                                                                           Output: c.relname, c.oid, c.relnamespace, a.attname, a.attrelid, a.attnum
                                                                           Inner Unique: true
                                                                           Hash Cond: (a.attrelid = c.oid)
                                                                           Join Filter: has_column_privilege(c.oid, a.attnum, 'select'::text)
                                                                           Rows Removed by Join Filter: 188
                                                                           Buffers: shared hit=77161 read=6
                                                                           Worker 0: actual time=23.900..133.662 rows=93462 loops=1
                                                                             Buffers: shared hit=24133
                                                                           Worker 1: actual time=24.367..134.121 rows=93381 loops=1
                                                                             Buffers: shared hit=24355
                                                                           ->  Parallel Seq Scan on pg_catalog.pg_attribute a  (cost=0.00..6549.30 rows=120630 width=70) (actual time=0.017..
37.640 rows=96419 loops=3)
                                                                                 Output: a.attrelid, a.attname, a.atttypid, a.attstattarget, a.attlen, a.attnum, a.attndims, a.attcacheoff, a
.atttypmod, a.attbyval, a.attstorage, a.attalign, a.attnotnull, a.atthasdef, a.atthasmissing, a.attidentity, a.attisdropped, a.attislocal, a.attinhcount, a.attcollation, a.attacl, a.attopti
ons, a.attfdwoptions, a.attmissingval
                                                                                 Filter: (NOT a.attisdropped)
                                                                                 Buffers: shared hit=5343
                                                                                 Worker 0: actual time=0.018..36.935 rows=93462 loops=1
                                                                                   Buffers: shared hit=1725
                                                                                 Worker 1: actual time=0.022..36.944 rows=93381 loops=1
                                                                                   Buffers: shared hit=1725
                                                                           ->  Hash  (cost=1101.49..1101.49 rows=18519 width=72) (actual time=23.411..23.411 rows=17371 loops=3)
                                                                                 Output: c.relname, c.oid, c.relnamespace
                                                                                 Buckets: 32768  Batches: 1  Memory Usage: 2021kB
                                                                                 Buffers: shared hit=2610
                                                                                 Worker 0: actual time=23.623..23.624 rows=17371 loops=1
                                                                                   Buffers: shared hit=870
                                                                                 Worker 1: actual time=24.078..24.078 rows=17371 loops=1
                                                                                   Buffers: shared hit=870
                                                                                 ->  Seq Scan on pg_catalog.pg_class c  (cost=0.00..1101.49 rows=18519 width=72) (actual time=0.008..16.584 r
ows=17371 loops=3)
                                                                                       Output: c.relname, c.oid, c.relnamespace
                                                                                       Filter: ((NOT c.relrowsecurity) OR (NOT row_security_active(c.oid)))
                                                                                       Buffers: shared hit=2610
                                                                                       Worker 0: actual time=0.008..16.572 rows=17371 loops=1
                                                                                         Buffers: shared hit=870
                                                                                       Worker 1: actual time=0.008..17.080 rows=17371 loops=1
                                                                                         Buffers: shared hit=870
                                                         ->  Hash  (cost=1.06..1.06 rows=6 width=68) (actual time=0.024..0.024 rows=6 loops=3)
                                                               Output: n.nspname, n.oid
                                                               Buckets: 1024  Batches: 1  Memory Usage: 9kB
                                                               Buffers: shared hit=3
                                                               Worker 0: actual time=0.032..0.032 rows=6 loops=1
                                                                 Buffers: shared hit=1
                                                               Worker 1: actual time=0.027..0.027 rows=6 loops=1
                                                                 Buffers: shared hit=1
                                                               ->  Seq Scan on pg_catalog.pg_namespace n  (cost=0.00..1.06 rows=6 width=68) (actual time=0.012..0.013 rows=6 loops=3)
                                                                     Output: n.nspname, n.oid
                                                                     Buffers: shared hit=3
                                                                     Worker 0: actual time=0.015..0.016 rows=6 loops=1
                                                                       Buffers: shared hit=1
                                                                     Worker 1: actual time=0.016..0.017 rows=6 loops=1
                                                                       Buffers: shared hit=1
                                 ->  Sort  (cost=8448.19..8498.30 rows=20047 width=312) (actual time=254.794..34880.420 rows=836244824 loops=1)
                                       Output: sq.nspname, sq.tblname, sq.idxname, sq.reltuples, sq.relpages, sq.relam, sq.attrelid, sq.fillfactor, sq.indexdef, sq.attname, sq.atttypid
                                       Sort Key: sq.nspname
                                       Sort Method: quicksort  Memory: 2471kB
                                       Buffers: shared hit=122511 read=9
                                       ->  Subquery Scan on sq  (cost=6414.31..7015.72 rows=20047 width=312) (actual time=6.128..251.529 rows=4418 loops=1)
                                             Output: sq.nspname, sq.tblname, sq.idxname, sq.reltuples, sq.relpages, sq.relam, sq.attrelid, sq.fillfactor, sq.indexdef, sq.attname, sq.atttypi
d
                                             Buffers: shared hit=122511 read=9
                                             ->  CTE Scan on q  (cost=6414.31..6815.25 rows=20047 width=485) (actual time=6.126..250.484 rows=4418 loops=1)
                                                   Output: q.nspname, q.tblname, q.idxname, q.reltuples, q.relpages, q.relam, NULL::oid, NULL::oid, q.fillfactor, q.attrelid, q.attname, q.at
ttypid, NULL::integer, NULL::smallint, NULL::smallint, NULL::integer, NULL::integer, NULL::integer, NULL::boolean, NULL::"char", NULL::"char", NULL::boolean, NULL::boolean, NULL::boolean, N
ULL::"char", NULL::boolean, NULL::boolean, NULL::integer, NULL::oid, NULL::aclitem[], NULL::text[], NULL::text[], NULL::anyarray, q.indexdef
                                                   Buffers: shared hit=122511 read=9
                                                   CTE q
                                                     ->  Nested Loop  (cost=1160.57..6414.31 rows=20047 width=486) (actual time=6.119..242.439 rows=4418 loops=1)
                                                           Output: pg_namespace.nspname, tbl.relname, idx.relname, idx.reltuples, idx.relpages, idx.relam, pg_index.indrelid, pg_index.indexr
elid, COALESCE((("substring"(array_to_string(idx.reloptions, ' '::text), 'fillfactor=([0-9]+)'::text))::smallint)::integer, 90), a_1.attrelid, a_1.attname, a_1.atttypid, a_1.attstattarget,
a_1.attlen, a_1.attnum, a_1.attndims, a_1.attcacheoff, a_1.atttypmod, a_1.attbyval, a_1.attstorage, a_1.attalign, a_1.attnotnull, a_1.atthasdef, a_1.atthasmissing, a_1.attidentity, a_1.atti
sdropped, a_1.attislocal, a_1.attinhcount, a_1.attcollation, a_1.attacl, a_1.attoptions, a_1.attfdwoptions, a_1.attmissingval, pg_get_indexdef(a_1.attrelid, (a_1.attnum)::integer, true)
                                                           Buffers: shared hit=122511 read=9
                                                           ->  Hash Join  (cost=1160.15..2602.95 rows=1559 width=265) (actual time=6.032..23.901 rows=4341 loops=1)
                                                                 Output: pg_index.indrelid, pg_index.indexrelid, idx.relname, idx.reltuples, idx.relpages, idx.relam, idx.reloptions, idx.oid
, tbl.relname, pg_namespace.nspname
                                                                 Inner Unique: true
                                                                 Hash Cond: (idx.relnamespace = pg_namespace.oid)
                                                                 Buffers: shared hit=14102
                                                                 ->  Nested Loop  (cost=1159.01..2594.83 rows=1559 width=205) (actual time=6.003..22.130 rows=4341 loops=1)
                                                                       Output: pg_index.indrelid, pg_index.indexrelid, idx.relname, idx.reltuples, idx.relpages, idx.relam, idx.reloptions, i
dx.oid, idx.relnamespace, tbl.relname
                                                                       Inner Unique: true
                                                                       Buffers: shared hit=14101
                                                                       ->  Hash Join  (cost=1158.72..1462.46 rows=2169 width=72) (actual time=5.979..11.746 rows=4341 loops=1)
                                                                             Output: pg_index.indrelid, pg_index.indexrelid, tbl.relname
                                                                             Inner Unique: true
                                                                             Hash Cond: (pg_index.indrelid = tbl.oid)
                                                                             Buffers: shared hit=1063
                                                                             ->  Seq Scan on pg_catalog.pg_index  (cost=0.00..280.71 rows=8771 width=8) (actual time=0.004..3.355 rows=8649 l
oops=1)
                                                                                   Output: pg_index.indexrelid, pg_index.indrelid, pg_index.indnatts, pg_index.indnkeyatts, pg_index.indisuni
que, pg_index.indisprimary, pg_index.indisexclusion, pg_index.indimmediate, pg_index.indisclustered, pg_index.indisvalid, pg_index.indcheckxmin, pg_index.indisready, pg_index.indislive, pg_
index.indisreplident, pg_index.indkey, pg_index.indcollation, pg_index.indclass, pg_index.indoption, pg_index.indexprs, pg_index.indpred
                                                                                   Filter: pg_index.indisvalid
                                                                                   Buffers: shared hit=193
                                                                             ->  Hash  (cost=1101.49..1101.49 rows=4579 width=68) (actual time=5.923..5.923 rows=4295 loops=1)
                                                                                   Output: tbl.relname, tbl.oid
                                                                                   Buckets: 8192  Batches: 1  Memory Usage: 484kB
                                                                                   Buffers: shared hit=870
                                                                                   ->  Seq Scan on pg_catalog.pg_class tbl  (cost=0.00..1101.49 rows=4579 width=68) (actual time=0.006..5.133
 rows=4295 loops=1)
                                                                                         Output: tbl.relname, tbl.oid
                                                                                         Filter: (tbl.relkind = 'r'::"char")
                                                                                         Rows Removed by Filter: 13076
                                                                                         Buffers: shared hit=870
                                                                       ->  Index Scan using pg_class_oid_index on pg_catalog.pg_class idx  (cost=0.29..0.52 rows=1 width=133) (actual time=0.
002..0.002 rows=1 loops=4341)
                                                                             Output: idx.relname, idx.reltuples, idx.relpages, idx.relam, idx.reloptions, idx.oid, idx.relnamespace
                                                                             Index Cond: (idx.oid = pg_index.indexrelid)
                                                                             Filter: (idx.relpages > 0)
                                                                             Buffers: shared hit=13038
                                                                 ->  Hash  (cost=1.06..1.06 rows=6 width=68) (actual time=0.020..0.020 rows=6 loops=1)
                                                                       Output: pg_namespace.nspname, pg_namespace.oid
                                                                       Buckets: 1024  Batches: 1  Memory Usage: 9kB
                                                                       Buffers: shared hit=1
                                                                       ->  Seq Scan on pg_catalog.pg_namespace  (cost=0.00..1.06 rows=6 width=68) (actual time=0.016..0.017 rows=6 loops=1)
                                                                             Output: pg_namespace.nspname, pg_namespace.oid
                                                                             Buffers: shared hit=1
                                                           ->  Index Scan using pg_attribute_relid_attnum_index on pg_catalog.pg_attribute a_1  (cost=0.42..1.93 rows=29 width=238) (actual t
ime=0.002..0.003 rows=1 loops=4341)
                                                                 Output: a_1.attrelid, a_1.attname, a_1.atttypid, a_1.attstattarget, a_1.attlen, a_1.attnum, a_1.attndims, a_1.attcacheoff, a
_1.atttypmod, a_1.attbyval, a_1.attstorage, a_1.attalign, a_1.attnotnull, a_1.atthasdef, a_1.atthasmissing, a_1.attidentity, a_1.attisdropped, a_1.attislocal, a_1.attinhcount, a_1.attcollat
ion, a_1.attacl, a_1.attoptions, a_1.attfdwoptions, a_1.attmissingval
                                                                 Index Cond: ((a_1.attrelid = idx.oid) AND (a_1.attnum > 0))
                                                                 Buffers: shared hit=17392
                           ->  Index Only Scan using pg_type_oid_index on pg_catalog.pg_type t  (cost=0.29..0.34 rows=1 width=4) (actual time=0.002..0.002 rows=1 loops=4080)
                                 Output: t.oid
                                 Index Cond: (t.oid = sq.atttypid)
                                 Heap Fetches: 0
                                 Buffers: shared hit=8161
         ->  Hash  (cost=1.07..1.07 rows=1 width=4) (actual time=0.023..0.023 rows=1 loops=1)
               Output: am.oid
               Buckets: 1024  Batches: 1  Memory Usage: 9kB
               Buffers: shared hit=1
               ->  Seq Scan on pg_catalog.pg_am am  (cost=0.00..1.07 rows=1 width=4) (actual time=0.009..0.011 rows=1 loops=1)
                     Output: am.oid
                     Filter: (am.amname = 'btree'::name)
                     Rows Removed by Filter: 5
                     Buffers: shared hit=1
 Planning Time: 7.811 ms
 Execution Time: 157782.985 ms
(196 rows)
pgiraud commented 5 years ago

@bsislow we're having a lot of troubles understanding this execution plan. There's a Sort node returning more than 800,000,000 rows. That's weird. https://explain.depesz.com/s/c0Ht#l17

In order for us to better understand what happens, could you please help us either build a reproducible environnement? Please send us (by mail at pierre.giraud@dalibo.com) the schema without data.

pg_dump --schema-only $database

Or even better would be to help us build a similar database.

bsislow commented 5 years ago

Emailed pg_dump output to you.

pgiraud commented 5 years ago

@bsislow: @ioguix from Dalibo rewrote the query and we now have a much better performance. We're very confident but we want to ask to have a try once again to confirm this. Can you please run the following SQL script on your large database?

https://pastebin.com/mJRdAL3s

bsislow commented 5 years ago

It seems better; comes back instantly:

Planning Time: 5.737 ms Execution Time: 290.555 ms

                                                                                                                             QUERY PLAN

---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-----------------------------------------------------------------------
 Subquery Scan on rows_data_stats  (cost=69152.95..69364.28 rows=386 width=349) (actual time=258.256..289.351 rows=4084 loops=1)
   Output: current_database(), rows_data_stats.nspname, rows_data_stats.tblname, rows_data_stats.idxname, (rows_data_stats.bs * ((rows_data_stats.relpages)::bigint)::numeric), (rows_data_st
ats.bs * ((((rows_data_stats.relpages)::double precision - COALESCE(('1'::double precision + ceil((rows_data_stats.reltuples / floor(((((rows_data_stats.bs - (rows_data_stats.pageopqdata)::
numeric) - (rows_data_stats.pagehdr)::numeric))::double precision / (('4'::numeric + (((((((rows_data_stats.index_tuple_hdr_bm + rows_data_stats.maxalign) - CASE WHEN ((rows_data_stats.inde
x_tuple_hdr_bm % rows_data_stats.maxalign) = 0) THEN rows_data_stats.maxalign ELSE (rows_data_stats.index_tuple_hdr_bm % rows_data_stats.maxalign) END))::double precision + rows_data_stats.
nulldatawidth) + (rows_data_stats.maxalign)::double precision) - (CASE WHEN (rows_data_stats.nulldatawidth = '0'::double precision) THEN 0 WHEN (((rows_data_stats.nulldatawidth)::integer %
rows_data_stats.maxalign) = 0) THEN rows_data_stats.maxalign ELSE ((rows_data_stats.nulldatawidth)::integer % rows_data_stats.maxalign) END)::double precision))::numeric))::double precision
))))), '0'::double precision)))::bigint)::numeric), (('100'::double precision * ((rows_data_stats.relpages)::double precision - COALESCE(('1'::double precision + ceil((rows_data_stats.reltu
ples / floor(((((rows_data_stats.bs - (rows_data_stats.pageopqdata)::numeric) - (rows_data_stats.pagehdr)::numeric))::double precision / (('4'::numeric + (((((((rows_data_stats.index_tuple_
hdr_bm + rows_data_stats.maxalign) - CASE WHEN ((rows_data_stats.index_tuple_hdr_bm % rows_data_stats.maxalign) = 0) THEN rows_data_stats.maxalign ELSE (rows_data_stats.index_tuple_hdr_bm %
 rows_data_stats.maxalign) END))::double precision + rows_data_stats.nulldatawidth) + (rows_data_stats.maxalign)::double precision) - (CASE WHEN (rows_data_stats.nulldatawidth = '0'::double
 precision) THEN 0 WHEN (((rows_data_stats.nulldatawidth)::integer % rows_data_stats.maxalign) = 0) THEN rows_data_stats.maxalign ELSE ((rows_data_stats.nulldatawidth)::integer % rows_data_
stats.maxalign) END)::double precision))::numeric))::double precision))))), '0'::double precision))) / (rows_data_stats.relpages)::double precision), rows_data_stats.fillfactor, CASE WHEN (
(rows_data_stats.relpages)::double precision > COALESCE(('1'::double precision + ceil((rows_data_stats.reltuples / floor((((((rows_data_stats.bs - (rows_data_stats.pageopqdata)::numeric) -
(rows_data_stats.pagehdr)::numeric) * (rows_data_stats.fillfactor)::numeric))::double precision / ('100'::double precision * (('4'::numeric + (((((((rows_data_stats.index_tuple_hdr_bm + row
s_data_stats.maxalign) - CASE WHEN ((rows_data_stats.index_tuple_hdr_bm % rows_data_stats.maxalign) = 0) THEN rows_data_stats.maxalign ELSE (rows_data_stats.index_tuple_hdr_bm % rows_data_s
tats.maxalign) END))::double precision + rows_data_stats.nulldatawidth) + (rows_data_stats.maxalign)::double precision) - (CASE WHEN (rows_data_stats.nulldatawidth = '0'::double precision)
THEN 0 WHEN (((rows_data_stats.nulldatawidth)::integer % rows_data_stats.maxalign) = 0) THEN rows_data_stats.maxalign ELSE ((rows_data_stats.nulldatawidth)::integer % rows_data_stats.maxali
gn) END)::double precision))::numeric))::double precision)))))), '0'::double precision)) THEN ((rows_data_stats.bs)::double precision * ((rows_data_stats.relpages)::double precision - COALE
SCE(('1'::double precision + ceil((rows_data_stats.reltuples / floor((((((rows_data_stats.bs - (rows_data_stats.pageopqdata)::numeric) - (rows_data_stats.pagehdr)::numeric) * (rows_data_sta
ts.fillfactor)::numeric))::double precision / ('100'::double precision * (('4'::numeric + (((((((rows_data_stats.index_tuple_hdr_bm + rows_data_stats.maxalign) - CASE WHEN ((rows_data_stats
.index_tuple_hdr_bm % rows_data_stats.maxalign) = 0) THEN rows_data_stats.maxalign ELSE (rows_data_stats.index_tuple_hdr_bm % rows_data_stats.maxalign) END))::double precision + rows_data_s
tats.nulldatawidth) + (rows_data_stats.maxalign)::double precision) - (CASE WHEN (rows_data_stats.nulldatawidth = '0'::double precision) THEN 0 WHEN (((rows_data_stats.nulldatawidth)::integ
er % rows_data_stats.maxalign) = 0) THEN rows_data_stats.maxalign ELSE ((rows_data_stats.nulldatawidth)::integer % rows_data_stats.maxalign) END)::double precision))::numeric))::double prec
ision)))))), '0'::double precision))) ELSE '0'::double precision END, (('100'::double precision * ((rows_data_stats.relpages)::double precision - COALESCE(('1'::double precision + ceil((row
s_data_stats.reltuples / floor((((((rows_data_stats.bs - (rows_data_stats.pageopqdata)::numeric) - (rows_data_stats.pagehdr)::numeric) * (rows_data_stats.fillfactor)::numeric))::double prec
ision / ('100'::double precision * (('4'::numeric + (((((((rows_data_stats.index_tuple_hdr_bm + rows_data_stats.maxalign) - CASE WHEN ((rows_data_stats.index_tuple_hdr_bm % rows_data_stats.
maxalign) = 0) THEN rows_data_stats.maxalign ELSE (rows_data_stats.index_tuple_hdr_bm % rows_data_stats.maxalign) END))::double precision + rows_data_stats.nulldatawidth) + (rows_data_stats
.maxalign)::double precision) - (CASE WHEN (rows_data_stats.nulldatawidth = '0'::double precision) THEN 0 WHEN (((rows_data_stats.nulldatawidth)::integer % rows_data_stats.maxalign) = 0) TH
EN rows_data_stats.maxalign ELSE ((rows_data_stats.nulldatawidth)::integer % rows_data_stats.maxalign) END)::double precision))::numeric))::double precision)))))), '0'::double precision)))
/ (rows_data_stats.relpages)::double precision), rows_data_stats.is_na
   Buffers: shared hit=96509
   ->  GroupAggregate  (cost=69152.95..69182.86 rows=386 width=265) (actual time=258.187..261.152 rows=4084 loops=1)
         Output: n.nspname, ct.relname, ci.relname, ci.reltuples, ci.relpages, i.indexrelid, (COALESCE((("substring"(array_to_string(ci.reloptions, ' '::text), 'fillfactor=([0-9]+)'::text))
::smallint)::integer, 90)), ((current_setting('block_size'::text))::numeric), (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 ELSE
4 END), (24), 16, CASE WHEN (max(COALESCE(s.stanullfrac, '0'::real)) = '0'::double precision) THEN 2 ELSE 6 END, sum((('1'::double precision - COALESCE(s.stanullfrac, '0'::real)) * (COALESC
E(s.stawidth, 1024))::double precision)), (max(CASE WHEN (a.atttypid = '19'::oid) THEN 1 ELSE 0 END) > 0)
         Group Key: n.nspname, ct.relname, ci.relname, ci.reltuples, ci.relpages, i.indexrelid, (COALESCE((("substring"(array_to_string(ci.reloptions, ' '::text), 'fillfactor=([0-9]+)'::tex
t))::smallint)::integer, 90)), ((current_setting('block_size'::text))::numeric), (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8 EL
SE 4 END), 24
         Buffers: shared hit=96509
         ->  Sort  (cost=69152.95..69153.91 rows=386 width=260) (actual time=258.165..258.384 rows=4139 loops=1)
               Output: n.nspname, ct.relname, ci.relname, ci.reltuples, ci.relpages, i.indexrelid, (COALESCE((("substring"(array_to_string(ci.reloptions, ' '::text), 'fillfactor=([0-9]+)'::
text))::smallint)::integer, 90)), ((current_setting('block_size'::text))::numeric), (CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THEN 8
 ELSE 4 END), 24, s.stanullfrac, s.stawidth, a.atttypid
               Sort Key: n.nspname, ct.relname, ci.relname, ci.reltuples, ci.relpages, i.indexrelid, (COALESCE((("substring"(array_to_string(ci.reloptions, ' '::text), 'fillfactor=([0-9]+)'
::text))::smallint)::integer, 90))
               Sort Method: quicksort  Memory: 1292kB
               Buffers: shared hit=96509
               ->  Hash Join  (cost=2520.74..69136.37 rows=386 width=260) (actual time=31.113..253.858 rows=4139 loops=1)
                     Output: n.nspname, ct.relname, ci.relname, ci.reltuples, ci.relpages, i.indexrelid, (COALESCE((("substring"(array_to_string(ci.reloptions, ' '::text), 'fillfactor=([0-9
]+)'::text))::smallint)::integer, 90)), (current_setting('block_size'::text))::numeric, CASE WHEN ((version() ~ 'mingw32'::text) OR (version() ~ '64-bit|x86_64|ppc64|ia64|amd64'::text)) THE
N 8 ELSE 4 END, 24, s.stanullfrac, s.stawidth, a.atttypid
                     Inner Unique: true
                     Hash Cond: (ct.relnamespace = n.oid)
                     Buffers: shared hit=96497
                     ->  Nested Loop  (cost=2519.60..69126.75 rows=386 width=160) (actual time=30.842..228.490 rows=4139 loops=1)
                           Output: ci.relname, ci.reltuples, ci.relpages, i.indexrelid, (COALESCE((("substring"(array_to_string(ci.reloptions, ' '::text), 'fillfactor=([0-9]+)'::text))::sma
llint)::integer, 90)), a.atttypid, s.stanullfrac, s.stawidth, ct.relname, ct.relnamespace
                           Join Filter: ((a.attrelid = s.starelid) AND (a.attnum = s.staattnum))
                           Buffers: shared hit=96496
                           ->  Nested Loop  (cost=2519.18..67077.85 rows=3318 width=198) (actual time=30.502..157.243 rows=12906 loops=1)
                                 Output: ci.relname, ci.reltuples, ci.relpages, i.indexrelid, (COALESCE((("substring"(array_to_string(ci.reloptions, ' '::text), 'fillfactor=([0-9]+)'::text)
)::smallint)::integer, 90)), (generate_series(1, (i.indnatts)::integer)), ((string_to_array(textin(int2vectorout(i.indkey)), ' '::text))::integer[]), i.indrelid, a.atttypid, a.attrelid, a.a
ttnum, ct.relname, ct.relnamespace
                                 Inner Unique: true
                                 Buffers: shared hit=53600
                                 ->  Hash Join  (cost=2518.75..58662.13 rows=18643 width=188) (actual time=30.445..74.097 rows=12906 loops=1)
                                       Output: ci.relname, ci.reltuples, ci.relpages, i.indexrelid, (COALESCE((("substring"(array_to_string(ci.reloptions, ' '::text), 'fillfactor=([0-9]+)':
:text))::smallint)::integer, 90)), (generate_series(1, (i.indnatts)::integer)), ((string_to_array(textin(int2vectorout(i.indkey)), ' '::text))::integer[]), i.indrelid, ct.relname, ct.relnam
espace
                                       Inner Unique: true
                                       Hash Cond: (i.indrelid = ct.oid)
                                       Buffers: shared hit=1934
                                       ->  ProjectSet  (cost=1232.07..17568.81 rows=3153000 width=120) (actual time=11.265..48.713 rows=12906 loops=1)
                                             Output: ci.relname, ci.reltuples, ci.relpages, i.indrelid, i.indexrelid, COALESCE((("substring"(array_to_string(ci.reloptions, ' '::text), 'fill
factor=([0-9]+)'::text))::smallint)::integer, 90), (string_to_array(textin(int2vectorout(i.indkey)), ' '::text))::integer[], generate_series(1, (i.indnatts)::integer)
                                             Buffers: shared hit=1064
                                             InitPlan 1 (returns $0)
                                               ->  Seq Scan on pg_catalog.pg_am  (cost=0.00..1.07 rows=1 width=4) (actual time=0.008..0.009 rows=1 loops=1)
                                                     Output: pg_am.oid
                                                     Filter: (pg_am.amname = 'btree'::name)
                                                     Rows Removed by Filter: 5
                                                     Buffers: shared hit=1
                                             ->  Hash Join  (cost=1231.00..1534.73 rows=3153 width=157) (actual time=10.840..19.565 rows=8585 loops=1)
                                                   Output: i.indnatts, ci.relname, ci.reltuples, ci.relpages, i.indrelid, i.indexrelid, ci.reloptions, i.indkey
                                                   Inner Unique: true
                                                   Hash Cond: (i.indexrelid = ci.oid)
                                                   Buffers: shared hit=1064
                                                   ->  Seq Scan on pg_catalog.pg_index i  (cost=0.00..280.71 rows=8771 width=36) (actual time=0.003..2.963 rows=8649 loops=1)
                                                         Output: i.indexrelid, i.indrelid, i.indnatts, i.indnkeyatts, i.indisunique, i.indisprimary, i.indisexclusion, i.indimmediate, i.indi
sclustered, i.indisvalid, i.indcheckxmin, i.indisready, i.indislive, i.indisreplident, i.indkey, i.indcollation, i.indclass, i.indoption, i.indexprs, i.indpred
                                                         Buffers: shared hit=193
                                                   ->  Hash  (cost=1147.78..1147.78 rows=6657 width=125) (actual time=10.768..10.768 rows=8585 loops=1)
                                                         Output: ci.relname, ci.reltuples, ci.relpages, ci.reloptions, ci.oid
                                                         Buckets: 16384 (originally 8192)  Batches: 1 (originally 1)  Memory Usage: 1034kB
                                                         Buffers: shared hit=871
                                                         ->  Seq Scan on pg_catalog.pg_class ci  (cost=0.00..1147.78 rows=6657 width=125) (actual time=0.020..7.181 rows=8585 loops=1)
                                                               Output: ci.relname, ci.reltuples, ci.relpages, ci.reloptions, ci.oid
                                                               Filter: ((ci.relpages > 0) AND (ci.relam = $0))
                                                               Rows Removed by Filter: 8786
                                                               Buffers: shared hit=871
                                       ->  Hash  (cost=1055.19..1055.19 rows=18519 width=72) (actual time=18.942..18.942 rows=17371 loops=1)
                                             Output: ct.relname, ct.oid, ct.relnamespace
                                             Buckets: 32768  Batches: 1  Memory Usage: 2021kB
                                             Buffers: shared hit=870
                                             ->  Seq Scan on pg_catalog.pg_class ct  (cost=0.00..1055.19 rows=18519 width=72) (actual time=0.004..12.012 rows=17371 loops=1)
                                                   Output: ct.relname, ct.oid, ct.relnamespace
                                                   Buffers: shared hit=870
                                 ->  Index Scan using pg_attribute_relid_attnum_index on pg_catalog.pg_attribute a  (cost=0.43..0.45 rows=1 width=10) (actual time=0.005..0.005 rows=1 loops=
12906)
                                       Output: a.attrelid, a.attname, a.atttypid, a.attstattarget, a.attlen, a.attnum, a.attndims, a.attcacheoff, a.atttypmod, a.attbyval, a.attstorage, a.at
talign, a.attnotnull, a.atthasdef, a.atthasmissing, a.attidentity, a.attisdropped, a.attislocal, a.attinhcount, a.attcollation, a.attacl, a.attoptions, a.attfdwoptions, a.attmissingval
                                       Index Cond: ((a.attrelid = CASE WHEN ((((string_to_array(textin(int2vectorout(i.indkey)), ' '::text))::integer[]))[(generate_series(1, (i.indnatts)::i
nteger))] = 0) THEN i.indexrelid ELSE i.indrelid END) AND (a.attnum = CASE WHEN ((((string_to_array(textin(int2vectorout(i.indkey)), ' '::text))::integer[]))[(generate_series(1, (i.indnatts
)::integer))] = 0) THEN (generate_series(1, (i.indnatts)::integer)) ELSE (((string_to_array(textin(int2vectorout(i.indkey)), ' '::text))::integer[]))[(generate_series(1, (i.indnatts)::integ
er))] END))
                                       Buffers: shared hit=51666
                           ->  Index Scan using pg_statistic_relid_att_inh_index on pg_catalog.pg_statistic s  (cost=0.42..0.54 rows=5 width=14) (actual time=0.005..0.005 rows=0 loops=12906
)
                                 Output: s.starelid, s.staattnum, s.stainherit, s.stanullfrac, s.stawidth, s.stadistinct, s.stakind1, s.stakind2, s.stakind3, s.stakind4, s.stakind5, s.staop
1, s.staop2, s.staop3, s.staop4, s.staop5, s.stanumbers1, s.stanumbers2, s.stanumbers3, s.stanumbers4, s.stanumbers5, s.stavalues1, s.stavalues2, s.stavalues3, s.stavalues4, s.stavalues5
                                 Index Cond: ((s.starelid = CASE WHEN ((((string_to_array(textin(int2vectorout(i.indkey)), ' '::text))::integer[]))[(generate_series(1, (i.indnatts)::integer
))] = 0) THEN i.indexrelid ELSE i.indrelid END) AND (s.staattnum = CASE WHEN ((((string_to_array(textin(int2vectorout(i.indkey)), ' '::text))::integer[]))[(generate_series(1, (i.indnatts)::
integer))] = 0) THEN (generate_series(1, (i.indnatts)::integer)) ELSE (((string_to_array(textin(int2vectorout(i.indkey)), ' '::text))::integer[]))[(generate_series(1, (i.indnatts)::integer)
)] END))
                                 Buffers: shared hit=42896
                     ->  Hash  (cost=1.06..1.06 rows=6 width=68) (actual time=0.025..0.025 rows=6 loops=1)
                           Output: n.nspname, n.oid
                           Buckets: 1024  Batches: 1  Memory Usage: 9kB
                           Buffers: shared hit=1
                           ->  Seq Scan on pg_catalog.pg_namespace n  (cost=0.00..1.06 rows=6 width=68) (actual time=0.010..0.013 rows=6 loops=1)
                                 Output: n.nspname, n.oid
                                 Buffers: shared hit=1
 Planning Time: 5.737 ms
 Execution Time: 290.555 ms
(80 rows)
bsislow commented 5 years ago

Do you know when a fix for this will be released? Thanks.

bsislow commented 5 years ago

Any update on this? We are going live on a new system and need the monitoring capabilities - but we're also monitoring the Postgres log and it's producing these FATAL errors constantly. Thanks.

julmon commented 5 years ago

Hello,

Version 4.1 of the agent has just been released and should fix this issue. Could you confirm please ?

Thanks

bsislow commented 5 years ago

What is the proper upgrade process for 4.1? Thanks.

julmon commented 5 years ago

That's a usual binary upgrade, you only need to upgrade the agent with yum.

bsislow commented 5 years ago

Thank you! We will try this week.

bsislow commented 4 years ago

This issue is back with an upgrade to PostgreSQL 12.3 and temboard-agent 6.0.

2020-08-21 07:37:48 CDT [53575]: [2-1] user=temboard,db=xxxx,app=[unknown],client=[local] LOG:  could not send data to client: Broken pipe
2020-08-21 07:37:48 CDT [53575]: [3-1] user=temboard,db=xxxx,app=[unknown],client=[local] FATAL:  connection to client lost

$ temboard-agent -V
 INFO: Starting temboard-agent 6.0.
6.0
$ psql
psql (12.3)
Type "help" for help.

postgres=#
bersace commented 4 years ago

7.0 will come with an optimized btree_bloat query. See https://github.com/dalibo/temboard-agent/pull/456

bsislow commented 4 years ago

Thanks - when can we expect this release?

bersace commented 4 years ago

@bsislow It's a matter of weeks. We're about to release a second alpha release.

bsislow commented 4 years ago

Great. If you have a moment, please update this case when the production release of 7.0 is out and we will test it.

bsislow commented 4 years ago

Hello - any update on this case? Thank you.

pgiraud commented 4 years ago

@bsislow we're almost ready. The 7.0 release is scheduled for next week. Keep in touch.

bsislow commented 4 years ago

Thanks!

pgiraud commented 4 years ago

@bsislow temBoard 7.0 has just been released. Please have a try.

bsislow commented 4 years ago

Thanks, we will need a bit of time to organize the upgrade. Will let you know...

bersace commented 2 years ago

Hi @bsislow can you confirm this bug still occurs in temboard agent 7.10 ? A lot of things has evolved regarding connexions handling.