I could reproduce part of the things I described earlier in this thread. A guy named Andriy Senyshyn mailed me after reading this thread here (he could somehow not join the mailing list) and observed a difference when issuing "SET ROLE" as user postgres and as a non-superuser.
When I connect as superuser postgres to mydb and execute a "SET ROLE" things are pretty fast: $ PGOPTIONS='-c client-min-messages=DEBUG5' psql -U postgres mydb DEBUG: CommitTransaction DEBUG: name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: psql (9.6.6) Type "help" for help. magicline=# \timing Timing is on. magicline=# SET ROLE tenant1337; DEBUG: StartTransactionCommand DEBUG: StartTransaction DEBUG: name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: DEBUG: ProcessUtility DEBUG: CommitTransactionCommand DEBUG: CommitTransaction DEBUG: name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: SET Time: 0.968 ms magicline=> When I connect as user admin (non-superuser with NOINHERIT attribute) to mydb, the first "SET ROLE" statement is always quite slow in comparison to the former "SET ROLE" statement executed by superuser postgres: $ PGOPTIONS='-c client-min-messages=DEBUG5' psql -U admin mydb DEBUG: CommitTransaction DEBUG: name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: psql (9.6.6) Type "help" for help. magicline=> \timing Timing is on. magicline=> SET ROLE tenant1337; DEBUG: StartTransactionCommand DEBUG: StartTransaction DEBUG: name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: DEBUG: ProcessUtility DEBUG: rehashing catalog cache id 8 for pg_auth_members; 17 tups, 8 buckets DEBUG: rehashing catalog cache id 8 for pg_auth_members; 33 tups, 16 buckets DEBUG: rehashing catalog cache id 8 for pg_auth_members; 65 tups, 32 buckets DEBUG: rehashing catalog cache id 8 for pg_auth_members; 129 tups, 64 buckets DEBUG: rehashing catalog cache id 8 for pg_auth_members; 257 tups, 128 buckets DEBUG: rehashing catalog cache id 8 for pg_auth_members; 513 tups, 256 buckets DEBUG: rehashing catalog cache id 8 for pg_auth_members; 1025 tups, 512 buckets DEBUG: CommitTransactionCommand DEBUG: CommitTransaction DEBUG: name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: SET Time: 31.858 ms magicline=> Subsequent "SET ROLE" calls in the above session of user admin are pretty fast (below 1 ms). I further wonder what those log statements "rehashing catalog cache..." do and if they are the cause of the slow execution. So this does not reproduce my observed query times >2000ms but is maybe a hint for other things that might be worth looking into. Regards, Ulf 2017-11-08 10:31 GMT+01:00 Ulf Lohbrügge <ulf.lohbrue...@gmail.com>: > 2017-11-08 0:45 GMT+01:00 Tom Lane <t...@sss.pgh.pa.us>: > >> =?UTF-8?Q?Ulf_Lohbr=C3=BCgge?= <ulf.lohbrue...@gmail.com> writes: >> > I just ran "check_postgres.pl --action=bloat" and got the following >> output: >> > ... >> > Looks fine, doesn't it? >> >> A possible explanation is that something is taking an exclusive lock >> on some system catalog and holding it for a second or two. If so, >> turning on log_lock_waits might provide some useful info. >> >> regards, tom lane >> > > I just checked my configuration and found out that "log_lock_waits" was > already enabled. > > Unfortunately there is no log output of locks when those long running "SET > ROLE" statements occur. > > Regards, > Ulf > >