[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