[QGIS-Developer] Why so many database calls?

[Cory Albrecht]

So, nobody knows why QGIS makes all those seemingly wasteful SQL reads?

On Fri, Jun 16, 2023 at 1:18 PM Cory Albrecht <maps at hanfastolfe.com> wrote:

> 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/20230624/4c5d9914/attachment.htm>