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