Re: [PERFORM] Slow execution of SET ROLE, SET search_path and RESET ROLE

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(dot)lohbruegge(at)gmail(dot)com>:

> 2017-11-08 0:45 GMT+01:00 Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>:
>
>> =?UTF-8?Q?Ulf_Lohbr=C3=BCgge?= <ulf(dot)lohbruegge(at)gmail(dot)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
>
>