Re: pg_dump from v13 is slow

I can reproduce the issue with generated data:

pryzbyj=# SELECT format('create table t%s(i int)', i) FROM generate_series(1,9999)i;
\set ECHO errors
\set QUIET
\gexec

$ time pg_dump --section=pre-data -d pryzbyj -h /tmp -p 5613 |wc   
 110015  240049 1577087
real    0m50.445s

$ time pg_dump --section=pre-data -d pryzbyj -h /tmp -p 5612 |wc
 110015  240049 1577084
real    0m11.203s

On Thu, Aug 13, 2020 at 04:30:14PM -0700, Andres Freund wrote:
> Would be worth knowing how much of the time pgbench is 100% CPU
> utilized, and how much of the time it is basically waiting for server
> side queries and largely idle.

Good question - I guess you mean pg_dump.

$ command time -v pg_dump --section=pre-data -d pryzbyj -h /tmp -p 5612 |wc   
        Command being timed: "pg_dump --section=pre-data -d pryzbyj -h /tmp -p 5612"
        User time (seconds): 0.65
        System time (seconds): 0.52
        Percent of CPU this job got: 9%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 0:11.85

$ command time -v pg_dump --section=pre-data -d pryzbyj -h /tmp -p 5613 |wc
        Command being timed: "pg_dump --section=pre-data -d pryzbyj -h /tmp -p 5613"
        User time (seconds): 0.79
        System time (seconds): 0.49
        Percent of CPU this job got: 2%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 0:48.51

So v13 was 4.5x slower and it seems to be all on the server side.

I looked queries like this:
time strace -ts999 -e sendto pg_dump  --section=pre-data -d pryzbyj -h /tmp -p 5613 2>strace-13-3 |wc
cut -c1-66 strace-13-3 |sort |uniq |less

Most of the time is spent on these three queries:

