[gdal-dev] A performance issue when connecting to pg through PgPool.
CULOS
xavier.culos at eau-adour-garonne.fr
Tue Aug 11 02:38:30 PDT 2020
Hi,
is this the correct list for this issue ? It is about a problem of performence which concerns the couple GDAL / PgPool.
I am posting here because our other tools (talend, php, psycopg ...) which connect to the pool do not have this problem.
A trio of servers (pool, master, slave) have been working well so far, but...
under QGis, the following script launches a simple ogr.Open.
import osgeo.ogr as ogr
uri = "host=pool port=5432 dbname=dbname user=user password=password"
QgsMessageLog.logMessage("CONNECT", 'perfs', level=Qgis.Info)
conn = ogr.Open("PG:{}".format(uri))
QgsMessageLog.logMessage("OK", 'perfs', level=Qgis.Info)
And the result : a connection that lasts 8s.
2020-08-11T09:53:28 INFO CONNECT
(.. 8s ..)
2020-08-11T09:53:36 INFO OK
We find this delay of 8s when opening layers (first opened) in QGis. 9/10 times.
When you connect directly to the 'master' or to the 'slave', or when the pool is connected to only one node, the connection is immediate.
The ogrinfo command has the same behavior (ogrinfo -ro PG:"host=pool port=5432 dbname=my_db schemas=a_schema tables=a_table").
The pg servers logs are very different, depending on the case.
What is happening ? do you have an idea ?
Thanks,
Xavier.
----------------- Versions ------------
Gdal: 3.0.4 pgpool-II 4.0.9 or 4.1.2 PostgreSQL 11.7 (Debian 11.7-0+deb10u1)
---------------- LOGS ------------------
# direct connection to slave or master (no delay)
09:33:50 (57920) [20671-1] 0.108 ms, instruction : set client_encoding to 'UNICODE'
09:33:50 (57920) [20671-2] 0.319 ms, analyse <unnamed> : SELECT version()
09:33:50 (57920) [20671-3] 0.072 ms, lien <unnamed> : SELECT version()
09:33:50 (57920) [20671-4] 0.015 ms exécute <unnamed>: SELECT version()
09:33:50 (57920) [20671-5] 0.014 ms, analyse <unnamed> : SHOW standard_conforming_strings
09:33:50 (57920) [20671-6] 0.005 ms, lien <unnamed> : SHOW standard_conforming_strings
09:33:50 (57920) [20671-7] 0.023 ms exécute <unnamed>: SHOW standard_conforming_strings
09:33:50 (57920) [20671-8] 0.386 ms, analyse <unnamed> : SELECT oid, typname FROM pg_type WHERE typname IN ('geometry', 'geography') AND typtype='b'
09:33:50 (57920) [20671-9] 0.724 ms, lien <unnamed> : SELECT oid, typname FROM pg_type WHERE typname IN ('geometry', 'geography') AND typtype='b'
09:33:50 (57920) [20671-10] 0.052 ms exécute <unnamed>: SELECT oid, typname FROM pg_type WHERE typname IN ('geometry', 'geography') AND typtype='b'
09:33:50 (57920) [20671-11] 0.050 ms, analyse <unnamed> : SELECT postgis_version()
09:33:50 (57920) [20671-12] 46.468 ms, lien <unnamed> : SELECT postgis_version()
09:33:50 (57920) [20671-13] 0.026 ms exécute <unnamed>: SELECT postgis_version()
09:33:50 (57920) [20671-14] 0.036 ms, analyse <unnamed> : SET ENABLE_SEQSCAN = ON
09:33:50 (57920) [20671-15] 0.007 ms, lien <unnamed> : SET ENABLE_SEQSCAN = ON
09:33:50 (57920) [20671-16] 0.034 ms exécute <unnamed>: SET ENABLE_SEQSCAN = ON
09:33:50 (57920) [20671-17] 2.195 ms, analyse <unnamed> : SELECT 1 FROM information_schema.tables WHERE table_name = 'geometry_columns' LIMIT 1
09:33:50 (57920) [20671-18] 2.019 ms, lien <unnamed> : SELECT 1 FROM information_schema.tables WHERE table_name = 'geometry_columns' LIMIT 1
09:33:50 (57920) [20671-19] 1.823 ms exécute <unnamed>: SELECT 1 FROM information_schema.tables WHERE table_name = 'geometry_columns' LIMIT 1
09:33:50 (57920) [20671-20] 0.138 ms, analyse <unnamed> : SELECT 1 FROM information_schema.tables WHERE table_name = 'spatial_ref_sys' LIMIT 1
09:33:50 (57920) [20671-21] 0.520 ms, lien <unnamed> : SELECT 1 FROM information_schema.tables WHERE table_name = 'spatial_ref_sys' LIMIT 1
09:33:50 (57920) [20671-22] 0.866 ms exécute <unnamed>: SELECT 1 FROM information_schema.tables WHERE table_name = 'spatial_ref_sys' LIMIT 1
09:33:50 (57920) [20671-23] 0.201 ms, analyse <unnamed> : SELECT ST_Srid('POINT EMPTY'::GEOMETRY)
09:33:50 (57920) [20671-24] 0.033 ms, lien <unnamed> : SELECT ST_Srid('POINT EMPTY'::GEOMETRY)
09:33:50 (57920) [20671-25] 0.005 ms exécute <unnamed>: SELECT ST_Srid('POINT EMPTY'::GEOMETRY)
09:33:50 (57920) [20671-26] 0.053 ms, analyse <unnamed> : SELECT current_schema()
09:33:50 (57920) [20671-27] 0.022 ms, lien <unnamed> : SELECT current_schema()
09:33:50 (57920) [20671-28] 0.007 ms exécute <unnamed>: SELECT current_schema()
# connection through the 'pool' (8s)
# some requests are sent to the 'master', others to the 'slave'
# master log
09:35:06 (38174) [3076-1] 0.105 ms, instruction : set client_encoding to 'UNICODE'
09:35:06 (38174) [3076-2] 0.652 ms, analyse pgpool2087 : SELECT count(*) from (SELECT has_function_privilege('saisie_qgis', 'pg_catalog.to_regclass(cstring)', 'execute') WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE p.proname = 'to_regclass')) AS s
09:35:06 (38174) [3076-3] 0.649 ms, lien pgpool2087/pgpool2087 : SELECT count(*) from (SELECT has_function_privilege('saisie_qgis', 'pg_catalog.to_regclass(cstring)', 'execute') WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE p.proname = 'to_regclass')) AS s
09:35:06 (38174) [3076-4] 0.042 ms exécute pgpool2087/pgpool2087: SELECT count(*) from (SELECT has_function_privilege('saisie_qgis', 'pg_catalog.to_regclass(cstring)', 'execute') WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE p.proname = 'to_regclass')) AS s
09:35:06 (38174) [3076-5] 0.080 ms, analyse pgpool2087 : SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname = 'pg_namespace'
09:35:06 (38174) [3076-6] 0.166 ms, lien pgpool2087/pgpool2087 : SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname = 'pg_namespace'
09:35:06 (38174) [3076-7] 0.048 ms exécute pgpool2087/pgpool2087: SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname = 'pg_namespace'
09:35:06 (38174) [3076-8] 0.541 ms, analyse pgpool2087 : SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = pg_catalog.to_regclass('"pg_type"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
09:35:06 (38174) [3076-9] 0.329 ms, lien pgpool2087/pgpool2087 : SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = pg_catalog.to_regclass('"pg_type"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
09:35:06 (38174) [3076-10] 0.028 ms exécute pgpool2087/pgpool2087: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = pg_catalog.to_regclass('"pg_type"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
09:35:06 (38174) [3076-11] 0.100 ms, analyse <unnamed> : SELECT oid, typname FROM pg_type WHERE typname IN ('geometry', 'geography') AND typtype='b'
09:35:06 (38174) [3076-12] 0.327 ms, lien <unnamed> : SELECT oid, typname FROM pg_type WHERE typname IN ('geometry', 'geography') AND typtype='b'
09:35:06 (38174) [3076-13] 0.050 ms exécute <unnamed>: SELECT oid, typname FROM pg_type WHERE typname IN ('geometry', 'geography') AND typtype='b'
09:35:08 (38174) [3076-14] 0.047 ms, analyse <unnamed> : SET ENABLE_SEQSCAN = ON
09:35:08 (38174) [3076-15] 0.028 ms, lien <unnamed> : SET ENABLE_SEQSCAN = ON
09:35:08 (38174) [3076-16] 0.032 ms exécute <unnamed>: SET ENABLE_SEQSCAN = ON
09:35:08 (38174) [3076-17] 0.164 ms, analyse pgpool2087 : SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = pg_catalog.to_regclass('"tables"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
09:35:08 (38174) [3076-18] 0.426 ms, lien pgpool2087/pgpool2087 : SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = pg_catalog.to_regclass('"tables"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
09:35:08 (38174) [3076-19] 0.019 ms exécute pgpool2087/pgpool2087: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = pg_catalog.to_regclass('"tables"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
09:35:08 (38174) [3076-20] 0.131 ms, analyse pgpool2087 : SELECT count(*) FROM pg_catalog.pg_class AS c, pg_attribute AS a WHERE c.relname = 'pg_class' AND a.attrelid = c.oid AND a.attname = 'relistemp'
09:35:08 (38174) [3076-21] 0.470 ms, lien pgpool2087/pgpool2087 : SELECT count(*) FROM pg_catalog.pg_class AS c, pg_attribute AS a WHERE c.relname = 'pg_class' AND a.attrelid = c.oid AND a.attname = 'relistemp'
09:35:08 (38174) [3076-22] 0.062 ms exécute pgpool2087/pgpool2087: SELECT count(*) FROM pg_catalog.pg_class AS c, pg_attribute AS a WHERE c.relname = 'pg_class' AND a.attrelid = c.oid AND a.attname = 'relistemp'
09:35:08 (38174) [3076-23] 0.259 ms, analyse pgpool2087 : SELECT count(*) FROM pg_catalog.pg_class AS c, pg_namespace AS n WHERE c.relname = 'tables' AND c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
09:35:08 (38174) [3076-24] 0.401 ms, lien pgpool2087/pgpool2087 : SELECT count(*) FROM pg_catalog.pg_class AS c, pg_namespace AS n WHERE c.relname = 'tables' AND c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
09:35:08 (38174) [3076-25] 0.407 ms exécute pgpool2087/pgpool2087: SELECT count(*) FROM pg_catalog.pg_class AS c, pg_namespace AS n WHERE c.relname = 'tables' AND c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
09:35:08 (38174) [3076-26] 0.066 ms, analyse pgpool2087 : SELECT count(*) FROM pg_catalog.pg_class AS c, pg_catalog.pg_attribute AS a WHERE c.relname = 'pg_class' AND a.attrelid = c.oid AND a.attname = 'relpersistence'
09:35:08 (38174) [3076-27] 0.199 ms, lien pgpool2087/pgpool2087 : SELECT count(*) FROM pg_catalog.pg_class AS c, pg_catalog.pg_attribute AS a WHERE c.relname = 'pg_class' AND a.attrelid = c.oid AND a.attname = 'relpersistence'
09:35:08 (38174) [3076-28] 0.042 ms exécute pgpool2087/pgpool2087: SELECT count(*) FROM pg_catalog.pg_class AS c, pg_catalog.pg_attribute AS a WHERE c.relname = 'pg_class' AND a.attrelid = c.oid AND a.attname = 'relpersistence'
09:35:08 (38174) [3076-29] 0.077 ms, analyse pgpool2087 : SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.oid = pg_catalog.to_regclass('"information_schema"."tables"') AND c.relpersistence = 'u'
09:35:08 (38174) [3076-30] 0.149 ms, lien pgpool2087/pgpool2087 : SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.oid = pg_catalog.to_regclass('"information_schema"."tables"') AND c.relpersistence = 'u'
09:35:08 (38174) [3076-31] 0.021 ms exécute pgpool2087/pgpool2087: SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.oid = pg_catalog.to_regclass('"information_schema"."tables"') AND c.relpersistence = 'u'
# slave log
09:35:06 (42560) [21079-1] 0.116 ms, instruction : set client_encoding to 'UNICODE'
09:35:06 (42560) [21079-2] 0.372 ms, analyse <unnamed> : SELECT version()
09:35:06 (42560) [21079-3] 0.067 ms, lien <unnamed> : SELECT version()
09:35:06 (42560) [21079-4] 0.050 ms exécute <unnamed>: SELECT version()
09:35:06 (42560) [21079-5] 0.016 ms, analyse <unnamed> : SHOW standard_conforming_strings
09:35:06 (42560) [21079-6] 0.006 ms, lien <unnamed> : SHOW standard_conforming_strings
09:35:06 (42560) [21079-7] 0.019 ms exécute <unnamed>: SHOW standard_conforming_strings
09:35:06 (42560) [21079-8] 0.116 ms, analyse <unnamed> : SELECT postgis_version()
09:35:06 (42560) [21079-9] 42.548 ms, lien <unnamed> : SELECT postgis_version()
09:35:06 (42560) [21079-10] 0.014 ms exécute <unnamed>: SELECT postgis_version()
09:35:06 (42560) [21079-11] 0.026 ms, analyse <unnamed> : SET ENABLE_SEQSCAN = ON
09:35:06 (42560) [21079-12] 0.008 ms, lien <unnamed> : SET ENABLE_SEQSCAN = ON
09:35:06 (42560) [21079-13] 0.031 ms exécute <unnamed>: SET ENABLE_SEQSCAN = ON
09:35:09 (42560) [21079-14] 1.559 ms, analyse <unnamed> : SELECT 1 FROM information_schema.tables WHERE table_name = 'geometry_columns' LIMIT 1
09:35:09 (42560) [21079-15] 1.363 ms, lien <unnamed> : SELECT 1 FROM information_schema.tables WHERE table_name = 'geometry_columns' LIMIT 1
09:35:09 (42560) [21079-16] 1.261 ms exécute <unnamed>: SELECT 1 FROM information_schema.tables WHERE table_name = 'geometry_columns' LIMIT 1
09:35:09 (42560) [21079-17] 0.130 ms, analyse <unnamed> : SELECT 1 FROM information_schema.tables WHERE table_name = 'spatial_ref_sys' LIMIT 1
09:35:09 (42560) [21079-18] 0.472 ms, lien <unnamed> : SELECT 1 FROM information_schema.tables WHERE table_name = 'spatial_ref_sys' LIMIT 1
09:35:09 (42560) [21079-19] 0.711 ms exécute <unnamed>: SELECT 1 FROM information_schema.tables WHERE table_name = 'spatial_ref_sys' LIMIT 1
09:35:12 (42560) [21079-20] 0.260 ms, analyse <unnamed> : SELECT ST_Srid('POINT EMPTY'::GEOMETRY)
09:35:12 (42560) [21079-21] 0.050 ms, lien <unnamed> : SELECT ST_Srid('POINT EMPTY'::GEOMETRY)
09:35:12 (42560) [21079-22] 0.008 ms exécute <unnamed>: SELECT ST_Srid('POINT EMPTY'::GEOMETRY)
09:35:12 (42560) [21079-23] 0.050 ms, analyse <unnamed> : SELECT current_schema()
09:35:12 (42560) [21079-24] 0.018 ms, lien <unnamed> : SELECT current_schema()
09:35:12 (42560) [21079-25] 0.007 ms exécute <unnamed>: SELECT current_schema()
More information about the gdal-dev
mailing list