[QGIS-Developer] Qgis server: terrible performance with Qgis 3.26
Nyall Dawson
nyall.dawson at gmail.com
Thu Jul 7 00:32:54 PDT 2022
On Tue, 28 Jun 2022 at 23:30, David Marteau via QGIS-Developer
<qgis-developer at lists.osgeo.org> wrote:
>
> 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.
I've proposed a fix at https://github.com/qgis/QGIS/pull/49266, but it
requires testing on server and confirmation that it addresses the
regression.
Thanks!
Nyall
>
> David Marteau
> 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
>>>
>>> _______________________________________________
>>> 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
>
> _______________________________________________
> 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
More information about the QGIS-Developer
mailing list