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

[Ulf Lohbrügge]

2017-11-08 0:45 GMT+01:00 Tom Lane :

> =?UTF-8?Q?Ulf_Lohbr=C3=BCgge?=  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

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

[Tom Lane]

=?UTF-8?Q?Ulf_Lohbr=C3=BCgge?=  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

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

[Ulf Lohbrügge]

2017-11-07 22:39 GMT+01:00 Scott Marlowe :

> On Tue, Nov 7, 2017 at 2:25 PM, Ulf Lohbrügge 
> wrote:
> > 2017-11-07 20:45 GMT+01:00 Andres Freund :
> >>
> >> On 2017-11-07 18:48:14 +0100, Ulf Lohbrügge wrote:
> >> > Hi,
> >> >
> >> > 2017-11-07 16:11 GMT+01:00 Andres Freund :
> >> >
> >> > > 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

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

[Scott Marlowe]

On Tue, Nov 7, 2017 at 2:25 PM, Ulf Lohbrügge  wrote:
> 2017-11-07 20:45 GMT+01:00 Andres Freund :
>>
>> On 2017-11-07 18:48:14 +0100, Ulf Lohbrügge wrote:
>> > Hi,
>> >
>> > 2017-11-07 16:11 GMT+01:00 Andres Freund :
>> >
>> > > 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

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

[Ulf Lohbrügge]

2017-11-07 20:45 GMT+01:00 Andres Freund :

> On 2017-11-07 18:48:14 +0100, Ulf Lohbrügge wrote:
> > Hi,
> >
> > 2017-11-07 16:11 GMT+01:00 Andres Freund :
> >
> > > 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

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

[Andres Freund]

On 2017-11-07 18:48:14 +0100, Ulf Lohbrügge wrote:
> Hi,
> 
> 2017-11-07 16:11 GMT+01:00 Andres Freund :
> 
> > 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

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

[Ulf Lohbrügge]

Hi,

2017-11-07 16:11 GMT+01:00 Andres Freund :

> 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 : SET ROLE "tenant762"
> > 2017-11-07 09:44:30 CET [27659]: [4-1] user=admin,db=mydb LOG:  duration:
> > 1803.971 ms  execute : 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

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

[Andres Freund]

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 : SET ROLE "tenant762"
> 2017-11-07 09:44:30 CET [27659]: [4-1] user=admin,db=mydb LOG:  duration:
> 1803.971 ms  execute : 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

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

[Ulf Lohbrügge]

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 '';
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 : SET ROLE "tenant762"
2017-11-07 09:44:30 CET [27659]: [4-1] user=admin,db=mydb LOG:  duration:
1803.971 ms  execute : SET ROLE "tenant392"
2017-11-07 09:44:30 CET [27810]: [4-1] user=admin,db=mydb LOG:  duration:
1548.858 ms  execute : SET ROLE "tenant232"
2017-11-07 09:44:30 CET [27652]: [3-1] user=admin,db=mydb LOG:  duration:
1248.838 ms  execute : SET ROLE "tenant7"
2017-11-07 09:44:30 CET [27706]: [3-1] user=admin,db=mydb LOG:  duration:
998.044 ms  execute : SET ROLE "tenant1239"
2017-11-07 09:44:30 CET [27820]: [14-1] user=admin,db=mydb LOG:  duration:
1573.000 ms  execute : SET ROLE "tenant378"
2017-11-07 09:44:30 CET [28303]: [4-1] user=admin,db=mydb LOG:  duration:
2116.651 ms  execute : SET ROLE "tenant302"
2017-11-07 09:44:30 CET [27650]: [4-1] user=admin,db=mydb LOG:  duration:
2011.629 ms  execute : SET ROLE "tenant938"
2017-11-07 09:44:30 CET [28026]: [4-1] user=admin,db=mydb LOG:  duration:
2378.719 ms  execute : SET ROLE "tenant 634"
2017-11-07 09:44:30 CET [27708]: [7-1] user=admin,db=mydb LOG:  duration:
1327.962 ms  execute : SET ROLE "tenant22"
2017-11-07 09:44:30 CET [27707]: [4-1] user=admin,db=mydb LOG:  duration:
1366.602 ms  execute : SET ROLE "tenant22"
2017-11-07 09:44:30 CET [27610]: [8-1] user=admin,db=mydb LOG:  duration:
1098.192 ms  execute : SET ROLE "tenant22"
2017-11-07 09:44:30 CET [27762]: [3-1] user=admin,db=mydb LOG:  duration:
1349.368 ms  execute : SET ROLE "tenant22"
2017-11-07 09:44:30 CET [27756]: [4-1] user=admin,db=mydb LOG:  duration:
1735.926 ms  parse : SET search_path = DEFAULT
2017-11-07 09:44:31 CET [28190]: [4-1] user=admin,db=mydb LOG:  duration:
1987.256 ms  parse : SET search_path = DEFAULT
2017-11-07 09:44:31 CET [27646]: [3-1] user=admin,db=mydb LOG:  duration:
205.063 ms  execute : SET ROLE "tenant7"
2017-11-07 09:44:31 CET [27649]: [3-1] user=admin,db=mydb LOG:  duration:
225.152 ms  execute : SET ROLE "tenant302"
2017-11-07 09:44:31 CET [27654]: [5-1] user=admin,db=mydb LOG:  duration:
2235.243 ms  parse : SET search_path = DEFAULT
2017-11-07 09:44:31 CET [27674]: [4-1] user=admin,db=mydb LOG:  duration:
2080.905 ms  parse : SET search_path = DEFAULT
2017-11-07 09:44:31 CET [28307]: [5-1] user=admin,db=mydb LOG:  duration:
2351.064 ms  parse : SET search_path = DEFAULT
2017-11-07 09:44:31 CET [27681]: [4-1] user=admin,db=mydb LOG:  duration:
2455.486 ms  parse : SET search_path = DEFAULT
2017-11-07 09:44:31 CET [27651]: [4-1] user=admin,db=mydb LOG:  duration:
1830.737 ms  parse : SET search_path = DEFAULT
2017-11-07 09:44:32 CET [28137]: [4-1] user=admin,db=mydb LOG:  duration:
1973.241 ms  parse : SET search_path = DEFAULT
2017-11-07 09:44:32 CET [27682]: [4-1] user=admin,db=mydb LOG:  duration:
1863.962 ms  parse : SET search_path = DEFAULT
2017-11-07 09:44:32 CET [28243]: [4-1] user=admin,db=mydb LOG:  duration:
2120.339 ms  parse : SET search_path = DEFAULT
2017-11-07 09:44:32 CET [28025]: [5-1] user=admin,db=mydb LOG:  duration:
2643.520 ms  parse : SET search_path = DEFAULT
2017-11-07 09:44:32 CET [27709]: [7-1] user=admin,db=mydb LOG:  duration:
2519.842 ms  parse : SET search_path = DEFAULT
2017-11-07 09:44:32 CET [27655]: [5-1] user=admin,db=mydb LOG:  duration:
2622.280 ms  parse : SET search_path = DEFAULT
2017-11-07 09:44:32 CET [28242]: [4-1] user=admin,db=mydb LOG:  duration:
2326.483 ms  parse : SET search_path = DEFAULT
2017-11-07 09:44:32 CET [27652]: [4-1] user=admin,db=mydb LOG:  duration:
1746.423 ms  parse : SET search_path = DEFAULT
2017-11-07 09:44:32 CET [27706]: [4-1] user=admin,db=mydb LOG: