[QGIS-Developer] Why so many database calls?

[Cory Albrecht]

So QGIS took almost 2.5 hours to delete those 1,000-ish vertices, spitting
out those seemingly unnecessary transaction blocks every second or so.
Judging by the numbers of the named blocks, roughly 5,000 of them were done
just to delete those 1,000-ish vertices.

Right now, on that same feature, I went to add a new vertx in the middle of
the gap created by the deletion of the 1,000-ish last night, drag it to a
new spot, and right clock to place. Those same seemingly unnecessary
read-only transactions with a single select are being done, but at the rate
of roughly 100 per second and the process takes about 7-8 minutes after the
right click before QGIS becomes responsive again. I've done it a few times
this morning, exiting QGIS without saving, and same thing each time.

Why so many of these database queries?


On Thu, Jun 15, 2023 at 5:40 PM Cory Albrecht <maps at hanfastolfe.com> wrote:

> Hello,
>
> So I've been trying to track down why my postgresql server was getting so
> many Signal 10 (SUG BS, memory bus) errors. So far I have figured out that
> they are only happening when QGIS is connecting to it using GSS/Kerberos
> encryption. No clue yet as to which side is the culprit (e.g. bad QGIS
> kerberised data flow, or bad PostgreSQL handling of the connection). QGIS
> cinnectio with SSL encryption is fine.
>
> Anyways, while doing this I've been watching a lot of PostgreSQL server
> logs, and I noticed the following behaviour of QGIS:
>
> When using the vertex editor to delete a whole slew (1,000-ish) vertices
> from a polygon feature, I saw that QGIS was making repeated DB cals like
> this:
>
> Jun 15 17:14:19 postgresql-3 postgres[87136]: [3204-1] ::>[2023-06-15
> 17:14:19.289 EDT][648b7d94.15460][87136/] <maps%Alternate History> LOG:
>  duration: 0.330 ms  statement: BEGIN READ ONLY;DECLARE qgis_1062 BINARY
> CURSOR FOR SELECT
> "feature_uuid"::text,"name"::text,"start_date"::text,"end_date"::text,"main_rgb"::text,"realm_uuid"::text,"stripe_rgb"::text,"border_rgb"::text,"border_shade"::text,"sovereign"::text,"type"::text,"info_url"::text,array_out("predecessors")::text,array_out("successors")::text,boolout("visible")::text,boolout("has_children")::text,"full_name"::text,"alternate_name"::text,"flag_url"::text
> FROM "Balance of Power"."timeline_level0" WHERE
> "feature_uuid"::text='fbbec581-eb8f-4068-8729-8f9d63896bd5'
> Jun 15 17:14:19 postgresql-3 postgres[87136]: [3205-1] ::>[2023-06-15
> 17:14:19.290 EDT][648b7d94.15460][87136/] <maps%Alternate History> LOG:
>  duration: 0.628 ms  statement: FETCH FORWARD 2000 FROM qgis_1062
> Jun 15 17:14:19 postgresql-3 postgres[87136]: [3206-1] ::>[2023-06-15
> 17:14:19.291 EDT][648b7d94.15460][87136/] <maps%Alternate History> LOG:
>  duration: 0.045 ms  statement: CLOSE qgis_1062;COMMIT
>
> An example of the QGIS console output:
>
> ./src/core/qgsmessagelog.cpp:29 : (logMessage) [4ms] 2023-06-15T17:37:08
> PostGIS[1] NOTICE: LOG:  duration: 0.399 ms  statement: FETCH FORWARD 2000
> FROM qgis_2017
> ./src/core/qgsmessagelog.cpp:29 : (logMessage) [1ms] 2023-06-15T17:37:08
> PostGIS[1] NOTICE: LOG:  duration: 0.035 ms  statement: CLOSE
> qgis_2017;COMMIT
> ./src/core/qgsmessagelog.cpp:29 : (logMessage) [3ms] 2023-06-15T17:37:08
> PostGIS[1] NOTICE: LOG:  duration: 0.240 ms  statement: BEGIN READ
> ONLY;DECLARE qgis_2018 BINARY CURSOR FOR SELECT
> "feature_uuid"::text,"name"::text,"start_date"::text,"end_date"::text,"main_rgb"::text,"realm_uuid"::text,"stripe_rgb"::text,"border_rgb"::text,"border_shade"::text,"sovereign"::text,"type"::text,"info_url"::text,array_out("predecessors")::text,array_out("successors")::text,boolout("visible")::text,boolout("has_children")::text,"full_name"::text,"alternate_name"::text,"flag_url"::text
> FROM "Balance of Power"."timeline_level0" WHERE
> "feature_uuid"::text='fbbec581-eb8f-4068-8729-8f9d63896bd5'
> ./src/core/qgsmessagelog.cpp:29 : (logMessage) [2ms] 2023-06-15T17:37:08
> PostGIS[1] NOTICE: LOG:  duration: 0.406 ms  statement: FETCH FORWARD 2000
> FROM qgis_2018
> ./src/core/qgsmessagelog.cpp:29 : (logMessage) [1ms] 2023-06-15T17:37:08
> PostGIS[1] NOTICE: LOG:  duration: 0.034 ms  statement: CLOSE
> qgis_2018;COMMIT
>
>
>
> That is repeated 4 times every couple of seconds as I wait for QGIS to
> finish deleting these 1,000-ish vertices. So far it's at begin block
> qgis_2058 (increasing sequentially) and it's been 20+ minutes that QGIS has
> been frozen, CPU usage for the process jumping around between 100% and 300%.
>
> (Before you ask, Fall 2021 Dell XPS 9510, 11th Gen Intel Core i9-11900H @
> 2.50GHz 8 cores, 64GB RAM.)
>
> So why is it repeatedly making database calls to get the non geometry
> attributes of that same singular feature? Why can't it just use the cached
> data instead of making all these wasteful DB queries?
>
> And why is it taking so long to delete the vertices? Is it related to all
> the unnecessary DB queries?
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.osgeo.org/pipermail/qgis-developer/attachments/20230616/5c468dfe/attachment-0001.htm>