Re: [PERFORM] Slow execution of SET ROLE, SET search_path and RESET ROLE
2017-11-08 0:45 GMT+01:00 Tom Lane : > =?UTF-8?Q?Ulf_Lohbr=C3=BCgge?= writes: > > I just ran "check_postgres.pl --action=bloat" and got the following > output: > > ... > > Looks fine, doesn't it? > > A possible explanation is that something is taking an exclusive lock > on some system catalog and holding it for a second or two. If so, > turning on log_lock_waits might provide some useful info. > > regards, tom lane > I just checked my configuration and found out that "log_lock_waits" was already enabled. Unfortunately there is no log output of locks when those long running "SET ROLE" statements occur. Regards, Ulf
Re: [PERFORM] Slow execution of SET ROLE, SET search_path and RESET ROLE
=?UTF-8?Q?Ulf_Lohbr=C3=BCgge?= writes: > I just ran "check_postgres.pl --action=bloat" and got the following output: > ... > Looks fine, doesn't it? A possible explanation is that something is taking an exclusive lock on some system catalog and holding it for a second or two. If so, turning on log_lock_waits might provide some useful info. regards, tom lane -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance
Re: [PERFORM] Slow execution of SET ROLE, SET search_path and RESET ROLE
2017-11-07 22:39 GMT+01:00 Scott Marlowe : > On Tue, Nov 7, 2017 at 2:25 PM, Ulf Lohbrügge > wrote: > > 2017-11-07 20:45 GMT+01:00 Andres Freund : > >> > >> On 2017-11-07 18:48:14 +0100, Ulf Lohbrügge wrote: > >> > Hi, > >> > > >> > 2017-11-07 16:11 GMT+01:00 Andres Freund : > >> > > >> > > Hi, > >> > > > >> > > On 2017-11-07 11:11:36 +0100, Ulf Lohbrügge 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. > >> > >> Could you VACUUM (VERBOSE, FREEZE) that table and report the output? Do > >> you ever delete roles? > > > > > > Which table do you mean exactly? pg_catalog.pg_authid? > > > > Sorry, forgot to write that: I delete about 2-3 roles per day. > > I'm gonna take a guess that pg_users or pg_roles has gotten bloated > over time. Try running a vacuum full on both of them. It's also > possible some other pg_xxx table is bloated out here too you might > need to download something like checkpostgres.pl to check for bloat in > system catalog tables. > As pg_user and pg_roles are views: Do you mean pg_authid? That table is just 432kb large: --snip-- postgres=# select pg_size_pretty(pg_total_relation_size('pg_authid')); pg_size_pretty 432 kB (1 row) --snap-- I don't want to start a vacuum full right now because I'm not quite sure if things will lock up. But I will do it later when there is less traffic. I just ran "check_postgres.pl --action=bloat" and got the following output: --snip-- POSTGRES_BLOAT OK: DB "postgres" (host:localhost) (db postgres) index pg_shdepend_depender_index rows:? pages:9615 shouldbe:4073 (2.4X) wasted bytes:45400064 (43 MB) | pg_shdepend_depender_index=45400064B pg_catalog.pg_shdepend=9740288B pg_shdepend_reference_index=4046848B pg_depend_reference_index=98304B pg_depend_depender_index=57344B pg_catalog.pg_class=32768B pg_catalog.pg_description=16384B pg_amop_fam_strat_index=8192B pg_amop_opr_fam_index=8192B pg_catalog.pg_amop=8192B pg_catalog.pg_depend=8192B pg_class_oid_index=0B pg_class_relname_nsp_index=0B pg_class_tblspc_relfilenode_index=0B pg_description_o_c_o_index=0B --snap-- Looks fine, doesn't it? Cheers, Ulf
Re: [PERFORM] Slow execution of SET ROLE, SET search_path and RESET ROLE
On Tue, Nov 7, 2017 at 2:25 PM, Ulf Lohbrügge wrote: > 2017-11-07 20:45 GMT+01:00 Andres Freund : >> >> On 2017-11-07 18:48:14 +0100, Ulf Lohbrügge wrote: >> > Hi, >> > >> > 2017-11-07 16:11 GMT+01:00 Andres Freund : >> > >> > > Hi, >> > > >> > > On 2017-11-07 11:11:36 +0100, Ulf Lohbrügge 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. >> >> Could you VACUUM (VERBOSE, FREEZE) that table and report the output? Do >> you ever delete roles? > > > Which table do you mean exactly? pg_catalog.pg_authid? > > Sorry, forgot to write that: I delete about 2-3 roles per day. I'm gonna take a guess that pg_users or pg_roles has gotten bloated over time. Try running a vacuum full on both of them. It's also possible some other pg_xxx table is bloated out here too you might need to download something like checkpostgres.pl to check for bloat in system catalog tables. -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance
Re: [PERFORM] Slow execution of SET ROLE, SET search_path and RESET ROLE
2017-11-07 20:45 GMT+01:00 Andres Freund : > On 2017-11-07 18:48:14 +0100, Ulf Lohbrügge wrote: > > Hi, > > > > 2017-11-07 16:11 GMT+01:00 Andres Freund : > > > > > Hi, > > > > > > On 2017-11-07 11:11:36 +0100, Ulf Lohbrügge 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. > > Could you VACUUM (VERBOSE, FREEZE) that table and report the output? Do > you ever delete roles? > Which table do you mean exactly? pg_catalog.pg_authid? Sorry, forgot to write that: I delete about 2-3 roles per day. > > > 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. > > And most of that is going to be roundtrip time. Hm. Could it be that > you're just seeing the delays when pgbouncer establishes new pooling > connections and you're attributing that to SET ROLE in your app? > I stopped using pgbouncer when I solely started using role 'admin' with "SET ROLE" statements. I use a connection pool (HikariCP) that renews connections after 30 minutes. I couldn't find a pattern yet when those slow statements occur. Does using a few thousands roles and schemata in postgres scale well? I only found some theoretical descriptions of multi tenancy setups with postgres while googling. Using tabulator in psql cli is pretty slow, mainly because pg_table_is_visible() is being called for many entries in pg_class. Cheers, Ulf
Re: [PERFORM] Slow execution of SET ROLE, SET search_path and RESET ROLE
On 2017-11-07 18:48:14 +0100, Ulf Lohbrügge wrote: > Hi, > > 2017-11-07 16:11 GMT+01:00 Andres Freund : > > > Hi, > > > > On 2017-11-07 11:11:36 +0100, Ulf Lohbrügge 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. Could you VACUUM (VERBOSE, FREEZE) that table and report the output? Do you ever delete roles? > > 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. And most of that is going to be roundtrip time. Hm. Could it be that you're just seeing the delays when pgbouncer establishes new pooling connections and you're attributing that to SET ROLE in your app? Greetings, Andres Freund -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance
Re: [PERFORM] Slow execution of SET ROLE, SET search_path and RESET ROLE
Hi, 2017-11-07 16:11 GMT+01:00 Andres Freund : > Hi, > > On 2017-11-07 11:11:36 +0100, Ulf Lohbrügge 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 = 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 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" > > 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
Re: [PERFORM] Slow execution of SET ROLE, SET search_path and RESET ROLE
Hi, On 2017-11-07 11:11:36 +0100, Ulf Lohbrügge 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? > 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. Just to be sure: You realize bad application code could escape from that, right? > 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" 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? Greetings, Andres Freund -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance