Обсуждение: [PERFORM] Slow execution of SET ROLE, SET search_path and RESET ROLE
Hi there,
I'm using PostgreSQL 9.5.9 on Debian and experience slow execution of some basic SET statements.
I created about 1600 roles and use that setup for a multi tenancy application:
--snip--
-- create one role per tenant
CREATE ROLE tenant1;
...
CREATE ROLE tenant1600;
-- create admin role that is granted all tenant roles
CREATE ROLE admin NOINHERIT LOGIN PASSWORD 'XXXX';
GRANT tenant1 TO admin;
...
GRANT tenant1600 TO admin;
-- every tenant resides in its own schema
CREATE SCHEMA AUTHORIZATION tenant1;
...
CREATE SCHEMA AUTHORIZATION tenant1600;
--snap--
My application solely uses the role 'admin' to connect to the database. When performing sql statements for a specific tenant (e.g. tenant1337), a connection with user 'admin' is established and the following commands are executed:
SET ROLE 1337;
SET search_path = tenant1337;
Then the application uses that connection to perform various statements in the database. As I'm using a connection pool, every connection that is returned to the pool executes the following commands:
RESET ROLE;
SET search_path = DEFAULT;
My application is a web service that approximately executes some hundred statements per second.
I set "log_min_duration_statement = 200ms" and I get about 2k to 4k lines per day with statements like "SET ROLE"", "SET search_path ..." and "RESET ROLE":
--snip--
2017-11-07 09:44:30 CET [27760]: [3-1] user=admin,db=mydb LOG: duration: 901.591 ms execute <unnamed>: SET ROLE "tenant762"
2017-11-07 09:44:30 CET [27659]: [4-1] user=admin,db=mydb LOG: duration: 1803.971 ms execute <unnamed>: SET ROLE "tenant392"
2017-11-07 09:44:30 CET [27810]: [4-1] user=admin,db=mydb LOG: duration: 1548.858 ms execute <unnamed>: SET ROLE "tenant232"
2017-11-07 09:44:30 CET [27652]: [3-1] user=admin,db=mydb LOG: duration: 1248.838 ms execute <unnamed>: SET ROLE "tenant7"
2017-11-07 09:44:30 CET [27706]: [3-1] user=admin,db=mydb LOG: duration: 998.044 ms execute <unnamed>: SET ROLE "tenant1239"
2017-11-07 09:44:30 CET [27820]: [14-1] user=admin,db=mydb LOG: duration: 1573.000 ms execute <unnamed>: SET ROLE "tenant378"
2017-11-07 09:44:30 CET [28303]: [4-1] user=admin,db=mydb LOG: duration: 2116.651 ms execute <unnamed>: SET ROLE "tenant302"
2017-11-07 09:44:30 CET [27650]: [4-1] user=admin,db=mydb LOG: duration: 2011.629 ms execute <unnamed>: SET ROLE "tenant938"
2017-11-07 09:44:30 CET [28026]: [4-1] user=admin,db=mydb LOG: duration: 2378.719 ms execute <unnamed>: SET ROLE "tenant 634"
2017-11-07 09:44:30 CET [27708]: [7-1] user=admin,db=mydb LOG: duration: 1327.962 ms execute <unnamed>: SET ROLE "tenant22"
2017-11-07 09:44:30 CET [27707]: [4-1] user=admin,db=mydb LOG: duration: 1366.602 ms execute <unnamed>: SET ROLE "tenant22"
2017-11-07 09:44:30 CET [27610]: [8-1] user=admin,db=mydb LOG: duration: 1098.192 ms execute <unnamed>: SET ROLE "tenant22"
2017-11-07 09:44:30 CET [27762]: [3-1] user=admin,db=mydb LOG: duration: 1349.368 ms execute <unnamed>: SET ROLE "tenant22"
2017-11-07 09:44:30 CET [27756]: [4-1] user=admin,db=mydb LOG: duration: 1735.926 ms parse <unnamed>: SET search_path = DEFAULT
2017-11-07 09:44:31 CET [28190]: [4-1] user=admin,db=mydb LOG: duration: 1987.256 ms parse <unnamed>: SET search_path = DEFAULT
2017-11-07 09:44:31 CET [27646]: [3-1] user=admin,db=mydb LOG: duration: 205.063 ms execute <unnamed>: SET ROLE "tenant7"
2017-11-07 09:44:31 CET [27649]: [3-1] user=admin,db=mydb LOG: duration: 225.152 ms execute <unnamed>: SET ROLE "tenant302"
2017-11-07 09:44:31 CET [27654]: [5-1] user=admin,db=mydb LOG: duration: 2235.243 ms parse <unnamed>: SET search_path = DEFAULT
2017-11-07 09:44:31 CET [27674]: [4-1] user=admin,db=mydb LOG: duration: 2080.905 ms parse <unnamed>: SET search_path = DEFAULT
2017-11-07 09:44:31 CET [28307]: [5-1] user=admin,db=mydb LOG: duration: 2351.064 ms parse <unnamed>: SET search_path = DEFAULT
2017-11-07 09:44:31 CET [27681]: [4-1] user=admin,db=mydb LOG: duration: 2455.486 ms parse <unnamed>: SET search_path = DEFAULT
2017-11-07 09:44:31 CET [27651]: [4-1] user=admin,db=mydb LOG: duration: 1830.737 ms parse <unnamed>: SET search_path = DEFAULT
2017-11-07 09:44:32 CET [28137]: [4-1] user=admin,db=mydb LOG: duration: 1973.241 ms parse <unnamed>: SET search_path = DEFAULT
2017-11-07 09:44:32 CET [27682]: [4-1] user=admin,db=mydb LOG: duration: 1863.962 ms parse <unnamed>: SET search_path = DEFAULT
2017-11-07 09:44:32 CET [28243]: [4-1] user=admin,db=mydb LOG: duration: 2120.339 ms parse <unnamed>: SET search_path = DEFAULT
2017-11-07 09:44:32 CET [28025]: [5-1] user=admin,db=mydb LOG: duration: 2643.520 ms parse <unnamed>: SET search_path = DEFAULT
2017-11-07 09:44:32 CET [27709]: [7-1] user=admin,db=mydb LOG: duration: 2519.842 ms parse <unnamed>: SET search_path = DEFAULT
2017-11-07 09:44:32 CET [27655]: [5-1] user=admin,db=mydb LOG: duration: 2622.280 ms parse <unnamed>: SET search_path = DEFAULT
2017-11-07 09:44:32 CET [28242]: [4-1] user=admin,db=mydb LOG: duration: 2326.483 ms parse <unnamed>: SET search_path = DEFAULT
2017-11-07 09:44:32 CET [27652]: [4-1] user=admin,db=mydb LOG: duration: 1746.423 ms parse <unnamed>: SET search_path = DEFAULT
2017-11-07 09:44:32 CET [27706]: [4-1] user=admin,db=mydb LOG: duration: 1759.188 ms parse <unnamed>: SET search_path = DEFAULT
2017-11-07 09:44:32 CET [27603]: [5-1] user=admin,db=mydb LOG: duration: 2521.347 ms parse <unnamed>: SET search_path = DEFAULT
2017-11-07 09:44:32 CET [27818]: [5-1] user=admin,db=mydb LOG: duration: 2382.254 ms parse <unnamed>: SET search_path = DEFAULT
2017-11-07 09:44:32 CET [27761]: [5-1] user=admin,db=mydb LOG: duration: 2372.629 ms parse <unnamed>: SET search_path = DEFAULT
--snap--
Besides those peaks in statement duration, my application performs (i.e. has acceptable response times) most of the time.
Is there anything I can do to improve performance here?
Any help is greatly appreciated!
Regards,
Ulf
Hi, On 2017-11-07 11:11:36 +0100, Ulf Lohbrügge wrote: > I'm using PostgreSQL 9.5.9 on Debian and experience slow execution of some > basic SET statements. > > I created about 1600 roles and use that setup for a multi tenancy > application: Hm. How often do you drop/create these roles? How many other roles/groups is one role a member of? > My application solely uses the role 'admin' to connect to the database. > When performing sql statements for a specific tenant (e.g. tenant1337), a > connection with user 'admin' is established and the following commands are > executed: > > SET ROLE 1337; > SET search_path = tenant1337; > > Then the application uses that connection to perform various statements in > the database. Just to be sure: You realize bad application code could escape from that, right? > My application is a web service that approximately executes some hundred > statements per second. > > I set "log_min_duration_statement = 200ms" and I get about 2k to 4k lines > per day with statements like "SET ROLE"", "SET search_path ..." and "RESET > ROLE": > > --snip-- > 2017-11-07 09:44:30 CET [27760]: [3-1] user=admin,db=mydb LOG: duration: > 901.591 ms execute <unnamed>: SET ROLE "tenant762" > 2017-11-07 09:44:30 CET [27659]: [4-1] user=admin,db=mydb LOG: duration: > 1803.971 ms execute <unnamed>: SET ROLE "tenant392" That is weird. > Besides those peaks in statement duration, my application performs (i.e. > has acceptable response times) most of the time. > > Is there anything I can do to improve performance here? > Any help is greatly appreciated! Can you manually reproduce the problem? What times do you get if you manually run the statement? Greetings, Andres Freund -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance
Hi,
2017-11-07 16:11 GMT+01:00 Andres Freund <andres@anarazel.de>:
Hi,
On 2017-11-07 11:11:36 +0100, Ulf Lohbrügge wrote:
> I'm using PostgreSQL 9.5.9 on Debian and experience slow execution of some
> basic SET statements.
>
> I created about 1600 roles and use that setup for a multi tenancy
> application:
Hm. How often do you drop/create these roles? How many other
roles/groups is one role a member of?
I create between 10-40 roles per day.
The roles tenant1 to tenant1600 are not members of any other roles. Only the role 'admin' is member of many roles (tenant1 to tenant1600).
> My application solely uses the role 'admin' to connect to the database.
> When performing sql statements for a specific tenant (e.g. tenant1337), a
> connection with user 'admin' is established and the following commands are
> executed:
>
> SET ROLE 1337;
> SET search_path = tenant1337;
>
> Then the application uses that connection to perform various statements in
> the database.
Just to be sure: You realize bad application code could escape from
that, right?
Yes, I do. :)
My application executes all statements via an ORM tool (Hibernate). But evil code could still get the plain DB-Connection and execute "SET ROLE ..." statements. My application used to connect as tenant1 to tenant1600 but that lead to a vast amount of postgresql connections (even with pgbouncer).
> My application is a web service that approximately executes some hundred
> statements per second.
>
> I set "log_min_duration_statement = 200ms" and I get about 2k to 4k lines
> per day with statements like "SET ROLE"", "SET search_path ..." and "RESET
> ROLE":
>
> --snip--
> 2017-11-07 09:44:30 CET [27760]: [3-1] user=admin,db=mydb LOG: duration:
> 901.591 ms execute <unnamed>: SET ROLE "tenant762"
> 2017-11-07 09:44:30 CET [27659]: [4-1] user=admin,db=mydb LOG: duration:
> 1803.971 ms execute <unnamed>: SET ROLE "tenant392"
That is weird.
> Besides those peaks in statement duration, my application performs (i.e.
> has acceptable response times) most of the time.
>
> Is there anything I can do to improve performance here?
> Any help is greatly appreciated!
Can you manually reproduce the problem? What times do you get if you
manually run the statement?
Unfortunately not. Every time I manually execute "SET ROLE ..." the statement is pretty fast. I created a simple SQL file that contains the following statements:
--snip--
SET ROLE tenant382;
SET ROLE tenant1337;
SET ROLE tenant2;
-- repeat the lines above 100k times
--snap--
When I execute those statements via 'time psql < set-roles.sql', the call lasts 138,7 seconds. So 300k "SET ROLE" statements result in 0,46ms per call on average.
Cheers,
Ulf
On 2017-11-07 18:48:14 +0100, Ulf Lohbrügge wrote: > Hi, > > 2017-11-07 16:11 GMT+01:00 Andres Freund <andres@anarazel.de>: > > > Hi, > > > > On 2017-11-07 11:11:36 +0100, Ulf Lohbrügge wrote: > > > I'm using PostgreSQL 9.5.9 on Debian and experience slow execution of > > some > > > basic SET statements. > > > > > > I created about 1600 roles and use that setup for a multi tenancy > > > application: > > > > Hm. How often do you drop/create these roles? How many other > > roles/groups is one role a member of? > > > > I create between 10-40 roles per day. Could you VACUUM (VERBOSE, FREEZE) that table and report the output? Do you ever delete roles? > > Can you manually reproduce the problem? What times do you get if you > > manually run the statement? > > > > Unfortunately not. Every time I manually execute "SET ROLE ..." the > statement is pretty fast. I created a simple SQL file that contains the > following statements: > > --snip-- > SET ROLE tenant382; > SET ROLE tenant1337; > SET ROLE tenant2; > -- repeat the lines above 100k times > --snap-- > > When I execute those statements via 'time psql < set-roles.sql', the call > lasts 138,7 seconds. So 300k "SET ROLE" statements result in 0,46ms per > call on average. And most of that is going to be roundtrip time. Hm. Could it be that you're just seeing the delays when pgbouncer establishes new pooling connections and you're attributing that to SET ROLE in your app? Greetings, Andres Freund -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance
2017-11-07 20:45 GMT+01:00 Andres Freund <andres@anarazel.de>:
On 2017-11-07 18:48:14 +0100, Ulf Lohbrügge wrote:
> Hi,
>
> 2017-11-07 16:11 GMT+01:00 Andres Freund <andres@anarazel.de>:
>
> > Hi,
> >
> > On 2017-11-07 11:11:36 +0100, Ulf Lohbrügge wrote:
> > > I'm using PostgreSQL 9.5.9 on Debian and experience slow execution of
> > some
> > > basic SET statements.
> > >
> > > I created about 1600 roles and use that setup for a multi tenancy
> > > application:
> >
> > Hm. How often do you drop/create these roles? How many other
> > roles/groups is one role a member of?
> >
>
> I create between 10-40 roles per day.
Could you VACUUM (VERBOSE, FREEZE) that table and report the output? Do
you ever delete roles?
Which table do you mean exactly? pg_catalog.pg_authid?
Sorry, forgot to write that: I delete about 2-3 roles per day.
> > Can you manually reproduce the problem? What times do you get if you
> > manually run the statement?
> >
>
> Unfortunately not. Every time I manually execute "SET ROLE ..." the
> statement is pretty fast. I created a simple SQL file that contains the
> following statements:
>
> --snip--
> SET ROLE tenant382;
> SET ROLE tenant1337;
> SET ROLE tenant2;
> -- repeat the lines above 100k times
> --snap--
>
> When I execute those statements via 'time psql < set-roles.sql', the call
> lasts 138,7 seconds. So 300k "SET ROLE" statements result in 0,46ms per
> call on average.
And most of that is going to be roundtrip time. Hm. Could it be that
you're just seeing the delays when pgbouncer establishes new pooling
connections and you're attributing that to SET ROLE in your app?
I stopped using pgbouncer when I solely started using role 'admin' with "SET ROLE" statements. I use a connection pool (HikariCP) that renews connections after 30 minutes. I couldn't find a pattern yet when those slow statements occur.
Does using a few thousands roles and schemata in postgres scale well? I only found some theoretical descriptions of multi tenancy setups with postgres while googling.
Using tabulator in psql cli is pretty slow, mainly because pg_table_is_visible() is being called for many entries in pg_class.
Cheers,
Ulf
On Tue, Nov 7, 2017 at 2:25 PM, Ulf Lohbrügge <ulf.lohbruegge@gmail.com> wrote: > 2017-11-07 20:45 GMT+01:00 Andres Freund <andres@anarazel.de>: >> >> On 2017-11-07 18:48:14 +0100, Ulf Lohbrügge wrote: >> > Hi, >> > >> > 2017-11-07 16:11 GMT+01:00 Andres Freund <andres@anarazel.de>: >> > >> > > Hi, >> > > >> > > On 2017-11-07 11:11:36 +0100, Ulf Lohbrügge wrote: >> > > > I'm using PostgreSQL 9.5.9 on Debian and experience slow execution >> > > > of >> > > some >> > > > basic SET statements. >> > > > >> > > > I created about 1600 roles and use that setup for a multi tenancy >> > > > application: >> > > >> > > Hm. How often do you drop/create these roles? How many other >> > > roles/groups is one role a member of? >> > > >> > >> > I create between 10-40 roles per day. >> >> Could you VACUUM (VERBOSE, FREEZE) that table and report the output? Do >> you ever delete roles? > > > Which table do you mean exactly? pg_catalog.pg_authid? > > Sorry, forgot to write that: I delete about 2-3 roles per day. I'm gonna take a guess that pg_users or pg_roles has gotten bloated over time. Try running a vacuum full on both of them. It's also possible some other pg_xxx table is bloated out here too you might need to download something like checkpostgres.pl to check for bloat in system catalog tables. -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance
2017-11-07 22:39 GMT+01:00 Scott Marlowe <scott.marlowe@gmail.com>:
On Tue, Nov 7, 2017 at 2:25 PM, Ulf Lohbrügge <ulf.lohbruegge@gmail.com> wrote:
> 2017-11-07 20:45 GMT+01:00 Andres Freund <andres@anarazel.de>:
>>
>> On 2017-11-07 18:48:14 +0100, Ulf Lohbrügge wrote:
>> > Hi,
>> >
>> > 2017-11-07 16:11 GMT+01:00 Andres Freund <andres@anarazel.de>:
>> >
>> > > Hi,
>> > >
>> > > On 2017-11-07 11:11:36 +0100, Ulf Lohbrügge wrote:
>> > > > I'm using PostgreSQL 9.5.9 on Debian and experience slow execution
>> > > > of
>> > > some
>> > > > basic SET statements.
>> > > >
>> > > > I created about 1600 roles and use that setup for a multi tenancy
>> > > > application:
>> > >
>> > > Hm. How often do you drop/create these roles? How many other
>> > > roles/groups is one role a member of?
>> > >
>> >
>> > I create between 10-40 roles per day.
>>
>> Could you VACUUM (VERBOSE, FREEZE) that table and report the output? Do
>> you ever delete roles?
>
>
> Which table do you mean exactly? pg_catalog.pg_authid?
>
> Sorry, forgot to write that: I delete about 2-3 roles per day.
I'm gonna take a guess that pg_users or pg_roles has gotten bloated
over time. Try running a vacuum full on both of them. It's also
possible some other pg_xxx table is bloated out here too you might
need to download something like checkpostgres.pl to check for bloat in
system catalog tables.
As pg_user and pg_roles are views: Do you mean pg_authid? That table is just 432kb large:
--snip--
postgres=# select pg_size_pretty(pg_total_relation_size('pg_authid'));
pg_size_pretty
----------------
432 kB
(1 row)
--snap--
I don't want to start a vacuum full right now because I'm not quite sure if things will lock up. But I will do it later when there is less traffic.
I just ran "check_postgres.pl --action=bloat" and got the following output:
--snip--
POSTGRES_BLOAT OK: DB "postgres" (host:localhost) (db postgres) index pg_shdepend_depender_index rows:? pages:9615 shouldbe:4073 (2.4X) wasted bytes:45400064 (43 MB) | pg_shdepend_depender_index=45400064B pg_catalog.pg_shdepend=9740288B pg_shdepend_reference_index=4046848B pg_depend_reference_index=98304B pg_depend_depender_index=57344B pg_catalog.pg_class=32768B pg_catalog.pg_description=16384B pg_amop_fam_strat_index=8192B pg_amop_opr_fam_index=8192B pg_catalog.pg_amop=8192B pg_catalog.pg_depend=8192B pg_class_oid_index=0B pg_class_relname_nsp_index=0B pg_class_tblspc_relfilenode_index=0B pg_description_o_c_o_index=0B
--snap--
Looks fine, doesn't it?
Cheers,
Ulf
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
--
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
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
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 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
=?UTF-8?Q?Ulf_Lohbr=C3=BCgge?= <ulf.lohbruegge@gmail.com> writes:
> 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.
This isn't particularly surprising in itself. When we know that the
session user is a superuser, SET ROLE just succeeds immediately.
Otherwise we have to determine whether the SET is allowed, ie, is
the session user a member of the specified role.
It looks like the first time such a question is asked within a session,
we build and cache a list of all the roles the session user is a member
of (directly or indirectly). That's what's taking the time here ---
apparently in your test case, the "admin" role is a member of a whole lot
of roles?
regards, tom lane
2017-12-07 17:01 GMT+01:00 Tom Lane <tgl@sss.pgh.pa.us>:
Ulf Lohbrügge <ulf.lohbruegge@gmail.com> writes:
> 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.
This isn't particularly surprising in itself. When we know that the
session user is a superuser, SET ROLE just succeeds immediately.
Otherwise we have to determine whether the SET is allowed, ie, is
the session user a member of the specified role.
It looks like the first time such a question is asked within a session,
we build and cache a list of all the roles the session user is a member
of (directly or indirectly). That's what's taking the time here ---
apparently in your test case, the "admin" role is a member of a whole lot
of roles?
Yes, the user "admin" is member of more than 1k roles.
So this cache will not invalidate during the lifetime of the session unless a new role is added, I guess?
Is there any locking involved when this cache gets invalidated? Could this be a source for my earlier observed slow executions?
Regards,
Ulf
=?UTF-8?Q?Ulf_Lohbr=C3=BCgge?= <ulf.lohbruegge@gmail.com> writes:
> 2017-12-07 17:01 GMT+01:00 Tom Lane <tgl@sss.pgh.pa.us>:
>> It looks like the first time such a question is asked within a session,
>> we build and cache a list of all the roles the session user is a member
>> of (directly or indirectly). That's what's taking the time here ---
>> apparently in your test case, the "admin" role is a member of a whole lot
>> of roles?
> Yes, the user "admin" is member of more than 1k roles.
> So this cache will not invalidate during the lifetime of the session unless
> a new role is added, I guess?
It looks like any update to the role membership catalog (pg_auth_members)
invalidates that cache. So basically a "GRANT role" or "REVOKE role"
would do it.
> Is there any locking involved when this cache gets invalidated? Could this
> be a source for my earlier observed slow executions?
This particular aspect of things doesn't seem like such a problem to me,
but it's certainly possible that there are other aspects that get
unreasonably slow when there are that many role memberships involved.
Don't see what it'd have to do with SET SEARCH_PATH, though. Or RESET
ROLE; that doesn't require any permission checks, either.
regards, tom lane