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
