[QGIS-Developer] Qgis server: terrible performance with Qgis 3.26
David Marteau
dmarteau at 3liz.com
Tue Jun 28 06:30:24 PDT 2022
Hi,
From bisect-like analysis, I have found the commit that introduces the
loss of loading performance:
https://github.com/qgis/QGIS/commit/c6beb62216fcfbfe3ca64283c09117da53800a98
We need more investigation to understand exactly what is causing that
regression.
David Marteau
www.3liz.com <http://www.3liz.com>
Le 21/06/2022 à 14:45, David Marteau via QGIS-Developer a écrit :
> Hi,
>
> Here is a first analysis using QgsRuntimeProfiler outputs
>
> The project is the same in all tests and has been saved with Qgis 3.26.
> This is a first load in each case just after qgis init, so there
> should be no caching involved.
>
> Output has been filtered to `projectload` profiler group and rows with
> elapsed time > 0
>
> All builds are official builds and installed from qgis.org packages.
> Tests are run in Docker container with ubuntu 21.04
>
> Total time show a variance of +/- 25% on multiple runs.
>
> ## Qgis 3.26
>
> ### Flags
> * Qgis.ProjectReadFlag.TrustLayerMetadata
> * Qgis.ProjectReadFlag.DontLoad3DViews
> * Qgis.ProjectReadFlag.DontLoadProjectStyles
>
> projectload, Reading project file: 21.0 ms
> projectload, Creating auxiliary storage: 65.0 ms
> projectload, Reading properties: 19.0 ms
> projectload, Reading map layers: 14.0 ms
> -projectload, france_parts: 6.0 ms
> --projectload, Load layer source: 5.0 ms
> ---projectload, Create ogr provider: 3.0 ms
> -projectload, france_parts bordure: 4.0 ms
> --projectload, Load layer source: 4.0 ms
> ---projectload, Create ogr provider: 2.0 ms
> -projectload, france_parts tuilé en cache: 3.0 ms
> --projectload, Load layer source: 3.0 ms
> ---projectload, Create ogr provider: 1.0 ms
> projectload, Storing original layer properties: 2.0 ms
>
> Total time: 152.0 ms
>
> ## Qgis 3.24
>
> ### Flags
> * QgsProject.FlagTrustLayerMetadata
>
> projectload, Reading project file: 5.0 ms
> projectload, Reading properties: 4.0 ms
> projectload, Reading map layers: 4.0 ms
> -projectload, france_parts: 1.0 ms
> --projectload, Load layer source: 1.0 ms
> -projectload, france_parts bordure: 1.0 ms
> --projectload, Load layer source: 1.0 ms
> -projectload, france_parts tuilé en cache: 1.0 ms
> --projectload, Load layer source: 1.0 ms
> projectload, Storing original layer properties: 1.0 ms
> projectload, Updating interface: 1.0 ms
>
> Total time: 21.0 ms
>
> Some remarks:
>
> I Wonder why we have `Creating auxiliary storage` that takes 65.0 ms
> in Qgis 3.26 and it does not appears in Qgis 3.24:
> I need to figure how auxiliary layers are loaded in Qgis 3.24 (are
> they loaded lazily ?).
>
> The `Reading project file`, `Reading properties` and `Reading map
> layers` sections are almost 3 to 4 times slower in Qgis 3.26.
>
> The loading of layers ares also slower in Qgis 3.26 compared to Qgis 3.24.
>
>
> Le 21/06/2022 à 12:27, David Marteau a écrit :
>>
>>
>> May be I could use QgsRuntimeProfiler output in first place ?
>>
>> Le 20/06/2022 à 18:55, Even Rouault a écrit :
>>>
>>> Use sysprof or just run under a debugger and interrupt regularly
>>> should help you spot in which method(s) most time is spent
>>>
>>> Le 20/06/2022 à 18:48, David Marteau via QGIS-Developer a écrit :
>>>>
>>>> I used the following test:
>>>>
>>>> readflags = Qgis.ProjectReadFlags() readflags |=
>>>> Qgis.ProjectReadFlag.TrustLayerMetadata|Qgis.ProjectReadFlag.DontLoad3DViews|Qgis.ProjectReadFlag.DontLoadProjectStyles
>>>> prj = QgsProject()%timeit -n 1
>>>> prj.read(f"{datapath}/france_parts3_26.qgs",readflags)
>>>>
>>>> 105 ms ± 18.5 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)
>>>>
>>>> This improve the result but we are still much higher that the
>>>> loading time of 3.24: 15ms compared to 105ms
>>>>
>>>>
>>>> Le 20/06/2022 à 18:38, Nyall Dawson a écrit :
>>>>>
>>>>>
>>>>> On Mon, 20 June 2022, 11:42 pm David Marteau, <dmarteau at 3liz.com>
>>>>> wrote:
>>>>>
>>>>> Hi,
>>>>>
>>>>> > You should set the other new read optimisation flags here --
>>>>> see
>>>>> https://github.com/qgis/QGIS/blob/88ebb3f2f513dbce5a775f50e51ea0117f859c65/src/core/qgis.h#L1962
>>>>>
>>>>> These are already available also in 3.24 and we use the
>>>>> `TrustLayerMetadata` in the above test. For server, the other
>>>>> flags are not applicable (Getprint requests need print layouts ).
>>>>>
>>>>> So that mean we are comparing 3.24 to 3.26 with same level of
>>>>> read optimisation and that does not change the fact that, for
>>>>> that very same level of read optimisation, project's loading
>>>>> is incredibly slower in 3.26.
>>>>>
>>>>>
>>>>> You'll need to set the new flags relating to skipping the 3d views
>>>>> and project style loading in order to compare properly. Neither of
>>>>> those things were occurring in 3.24, and both have an associated
>>>>> cost. And neither are relevant for server.
>>>>>
>>>>> Nyall
>>>>>
>>>>>
>>>>>
>>>>> Le 20/06/2022 à 15:10, Nyall Dawson a écrit :
>>>>>>
>>>>>>
>>>>>> On Mon, 20 June 2022, 9:37 pm David Marteau via
>>>>>> QGIS-Developer, <qgis-developer at lists.osgeo.org> wrote:
>>>>>>
>>>>>> Hi,
>>>>>>
>>>>>> I have noticed a huge drop of performance while testing
>>>>>> Qgis server with Qgis 3.26, from 10x to 30x slower as usual.
>>>>>>
>>>>>> Trying to reduce the problem I have found a huge increase
>>>>>> of time spend reading the project in 3.26 compared to 3.24.
>>>>>>
>>>>>> Here some benchmark with very simple project from the
>>>>>> test data set. Note: the project has been updated with
>>>>>> qgis 3.26:
>>>>>>
>>>>>> Qgis 3.24:
>>>>>> ======
>>>>>>
>>>>>> readflags = QgsProject.ReadFlags()readflags |=
>>>>>> QgsProject.FlagTrustLayerMetadata
>>>>>>
>>>>>> prj = QgsProject()
>>>>>>
>>>>>> %timeit -n 1
>>>>>> prj.read(f"{datapath}/france_parts.qgs",readflags)
>>>>>>
>>>>>> > 15.7 ms ± 205 µs per loop (mean ± std. dev. of 7 runs, 1 loop each)
>>>>>>
>>>>>> Qgis 3.26:
>>>>>> ======
>>>>>>
>>>>>> readflags = QgsProject.ReadFlags() readflags |=
>>>>>> QgsProject.FlagTrustLayerMetadata
>>>>>>
>>>>>>
>>>>>> You should set the other new read optimisation flags here --
>>>>>> see
>>>>>> https://github.com/qgis/QGIS/blob/88ebb3f2f513dbce5a775f50e51ea0117f859c65/src/core/qgis.h#L1962
>>>>>>
>>>>>> Nyall
>>>>>>
>>>>>> prj = QgsProject()
>>>>>>
>>>>>> %timeit -n 1
>>>>>> prj.read(f"{datapath}/france_parts.qgs",readflags)
>>>>>>
>>>>>> 195 ms ± 44 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)
>>>>>>
>>>>>> There is a factor x10 between Qgis 3.24 et Qgis 3.26 for
>>>>>> the exact same project.
>>>>>> This has serious impact on requests: landing page catalog
>>>>>> request time increased from approximatevely 110ms to more
>>>>>> than 3.0s with our test data set.
>>>>>>
>>>>>>
>>>>>> David Marteau
>>>>>> www.3liz.com <http://www.3liz.com>
>>>>>>
>>>>>> _______________________________________________
>>>>>> 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
>>>>>>
>>>>
>>>> _______________________________________________
>>>> 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
>>> --
>>> http://www.spatialys.com
>>> My software is free, but my time generally not.
>
> _______________________________________________
> 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.osgeo.org/pipermail/qgis-developer/attachments/20220628/4e8356c4/attachment-0001.htm>
More information about the QGIS-Developer
mailing list