On Tue, 28 Jun 2022 at 23:30, David Marteau via QGIS-Developer <qgis-developer@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, <dmart...@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@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@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@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@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@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@lists.osgeo.org List info: https://lists.osgeo.org/mailman/listinfo/qgis-developer Unsubscribe: https://lists.osgeo.org/mailman/listinfo/qgis-developer
