Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.84_2) (envelope-from ) id 1eC0rF-0005ho-CR for pgsql-performance@arkaria.postgresql.org; Tue, 07 Nov 2017 10:11:49 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.84_2) (envelope-from ) id 1eC0rE-0006h5-Di for pgsql-performance@arkaria.postgresql.org; Tue, 07 Nov 2017 10:11:48 +0000 Received: from makus.postgresql.org ([2001:4800:1501:1::229]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.84_2) (envelope-from ) id 1eC0rD-0006gs-FZ for pgsql-performance@postgresql.org; Tue, 07 Nov 2017 10:11:47 +0000 Received: from mail-lf0-x235.google.com ([2a00:1450:4010:c07::235]) by makus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.84_2) (envelope-from ) id 1eC0r5-0007gB-R4 for pgsql-performance@postgresql.org; Tue, 07 Nov 2017 10:11:46 +0000 Received: by mail-lf0-x235.google.com with SMTP id a16so13816702lfk.0 for ; Tue, 07 Nov 2017 02:11:39 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:from:date:message-id:subject:to; bh=907qoaDrEqc8DFQv2R9Pw2wpOFJNLCY8jlkGNvTJQyo=; b=FLGl9N3gdWrnJUTEisUTqw6AyguvLBE0nyjK9v/N1gHawZB8q9SqW6x9hAOpSCOD83 Wa0TLb3Ns2yAYI1jmsaA8AkZ3hoWmdUM9Ei7zkmMuuIFwq3UGC7ntR5bMGBfixPy7Ssf +oi6Ip2LUT6+7fwTzbfdEfx98uAJpFGOgitn4/pvVB1WI1pWhnvhxLog6ky7MOT8m4X5 v2a4TtlAL3d79E4+9ujjZsrIKMuvpaD99yDsfnYkyn6UoLq59mFm6w+fWqud7rRbhkMp lHbaNWyXXX/mr/KyQ0blX1xDI23gW/x0Y/b4m5gKokDU7HSVeDgILJ2oy/Wb5u3nz7K9 SO8g== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:from:date:message-id:subject:to; bh=907qoaDrEqc8DFQv2R9Pw2wpOFJNLCY8jlkGNvTJQyo=; b=ah7p1/IpJI0KirrMWVrL+csBGLCrZQy+IunaOojEctnuVk28Q/qCn+D8O2wno8sOu5 5Bj1q0M5/BXNcNfBkih72/4Fh6vvm3MuSAjAO0mA+jGJYr7huInS0vKzZ7Z2p77j6kAB tm0g5u/r0qOzgzkNrDhG+VxV8oXNmT3IyR8APWrywTOaPjmC2nZSNNc43tpwC8ieTAWc ZkvRxZC+eewqctOvnafOjOfoNp9A5I0A8sWIBc0ohde9857yYjPLEalBuvv6ESiM7evP Vi/bBU31vb3XFTYebjTbwqaV5ebm6inoSvGDVOuY1tJzYccvi/33Z7Y3Vb98ziq7Le42 iVeA== X-Gm-Message-State: AMCzsaVFH/AiTFvOSjO4PgG6RkqPeVdf2KU0HNH/mK9cm1KvVOGB8sWy Z8RqnjQ0aAJAgMCxl7vUHXil6rV0oHLuC+mhzCXkAA== X-Google-Smtp-Source: ABhQp+TmMIx51XqmJXbEcUsaxq8nPtZgkaR12ntmbf/lBQLCJVlFFcmm50k6FB95gDOHsqc1jzc8drQzTjanSNwyOqY= X-Received: by 10.25.80.87 with SMTP id z23mr6339669lfj.60.1510049497186; Tue, 07 Nov 2017 02:11:37 -0800 (PST) MIME-Version: 1.0 Received: by 10.25.74.202 with HTTP; Tue, 7 Nov 2017 02:11:36 -0800 (PST) From: =?UTF-8?Q?Ulf_Lohbr=C3=BCgge?= Date: Tue, 7 Nov 2017 11:11:36 +0100 Message-ID: Subject: Slow execution of SET ROLE, SET search_path and RESET ROLE To: pgsql-performance@postgresql.org Content-Type: multipart/alternative; boundary="94eb2c1cb042df881a055d61cb7b" List-Archive: List-Help: List-ID: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: X-Mailing-List: pgsql-performance Precedence: bulk Sender: pgsql-performance-owner@postgresql.org --94eb2c1cb042df881a055d61cb7b Content-Type: text/plain; charset="UTF-8" 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 : SET ROLE "tenant762" 2017-11-07 09:44:30 CET [27659]: [4-1] user=admin,db=mydb LOG: duration: 1803.971 ms execute : SET ROLE "tenant392" 2017-11-07 09:44:30 CET [27810]: [4-1] user=admin,db=mydb LOG: duration: 1548.858 ms execute : SET ROLE "tenant232" 2017-11-07 09:44:30 CET [27652]: [3-1] user=admin,db=mydb LOG: duration: 1248.838 ms execute : SET ROLE "tenant7" 2017-11-07 09:44:30 CET [27706]: [3-1] user=admin,db=mydb LOG: duration: 998.044 ms execute : SET ROLE "tenant1239" 2017-11-07 09:44:30 CET [27820]: [14-1] user=admin,db=mydb LOG: duration: 1573.000 ms execute : SET ROLE "tenant378" 2017-11-07 09:44:30 CET [28303]: [4-1] user=admin,db=mydb LOG: duration: 2116.651 ms execute : SET ROLE "tenant302" 2017-11-07 09:44:30 CET [27650]: [4-1] user=admin,db=mydb LOG: duration: 2011.629 ms execute : SET ROLE "tenant938" 2017-11-07 09:44:30 CET [28026]: [4-1] user=admin,db=mydb LOG: duration: 2378.719 ms execute : SET ROLE "tenant 634" 2017-11-07 09:44:30 CET [27708]: [7-1] user=admin,db=mydb LOG: duration: 1327.962 ms execute : SET ROLE "tenant22" 2017-11-07 09:44:30 CET [27707]: [4-1] user=admin,db=mydb LOG: duration: 1366.602 ms execute : SET ROLE "tenant22" 2017-11-07 09:44:30 CET [27610]: [8-1] user=admin,db=mydb LOG: duration: 1098.192 ms execute : SET ROLE "tenant22" 2017-11-07 09:44:30 CET [27762]: [3-1] user=admin,db=mydb LOG: duration: 1349.368 ms execute : SET ROLE "tenant22" 2017-11-07 09:44:30 CET [27756]: [4-1] user=admin,db=mydb LOG: duration: 1735.926 ms parse : SET search_path = DEFAULT 2017-11-07 09:44:31 CET [28190]: [4-1] user=admin,db=mydb LOG: duration: 1987.256 ms parse : SET search_path = DEFAULT 2017-11-07 09:44:31 CET [27646]: [3-1] user=admin,db=mydb LOG: duration: 205.063 ms execute : SET ROLE "tenant7" 2017-11-07 09:44:31 CET [27649]: [3-1] user=admin,db=mydb LOG: duration: 225.152 ms execute : SET ROLE "tenant302" 2017-11-07 09:44:31 CET [27654]: [5-1] user=admin,db=mydb LOG: duration: 2235.243 ms parse : SET search_path = DEFAULT 2017-11-07 09:44:31 CET [27674]: [4-1] user=admin,db=mydb LOG: duration: 2080.905 ms parse : SET search_path = DEFAULT 2017-11-07 09:44:31 CET [28307]: [5-1] user=admin,db=mydb LOG: duration: 2351.064 ms parse : SET search_path = DEFAULT 2017-11-07 09:44:31 CET [27681]: [4-1] user=admin,db=mydb LOG: duration: 2455.486 ms parse : SET search_path = DEFAULT 2017-11-07 09:44:31 CET [27651]: [4-1] user=admin,db=mydb LOG: duration: 1830.737 ms parse : SET search_path = DEFAULT 2017-11-07 09:44:32 CET [28137]: [4-1] user=admin,db=mydb LOG: duration: 1973.241 ms parse : SET search_path = DEFAULT 2017-11-07 09:44:32 CET [27682]: [4-1] user=admin,db=mydb LOG: duration: 1863.962 ms parse : SET search_path = DEFAULT 2017-11-07 09:44:32 CET [28243]: [4-1] user=admin,db=mydb LOG: duration: 2120.339 ms parse : SET search_path = DEFAULT 2017-11-07 09:44:32 CET [28025]: [5-1] user=admin,db=mydb LOG: duration: 2643.520 ms parse : SET search_path = DEFAULT 2017-11-07 09:44:32 CET [27709]: [7-1] user=admin,db=mydb LOG: duration: 2519.842 ms parse : SET search_path = DEFAULT 2017-11-07 09:44:32 CET [27655]: [5-1] user=admin,db=mydb LOG: duration: 2622.280 ms parse : SET search_path = DEFAULT 2017-11-07 09:44:32 CET [28242]: [4-1] user=admin,db=mydb LOG: duration: 2326.483 ms parse : SET search_path = DEFAULT 2017-11-07 09:44:32 CET [27652]: [4-1] user=admin,db=mydb LOG: duration: 1746.423 ms parse : SET search_path = DEFAULT 2017-11-07 09:44:32 CET [27706]: [4-1] user=admin,db=mydb LOG: duration: 1759.188 ms parse : SET search_path = DEFAULT 2017-11-07 09:44:32 CET [27603]: [5-1] user=admin,db=mydb LOG: duration: 2521.347 ms parse : SET search_path = DEFAULT 2017-11-07 09:44:32 CET [27818]: [5-1] user=admin,db=mydb LOG: duration: 2382.254 ms parse : SET search_path = DEFAULT 2017-11-07 09:44:32 CET [27761]: [5-1] user=admin,db=mydb LOG: duration: 2372.629 ms parse : 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 --94eb2c1cb042df881a055d61cb7b Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable
Hi there,

