[QGIS-Developer] Why so many database calls?

Sat Aug 5 10:39:10 PDT 2023

So after getting very frustrated with QGIS taking literally hours to simply
delete vertices, I made a bug report

https://github.com/qgis/QGIS/issues/53973

When doing anything with vertices, QGIS makes the following set of exactly
the same (except or the cursor id) SQL queries 1 or more times for each
vertex being worked on:

Jul 27 16:54:17 postgresql-3 postgres[97809]: [2219-1] ::>[2023-07-27
16:54:17.743 EDT][64c2d4bf.17e11][97809/] <maps%Alternate History>
LOG:  duration: 0.323 ms  statement: BEGIN READ ONLY;DECLARE qgis_571
BINARY CURSOR FOR SELECT
"id","names"::text,"main_rgb"::text,"border_rgb"::text,"stripe_rgb"::text,"start_date"::text,"end_date"::text,"sovereign"::text,"category"::text,"predecessors"::text,"successors"::text
FROM "bop"."timeline_level_0" WHERE "id"=143

Jul 27 16:54:17 postgresql-3 postgres[97809]: [2220-1] ::>[2023-07-27
16:54:17.744 EDT][64c2d4bf.17e11][97809/] <maps%Alternate History>
LOG:  duration: 0.059 ms  statement: FETCH FORWARD 2000 FROM qgis_571

Jul 27 16:54:17 postgresql-3 postgres[97809]: [2221-1] ::>[2023-07-27
16:54:17.744 EDT][64c2d4bf.17e11][97809/] <maps%Alternate History>
LOG:  duration: 0.049 ms  statement: CLOSE qgis_571;COMMIT

To remove 600 vertices selected with the vertex tool from a feature, that
set of calls was made more than 800 times.

With a second deletion of 514 vertices, there was a pause of ~34 seconds
before QGIS started making these repeated queries. It started off of pretty

Here is the PostgreSQL for doing the delete, plus the canvas redraw when
finished

queries.log <https://github.com/qgis/QGIS/files/12188596/queries.log>

Since the vertices are being removed from the in-memory copy of the feature
and and nothing is being written, it would seem the query (for whatever
reason it is being used), only needs to be done once since the result from
the database will never change.

What is the point of these excessive, seemingly needless queries?

in a later comment, I talk about how QGIS took about 28 hours to delete
roughly 2,400 vertices from a roughly 23,200 vertex feature and how the
ever increasing delay between the repetitive calls was 90 seconds, making
these unnecessary database calls the likely culprit for making it take so
long.

On Sun, Jun 25, 2023 at 3:04 PM Cory Albrecht <maps at hanfastolfe.com> wrote:

> I wasn't asking anybody to fix a problem, so, no, there is no ticket. I
> was asking why the QGIS code makes thousands of SQL reads for a very simple
> operation. If all that is being done is moving a single vertex, why is
> there even a need to read from the database at all?
>
>
> On Sat, Jun 24, 2023 at 5:12 PM Alessandro Pasotti <apasotti at gmail.com>
> wrote:
>
>> 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
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.osgeo.org/pipermail/qgis-developer/attachments/20230805/a901061d/attachment-0001.htm>