Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.84_2) (envelope-from ) id 1eC80o-0000QQ-Px for pgsql-performance@arkaria.postgresql.org; Tue, 07 Nov 2017 17:50:10 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.84_2) (envelope-from ) id 1eC80n-000712-1K for pgsql-performance@arkaria.postgresql.org; Tue, 07 Nov 2017 17:50:09 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.84_2) (envelope-from ) id 1eC7z2-0003pF-9o for pgsql-performance@postgresql.org; Tue, 07 Nov 2017 17:48:20 +0000 Received: from mail-lf0-x22e.google.com ([2a00:1450:4010:c07::22e]) by magus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.84_2) (envelope-from ) id 1eC7yy-0000Z9-FL for pgsql-performance@postgresql.org; Tue, 07 Nov 2017 17:48:19 +0000 Received: by mail-lf0-x22e.google.com with SMTP id r135so31932lfe.5 for ; Tue, 07 Nov 2017 09:48:16 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:in-reply-to:references:from:date:message-id:subject:to :cc; bh=Jn//0hcXwGNHB+DAzIcsk5HzIJ68zqXCPqRVgJO0fJk=; b=kEOoRbAquAUfNlTt1Za5d5QJcrzhzpYch7Tjoo8KTuo2/1YYEARiZ8LCv9DF9cN3bn p8xqzuy+mSUJjZybL4gIg8tNu5qsFvmYb8+KbrtKLSJXqV5e0RKiK4F5LZBQy8XwxA/Y W80bkAXdjLQ16NCvJ/cT3QdUjPG95LUuQma6gnrDDBPNGGCnzacEQ9xQxzxDCDuWC9S4 IkV49ZTD5+wf6evmLZ03lZroWvIRwlHo4w7YDXPJANbidAyII8RYlMyqbtNryxABCN+d lEAhHy97GGCET6haDTcFJdHHn6NgNKZ3hbyOmxgMuqABDZAVtethzvZhDxv2+NwfsNRP lGZQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:in-reply-to:references:from:date :message-id:subject:to:cc; bh=Jn//0hcXwGNHB+DAzIcsk5HzIJ68zqXCPqRVgJO0fJk=; b=Ydnao+wZTfGp5sZ6bo6qLB+AdFl0i50pa7vVmklv47DuYUiiAm/XjIEEC84n0my/Ci kEdRzq5v+rHPOopN6srBgJR7nopZYdxPQGqPZ88+1X8GMQwNdMXi4D13zFMCg7u17K5k huS5ZZ/Y+C3OXfu1+arj6fuMJM1/FYFtkju/X+oTtCPaW2mA//Qaugum2/x0rGOAoi+J jYHznt4wu7DgMmbkFbkvraEHRSTkHEMHeZEWTt7LNwkbM2uzFBvaRD90fR+bn1JiCzfG Xanykcw+usX+3520zv+ZWitfE1IDjQdqf4ONPV41HKUnTDfJO237wUexmifRxSUIf4wk A6Ig== X-Gm-Message-State: AMCzsaX+4FPl3dDxn6bNO/T4mHC71dK7xjbgIoYEIFLYBtDtsVwh4lKa yn6zg4lmKSMlvEGwWxK2hfwidOINQv+/Tcl/UUQJGw== X-Google-Smtp-Source: ABhQp+S8HwhoskDUTuo0wZhQZn6eMvDiYSJUggXRQfKUlQdKxscxz0QEYhRWnoAF9LbzXMssXb/vNKVe+WY0MCNfFcs= X-Received: by 10.46.57.25 with SMTP id g25mr8117882lja.36.1510076894767; Tue, 07 Nov 2017 09:48:14 -0800 (PST) MIME-Version: 1.0 Received: by 10.25.74.202 with HTTP; Tue, 7 Nov 2017 09:48:14 -0800 (PST) In-Reply-To: <20171107151108.3jtmta4xrgmuyrqf@alap3.anarazel.de> References: <20171107151108.3jtmta4xrgmuyrqf@alap3.anarazel.de> From: =?UTF-8?Q?Ulf_Lohbr=C3=BCgge?= Date: Tue, 7 Nov 2017 18:48:14 +0100 Message-ID: Subject: Re: Slow execution of SET ROLE, SET search_path and RESET ROLE To: Andres Freund Cc: pgsql-performance@postgresql.org Content-Type: multipart/alternative; boundary="089e082f29c4e56f2e055d682cce" 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 --089e082f29c4e56f2e055d682cce Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable Hi, 2017-11-07 16:11 GMT+01:00 Andres Freund : > Hi, > > On 2017-11-07 11:11:36 +0100, Ulf Lohbr=C3=BCgge wrote: > > 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: > > Hm. How often do you drop/create these roles? How many other > roles/groups is one role a member of? > I create between 10-40 roles per day. The roles tenant1 to tenant1600 are not members of any other roles. Only the role 'admin' is member of many roles (tenant1 to tenant1600). > > > > 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 =3D tenant1337; > > > > Then the application uses that connection to perform various statements > in > > the database. > > Just to be sure: You realize bad application code could escape from > that, right? > Yes, I do. :) My application executes all statements via an ORM tool (Hibernate). But evil code could still get the plain DB-Connection and execute "SET ROLE ..." statements. My application used to connect as tenant1 to tenant1600 but that lead to a vast amount of postgresql connections (even with pgbouncer). > > > > My application is a web service that approximately executes some hundre= d > > statements per second. > > > > I set "log_min_duration_statement =3D 200ms" and I get about 2k to 4k l= ines > > 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=3Dadmin,db=3Dmydb LOG: dur= ation: > > 901.591 ms execute : SET ROLE "tenant762" > > 2017-11-07 09:44:30 CET [27659]: [4-1] user=3Dadmin,db=3Dmydb LOG: dur= ation: > > 1803.971 ms execute : SET ROLE "tenant392" > > That is weird. > > > > 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! > > Can you manually reproduce the problem? What times do you get if you > manually run the statement? > Unfortunately not. Every time I manually execute "SET ROLE ..." the statement is pretty fast. I created a simple SQL file that contains the following statements: --snip-- SET ROLE tenant382; SET ROLE tenant1337; SET ROLE tenant2; -- repeat the lines above 100k times --snap-- When I execute those statements via 'time psql < set-roles.sql', the call lasts 138,7 seconds. So 300k "SET ROLE" statements result in 0,46ms per call on average. Cheers, Ulf --089e082f29c4e56f2e055d682cce Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable
Hi,

