[PERFORM] Slow execution of SET ROLE, SET search_path and RESET ROLE - Mailing list pgsql-performance

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