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