I'm using Post= greSQL 9.5.9 on Debian and experience slow execution of some basic SET stat= ements.

I created about 1600 roles and use that se= tup 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 NOI= NHERIT LOGIN PASSWORD 'XXXX';
GRANT tenant1 TO admin;
...
GRANT tenant1600 TO admin;

--= every tenant resides in its own schema
CREATE SCHEMA AUTHORIZATI= ON tenant1;
...
CREATE SCHEMA AUTHORIZATION tenant1600;=
--snap--

My application solely uses the= role 'admin' to connect to the database. When performing sql state= ments 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 =3D tenant1337;

Then the application uses that connection to perfor= m various statements in the database. As I'm using a connection pool, e= very connection that is returned to the pool executes the following command= s:

RESET ROLE;
SET search_path =3D DEFAU= LT;

My application is a web service that approxima= tely executes some hundred statements per second.

= I set "log_min_duration_statement =3D 200ms" and I get about 2k t= o 4k lines per day with statements like "SET ROLE"", "S= ET search_path ..." and "RESET ROLE":

--snip--
2017-11-07 09:44:30 CET [27760]: [3-1] user=3Dadmin,d= b=3Dmydb LOG:=C2=A0 duration: 901.591 ms=C2=A0 execute <unnamed>: SET= ROLE "tenant762"
2017-11-07 09:44:30 CET [27659]: [4-1= ] user=3Dadmin,db=3Dmydb LOG:=C2=A0 duration: 1803.971 ms=C2=A0 execute <= ;unnamed>: SET ROLE "tenant392"
2017-11-07 09:44:30 = CET [27810]: [4-1] user=3Dadmin,db=3Dmydb LOG:=C2=A0 duration: 1548.858 ms= =C2=A0 execute <unnamed>: SET ROLE "tenant232"
20= 17-11-07 09:44:30 CET [27652]: [3-1] user=3Dadmin,db=3Dmydb LOG:=C2=A0 dura= tion: 1248.838 ms=C2=A0 execute <unnamed>: SET ROLE "tenant7&quo= t;
2017-11-07 09:44:30 CET [27706]: [3-1] user=3Dadmin,db=3Dmydb = LOG:=C2=A0 duration: 998.044 ms=C2=A0 execute <unnamed>: SET ROLE &qu= ot;tenant1239"
2017-11-07 09:44:30 CET [27820]: [14-1] user= =3Dadmin,db=3Dmydb LOG:=C2=A0 duration: 1573.000 ms=C2=A0 execute <unnam= ed>: SET ROLE "tenant378"
2017-11-07 09:44:30 CET [2= 8303]: [4-1] user=3Dadmin,db=3Dmydb LOG:=C2=A0 duration: 2116.651 ms=C2=A0 = execute <unnamed>: SET ROLE "tenant302"
2017-11-0= 7 09:44:30 CET [27650]: [4-1] user=3Dadmin,db=3Dmydb LOG:=C2=A0 duration: 2= 011.629 ms=C2=A0 execute <unnamed>: SET ROLE "tenant938"
2017-11-07 09:44:30 CET [28026]: [4-1] user=3Dadmin,db=3Dmydb LOG:= =C2=A0 duration: 2378.719 ms=C2=A0 execute <unnamed>: SET ROLE "= tenant 634"
2017-11-07 09:44:30 CET [27708]: [7-1] user=3Dad= min,db=3Dmydb LOG:=C2=A0 duration: 1327.962 ms=C2=A0 execute <unnamed>= ;: SET ROLE "tenant22"
2017-11-07 09:44:30 CET [27707]:= [4-1] user=3Dadmin,db=3Dmydb LOG:=C2=A0 duration: 1366.602 ms=C2=A0 execut= e <unnamed>: SET ROLE "tenant22"
2017-11-07 09:44= :30 CET [27610]: [8-1] user=3Dadmin,db=3Dmydb LOG:=C2=A0 duration: 1098.192= ms=C2=A0 execute <unnamed>: SET ROLE "tenant22"
= 2017-11-07 09:44:30 CET [27762]: [3-1] user=3Dadmin,db=3Dmydb LOG:=C2=A0 du= ration: 1349.368 ms=C2=A0 execute <unnamed>: SET ROLE "tenant22&= quot;
2017-11-07 09:44:30 CET [27756]: [4-1] user=3Dadmin,db=3Dmy= db LOG:=C2=A0 duration: 1735.926 ms=C2=A0 parse <unnamed>: SET search= _path =3D DEFAULT
2017-11-07 09:44:31 CET [28190]: [4-1] user=3Da= dmin,db=3Dmydb LOG:=C2=A0 duration: 1987.256 ms=C2=A0 parse <unnamed>= : SET search_path =3D DEFAULT
2017-11-07 09:44:31 CET [27646]: [3= -1] user=3Dadmin,db=3Dmydb LOG:=C2=A0 duration: 205.063 ms=C2=A0 execute &l= t;unnamed>: SET ROLE "tenant7"
2017-11-07 09:44:31 C= ET [27649]: [3-1] user=3Dadmin,db=3Dmydb LOG:=C2=A0 duration: 225.152 ms=C2= =A0 execute <unnamed>: SET ROLE "tenant302"
2017-= 11-07 09:44:31 CET [27654]: [5-1] user=3Dadmin,db=3Dmydb LOG:=C2=A0 duratio= n: 2235.243 ms=C2=A0 parse <unnamed>: SET search_path =3D DEFAULT
2017-11-07 09:44:31 CET [27674]: [4-1] user=3Dadmin,db=3Dmydb LOG:= =C2=A0 duration: 2080.905 ms=C2=A0 parse <unnamed>: SET search_path = =3D DEFAULT
2017-11-07 09:44:31 CET [28307]: [5-1] user=3Dadmin,d= b=3Dmydb LOG:=C2=A0 duration: 2351.064 ms=C2=A0 parse <unnamed>: SET = search_path =3D DEFAULT
2017-11-07 09:44:31 CET [27681]: [4-1] us= er=3Dadmin,db=3Dmydb LOG:=C2=A0 duration: 2455.486 ms=C2=A0 parse <unnam= ed>: SET search_path =3D DEFAULT
2017-11-07 09:44:31 CET [2765= 1]: [4-1] user=3Dadmin,db=3Dmydb LOG:=C2=A0 duration: 1830.737 ms=C2=A0 par= se <unnamed>: SET search_path =3D DEFAULT
2017-11-07 09:44:= 32 CET [28137]: [4-1] user=3Dadmin,db=3Dmydb LOG:=C2=A0 duration: 1973.241 = ms=C2=A0 parse <unnamed>: SET search_path =3D DEFAULT
2017-= 11-07 09:44:32 CET [27682]: [4-1] user=3Dadmin,db=3Dmydb LOG:=C2=A0 duratio= n: 1863.962 ms=C2=A0 parse <unnamed>: SET search_path =3D DEFAULT
2017-11-07 09:44:32 CET [28243]: [4-1] user=3Dadmin,db=3Dmydb LOG:= =C2=A0 duration: 2120.339 ms=C2=A0 parse <unnamed>: SET search_path = =3D DEFAULT
2017-11-07 09:44:32 CET [28025]: [5-1] user=3Dadmin,d= b=3Dmydb LOG:=C2=A0 duration: 2643.520 ms=C2=A0 parse <unnamed>: SET = search_path =3D DEFAULT
2017-11-07 09:44:32 CET [27709]: [7-1] us= er=3Dadmin,db=3Dmydb LOG:=C2=A0 duration: 2519.842 ms=C2=A0 parse <unnam= ed>: SET search_path =3D DEFAULT
2017-11-07 09:44:32 CET [2765= 5]: [5-1] user=3Dadmin,db=3Dmydb LOG:=C2=A0 duration: 2622.280 ms=C2=A0 par= se <unnamed>: SET search_path =3D DEFAULT
2017-11-07 09:44:= 32 CET [28242]: [4-1] user=3Dadmin,db=3Dmydb LOG:=C2=A0 duration: 2326.483 = ms=C2=A0 parse <unnamed>: SET search_path =3D DEFAULT
2017-= 11-07 09:44:32 CET [27652]: [4-1] user=3Dadmin,db=3Dmydb LOG:=C2=A0 duratio= n: 1746.423 ms=C2=A0 parse <unnamed>: SET search_path =3D DEFAULT
2017-11-07 09:44:32 CET [27706]: [4-1] user=3Dadmin,db=3Dmydb LOG:= =C2=A0 duration: 1759.188 ms=C2=A0 parse <unnamed>: SET search_path = =3D DEFAULT
2017-11-07 09:44:32 CET [27603]: [5-1] user=3Dadmin,d= b=3Dmydb LOG:=C2=A0 duration: 2521.347 ms=C2=A0 parse <unnamed>: SET = search_path =3D DEFAULT
2017-11-07 09:44:32 CET [27818]: [5-1] us= er=3Dadmin,db=3Dmydb LOG:=C2=A0 duration: 2382.254 ms=C2=A0 parse <unnam= ed>: SET search_path =3D DEFAULT
2017-11-07 09:44:32 CET [2776= 1]: [5-1] user=3Dadmin,db=3Dmydb LOG:=C2=A0 duration: 2372.629 ms=C2=A0 par= se <unnamed>: SET search_path =3D DEFAULT
--snap--

Besides those peaks in statement duration, my application = performs (i.e. has acceptable response times) most of the time.
<= br>
Is there anything I can do to improve performance here?
=
Any help is greatly appreciated!

Regards,
Ulf
--94eb2c1cb042df881a055d61cb7b--