|12:58:11 sendto(3,
"Q\0\0\3\215SELECT\na.attnum,\na.attname,\na.atttypmod,\na.attstattarget,\na.attstorage,\nt.typstorage,\na.attn
|...
|12:58:30 sendto(3,
"Q\0\0\3\215SELECT\na.attnum,\na.attname,\na.atttypmod,\na.attstattarget,\na.attstorage,\nt.typstorage,\na.attn

|12:58:32 sendto(3, "Q\0\0\1\314SELECT oid, tableoid, pol.polname, pol.polcmd, pol.polpermissive, CASE WHEN
pol.polroles= '{0}' TH
 
|...
|12:58:47 sendto(3, "Q\0\0\1\314SELECT oid, tableoid, pol.polname, pol.polcmd, pol.polpermissive, CASE WHEN
pol.polroles= '{0}' TH
 

|12:58:49 sendto(3, "Q\0\0\0\213SELECT pr.tableoid, pr.oid, p.pubname FROM pg_publication_rel pr, pg_publication p
WHEREpr.prrelid
 
|...
|12:59:01 sendto(3, "Q\0\0\0\213SELECT pr.tableoid, pr.oid, p.pubname FROM pg_publication_rel pr, pg_publication p
WHEREpr.prrelid
 

Compare with v12:

|12:57:58 sendto(3,
"Q\0\0\3\215SELECT\na.attnum,\na.attname,\na.atttypmod,\na.attstattarget,\na.attstorage,\nt.typstorage,\na.attn
|...
|12:58:03 sendto(3,
"Q\0\0\3\215SELECT\na.attnum,\na.attname,\na.atttypmod,\na.attstattarget,\na.attstorage,\nt.typstorage,\na.attn

|12:58:05 sendto(3, "Q\0\0\1\314SELECT oid, tableoid, pol.polname, pol.polcmd, pol.polpermissive, CASE WHEN
pol.polroles= '{0}' TH
 
|...
|12:58:07 sendto(3, "Q\0\0\1\314SELECT oid, tableoid, pol.polname, pol.polcmd, pol.polpermissive, CASE WHEN
pol.polroles= '{0}' TH
 

|12:58:09 sendto(3, "Q\0\0\0\213SELECT pr.tableoid, pr.oid, p.pubname FROM pg_publication_rel pr, pg_publication p
WHEREpr.prrelid
 
|...
|12:58:11 sendto(3, "Q\0\0\0\213SELECT pr.tableoid, pr.oid, p.pubname FROM pg_publication_rel pr, pg_publication p
WHEREpr.prrelid
 

The first query regressed the worst.

$ psql -h /tmp -Ap 5612 pryzbyj
psql (13beta3, server 12.4)
pryzbyj=# explain analyze SELECT
a.attnum,a.attname,a.atttypmod,a.attstattarget,a.attstorage,t.typstorage,a.attnotnull,a.atthasdef,a.attisdropped,a.attlen,a.attalign,a.attislocal,pg_catalog.format_type(t.oid,
a.atttypmod)AS atttypname,a.attgenerated,CASE WHEN a.atthasmissing AND NOT a.attisdropped THEN a.attmissingval ELSE
nullEND AS attmissingval,a.attidentity,pg_catalog.array_to_string(ARRAY(SELECT pg_catalog.quote_ident(option_name) || '
'|| pg_catalog.quote_literal(option_value) FROM pg_catalog.pg_options_to_table(attfdwoptions) ORDER BY option_name),
E',   ') AS attfdwoptions,CASE WHEN a.attcollation <> t.typcollation THEN a.attcollation ELSE 0 END AS
attcollation,array_to_string(a.attoptions,', ') AS attoptions FROM pg_catalog.pg_attribute a LEFT JOIN
pg_catalog.pg_typet ON a.atttypid = t.oid WHERE a.attrelid = '191444'::pg_catalog.oid AND a.attnum > 0::pg_catalog.int2
ORDERBY a.attnum;
 
QUERY PLAN
Nested Loop Left Join  (cost=0.58..16.72 rows=1 width=217) (actual time=0.205..0.209 rows=1 loops=1)
  ->  Index Scan using pg_attribute_relid_attnum_index on pg_attribute a  (cost=0.29..8.31 rows=1 width=189) (actual
time=0.030..0.032rows=1 loops=1)
 
        Index Cond: ((attrelid = '191444'::oid) AND (attnum > '0'::smallint))
  ->  Index Scan using pg_type_oid_index on pg_type t  (cost=0.29..8.30 rows=1 width=9) (actual time=0.011..0.011
rows=1loops=1)
 
        Index Cond: (oid = a.atttypid)
  SubPlan 1
    ->  Sort  (cost=0.09..0.09 rows=3 width=64) (actual time=0.119..0.119 rows=0 loops=1)
          Sort Key: pg_options_to_table.option_name
          Sort Method: quicksort  Memory: 25kB
          ->  Function Scan on pg_options_to_table  (cost=0.00..0.06 rows=3 width=64) (actual time=0.010..0.010 rows=0
loops=1)
Planning Time: 1.702 ms
Execution Time: 0.422 ms

$ psql -h /tmp -Ap 5613 pryzbyj
psql (13beta3)
pryzbyj=# explain analyze SELECT
a.attnum,a.attname,a.atttypmod,a.attstattarget,a.attstorage,t.typstorage,a.attnotnull,a.atthasdef,a.attisdropped,a.attlen,a.attalign,a.attislocal,pg_catalog.format_type(t.oid,
a.atttypmod)AS atttypname,a.attgenerated,CASE WHEN a.atthasmissing AND NOT a.attisdropped THEN a.attmissingval ELSE
nullEND AS attmissingval,a.attidentity,pg_catalog.array_to_string(ARRAY(SELECT pg_catalog.quote_ident(option_name) || '
'|| pg_catalog.quote_literal(option_value) FROM pg_catalog.pg_options_to_table(attfdwoptions) ORDER BY option_name),
E',   ') AS attfdwoptions,CASE WHEN a.attcollation <> t.typcollation THEN a.attcollation ELSE 0 END AS
attcollation,array_to_string(a.attoptions,', ') AS attoptions FROM pg_catalog.pg_attribute a LEFT JOIN
pg_catalog.pg_typet ON a.atttypid = t.oid WHERE a.attrelid = '164518'::pg_catalog.oid AND a.attnum > 0::pg_catalog.int2
ORDERBY a.attnum;
 
QUERY PLAN
Nested Loop Left Join  (cost=0.58..16.72 rows=1 width=217) (actual time=0.134..0.139 rows=1 loops=1)
  ->  Index Scan using pg_attribute_relid_attnum_index on pg_attribute a  (cost=0.29..8.31 rows=1 width=189) (actual
time=0.028..0.030rows=1 loops=1)
 
        Index Cond: ((attrelid = '164518'::oid) AND (attnum > '0'::smallint))
  ->  Index Scan using pg_type_oid_index on pg_type t  (cost=0.29..8.30 rows=1 width=9) (actual time=0.008..0.008
rows=1loops=1)
 
        Index Cond: (oid = a.atttypid)
  SubPlan 1
    ->  Sort  (cost=0.09..0.09 rows=3 width=64) (actual time=0.065..0.065 rows=0 loops=1)
          Sort Key: pg_options_to_table.option_name
          Sort Method: quicksort  Memory: 25kB
          ->  Function Scan on pg_options_to_table  (cost=0.00..0.06 rows=3 width=64) (actual time=0.005..0.005 rows=0
loops=1)
Planning Time: 1.457 ms
Execution Time: 0.431 ms

I don't know if it's any issue, but I found that pg12 can process "null
statements" almost 2x as fast:

$ time for a in `seq 1 9999`; do echo ';'; done |psql -h /tmp -p 5613 postgres 
    real    0m0.745s
$ time for a in `seq 1 9999`; do echo ';'; done |psql -h /tmp -p 5612 postgres 
    real    0m0.444s

-- 
Justin