[QGIS-Developer] Why so many database calls?

[Alessandro Pasotti]

Hi Cory,

I think many developers have one or two ideas about where to look,
they probably didn't have the time to look into it.

Is there a ticket already?


On Sat, Jun 24, 2023 at 8:46 PM Cory Albrecht via QGIS-Developer
<qgis-developer at lists.osgeo.org> wrote:
>
> 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?
>>>
>>>
> _______________________________________________
> QGIS-Developer mailing list
> QGIS-Developer at lists.osgeo.org
> List info: https://lists.osgeo.org/mailman/listinfo/qgis-developer
> Unsubscribe: https://lists.osgeo.org/mailman/listinfo/qgis-developer



-- 
Alessandro Pasotti
QCooperative:  www.qcooperative.net
ItOpen:   www.itopen.it