Subject: Slow execution of SET ROLE, SET search_path and RESET ROLE

From: Ulf Lohbrügge <[email-masked]>
Date: Tue, 7 Nov 2017 11:11:36 +0100

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

---

From: Andres Freund <[email-masked]>
Date: Tue, 7 Nov 2017 07:11:08 -0800

Hi,

> I created about 1600 roles and use that setup for a multi tenancy

Hm. How often do you drop/create these roles?  How many other
roles/groups is one role a member of?

> the database.

Just to be sure: You realize bad application code could escape from
that, right?

> 1803.971 ms  execute <unnamed>: SET ROLE "tenant392"

That is weird.

> 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 ([email-masked])
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance

---

From: Ulf Lohbrügge <[email-masked]>
Date: Tue, 7 Nov 2017 18:48:14 +0100

Hi,

> 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).

> Just to be sure: You realize bad application code could escape from

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).

> 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

---

From: Andres Freund <[email-masked]>
Date: Tue, 7 Nov 2017 11:45:17 -0800

> I create between 10-40 roles per day.

Could you VACUUM (VERBOSE, FREEZE) that table and report the output?  Do
you ever delete roles?

> lasts 138,7 seconds. So 300k "SET ROLE" statements result in 0,46ms per

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

---

From: Ulf Lohbrügge <[email-masked]>
Date: Tue, 7 Nov 2017 22:25:36 +0100

> Could you VACUUM (VERBOSE, FREEZE) that table and report the output?  Do

Which table do you mean exactly? pg_catalog.pg_authid?

Sorry, forgot to write that: I delete about 2-3 roles per day.

> 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

---

From: Scott Marlowe <[email-masked]>
Date: Tue, 7 Nov 2017 14:39:15 -0700

On Tue, Nov 7, 2017 at 2:25 PM, Ulf Lohbrügge <[email-masked]> wrote:
>> > > > I'm using PostgreSQL 9.5.9 on Debian and experience slow execution
>> > > > of
>> > > some
>> > > > basic SET statements.
>> > > >

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.

---

From: Ulf Lohbrügge <[email-masked]>
Date: Wed, 8 Nov 2017 00:04:18 +0100

> need to download something like checkpostgres.pl to check for bloat in

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

---

From: Tom Lane <[email-masked]>
Date: Tue, 07 Nov 2017 18:45:47 -0500

> I just ran "check_postgres.pl --action=bloat" and got the following output:

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

---

From: Ulf Lohbrügge <[email-masked]>
Date: Wed, 8 Nov 2017 10:31:42 +0100

> turning on log_lock_waits might provide some useful info.

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