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.lohbruegge@xxxxxxxxx>:
2017-11-08 0:45 GMT+01:00 Tom Lane <tgl@xxxxxxxxxxxxx>:=?UTF-8?Q?Ulf_Lohbr=C3=BCgge?= <ulf.lohbruegge@xxxxxxxxx> writes:
> I just ran "check_postgres.pl --action="" 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 laneI 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
