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

Поиск
Список
Период
Сортировка
От Ulf Lohbrügge
Тема Re: [PERFORM] Slow execution of SET ROLE, SET search_path and RESET ROLE
Дата
Msg-id CABZYQRJZp78vAJ2byse8AO75v-CWuj6qNdDmUtfMzRb+o7HX=g@mail.gmail.com
обсуждение исходный текст
Ответ на [PERFORM] Slow execution of SET ROLE, SET search_path and RESET ROLE  (Ulf Lohbrügge <ulf.lohbruegge@gmail.com>)
Ответы Re: [PERFORM] Slow execution of SET ROLE, SET search_path and RESET ROLE
Список pgsql-performance
Дерево обсуждения
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@gmail.com>:
2017-11-08 0:45 GMT+01:00 Tom Lane <tgl@sss.pgh.pa.us>:
Ulf Lohbrügge <ulf.lohbruegge@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


В списке pgsql-performance по дате отправления:

Предыдущее
От: Gunther
Дата:
Сообщение: Re: pg_dump 3 times as slow after 8.4 -> 9.5 upgrade
Следующее
От: Tom Lane
Дата:
Сообщение: Re: [PERFORM] Slow execution of SET ROLE, SET search_path and RESET ROLE