2017-11-07 16:11 GMT+01:00 Andres Freund <andres@anarazel.de&g= t;:
Hi,

On 2017-11-07 11:11:36 +0100, Ulf Lohbr=C3=BCgge wrote:
> 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:

Hm. How often do you drop/create these roles?=C2=A0 How many other roles/groups is one role a member of?

I= create between 10-40 roles per day.

The roles ten= ant1 to tenant1600 are not members of any other roles. Only the role 'a= dmin' is member of many roles (tenant1 to tenant1600).
=C2=A0=


> 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 =3D tenant1337;
>
> Then the application uses that connection to perform various statement= s in
> the database.

Just to be sure: You realize bad application code could escape from<= br> that, right?

Yes, I do. :)
My= application executes all statements via an ORM tool (Hibernate). But evil = code could still get the plain DB-Connection and execute "SET ROLE ...= " statements. My application used to connect as tenant1 to tenant1600 = but that lead to a vast amount of postgresql connections (even with pgbounc= er).
=C2=A0


> My application is a web service that approximately executes some hundr= ed
> statements per second.
>
> I set "log_min_duration_statement =3D 200ms" and I get about= 2k to 4k lines
> per day with statements like "SET ROLE"", "SET sea= rch_path ..." and "RESET
> ROLE":
>
> --snip--
> 2017-11-07 09:44:30 CET [27760]: [3-1] user=3Dadmin,db=3Dmydb LOG:=C2= =A0 duration:
> 901.591 ms=C2=A0 execute <unnamed>: SET ROLE "tenant762&quo= t;
> 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&qu= ot;

That is weird.


> 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!

Can you manually reproduce the problem? What times do you get if you=
manually run the statement?

Unfortunate= ly not. Every time I manually execute "SET ROLE ..." the statemen= t is pretty fast. I created a simple SQL file that contains the following s= tatements:

--snip--
SET ROLE tenant382;<= /div>
SET ROLE tenant1337;
SET ROLE tenant2;
-- rep= eat the lines above 100k times
--snap--

= When I execute those statements via 'time psql < set-roles.sql',= the call lasts 138,7 seconds. So 300k "SET ROLE" statements resu= lt in 0,46ms per call on average.

Cheers,
Ulf

--089e082f29c4e56f2e055d682cce--