Skip to content

Commit

Permalink
[FEATURE] Add project load profile times to debugging tools dock
Browse files Browse the repository at this point in the history 
Now it's possible to get a breakdown of the various stages of
project load, in order to identify the causes of slow project
load times.

TODO: in 99% of cases this will be caused by one or more layers,
so it would be nice to further break down the individual layer load
times, e.g. so that for a WFS layer we see the time taken for
the initial server capabilities queries, etc...
For now, you just get the overall load time of each individual
layer.
  • Loading branch information
@nyalldawson
nyalldawson committed Jun 28, 2020
1 parent 42a1ed1 commit 005ac8a
Show file tree
Hide file tree
Showing 5 changed files with 80 additions and 4 deletions.
10 changes: 10 additions & 0 deletions python/core/auto_generated/qgsruntimeprofiler.sip.in
View file
Expand Up @@ -161,6 +161,16 @@ and starts recording the run time of the operation.

~QgsScopedRuntimeProfile();

void switchTask( const QString &name );
%Docstring
Switches the current task managed by the scoped profile to a new task with the given ``name``.
The current task will be finalised before switching.

This is useful for reusing an existing scoped runtime profiler with multi-step processes.

.. versionadded:: 3.14
%End

};


Expand Down
11 changes: 11 additions & 0 deletions src/core/layout/qgslayoutmanager.cpp
View file
Expand Up @@ -23,6 +23,7 @@
#include "qgscompositionconverter.h"
#include "qgsreadwritecontext.h"
#include "qgsstyleentityvisitor.h"
#include "qgsruntimeprofiler.h"
#include <QMessageBox>

QgsLayoutManager::QgsLayoutManager( QgsProject *project )
Expand Down Expand Up @@ -148,6 +149,7 @@ bool QgsLayoutManager::readXml( const QDomElement &element, const QDomDocument &
//restore each composer
bool result = true;
QDomNodeList composerNodes = element.elementsByTagName( QStringLiteral( "Composer" ) );
QgsScopedRuntimeProfile profile( tr( "Loading QGIS 2.x compositions" ), QStringLiteral( "projectload" ) );
for ( int i = 0; i < composerNodes.size(); ++i )
{
// This legacy title is the Composer "title" (that can be overridden by the Composition "name")
Expand Down Expand Up @@ -195,13 +197,18 @@ bool QgsLayoutManager::readXml( const QDomElement &element, const QDomDocument &
QgsReadWriteContext context;
context.setPathResolver( mProject->pathResolver() );

profile.switchTask( tr( "Creating layouts" ) );

// restore layouts
const QDomNodeList layoutNodes = layoutsElem.childNodes();
for ( int i = 0; i < layoutNodes.size(); ++i )
{
if ( layoutNodes.at( i ).nodeName() != QStringLiteral( "Layout" ) )
continue;

const QString layoutName = layoutNodes.at( i ).toElement().attribute( QStringLiteral( "name" ) );
QgsScopedRuntimeProfile profile( layoutName, QStringLiteral( "projectload" ) );

std::unique_ptr< QgsPrintLayout > l = qgis::make_unique< QgsPrintLayout >( mProject );
l->undoStack()->blockCommands( true );
if ( !l->readLayoutXml( layoutNodes.at( i ).toElement(), doc, context ) )
Expand All @@ -216,9 +223,13 @@ bool QgsLayoutManager::readXml( const QDomElement &element, const QDomDocument &
}
}
//reports
profile.switchTask( tr( "Creating reports" ) );
const QDomNodeList reportNodes = element.elementsByTagName( QStringLiteral( "Report" ) );
for ( int i = 0; i < reportNodes.size(); ++i )
{
const QString layoutName = reportNodes.at( i ).toElement().attribute( QStringLiteral( "name" ) );
QgsScopedRuntimeProfile profile( layoutName, QStringLiteral( "projectload" ) );

std::unique_ptr< QgsReport > r = qgis::make_unique< QgsReport >( mProject );
if ( !r->readLayoutXml( reportNodes.at( i ).toElement(), doc, context ) )
{
Expand Down
38 changes: 36 additions & 2 deletions src/core/qgsproject.cpp
View file
Expand Up @@ -61,6 +61,7 @@
#include "qgsprojectdisplaysettings.h"
#include "qgsprojecttimesettings.h"
#include "qgsvectortilelayer.h"
#include "qgsruntimeprofiler.h"

#include <algorithm>
#include <QApplication>
Expand Down Expand Up @@ -1059,6 +1060,7 @@ bool QgsProject::_getMapLayers( const QDomDocument &doc, QList<QDomNode> &broken
emit layerLoaded( 0, nl.count() );

// order layers based on their dependencies
QgsScopedRuntimeProfile profile( tr( "Sorting layers" ), QStringLiteral( "projectload" ) );
QgsLayerDefinition::DependencySorter depSorter( doc );
if ( depSorter.hasCycle() || depSorter.hasMissingDependency() )
return false;
Expand All @@ -1075,6 +1077,8 @@ bool QgsProject::_getMapLayers( const QDomDocument &doc, QList<QDomNode> &broken
if ( !name.isNull() )
emit loadingLayer( tr( "Loading layer %1" ).arg( name ) );

profile.switchTask( name );

if ( element.attribute( QStringLiteral( "embedded" ) ) == QLatin1String( "1" ) )
{
createEmbeddedLayer( element.attribute( QStringLiteral( "id" ) ), readPath( element.attribute( QStringLiteral( "project" ) ) ), brokenNodes, true, flags );
Expand Down Expand Up @@ -1109,6 +1113,7 @@ bool QgsProject::addLayer( const QDomElement &layerElem, QList<QDomNode> &broken
QgsDebugMsgLevel( "Layer type is " + type, 4 );
std::unique_ptr<QgsMapLayer> mapLayer;

QgsScopedRuntimeProfile profile( tr( "Create layer" ), QStringLiteral( "projectload" ) );
if ( type == QLatin1String( "vector" ) )
{
mapLayer = qgis::make_unique<QgsVectorLayer>();
Expand Down Expand Up @@ -1154,6 +1159,8 @@ bool QgsProject::addLayer( const QDomElement &layerElem, QList<QDomNode> &broken
QgsMapLayer::ReadFlags layerFlags = QgsMapLayer::ReadFlags();
if ( flags & QgsProject::ReadFlag::FlagDontResolveLayers )
layerFlags |= QgsMapLayer::FlagDontResolveLayers;

profile.switchTask( tr( "Load layer source" ) );
bool layerIsValid = mapLayer->readLayerXml( layerElem, context, layerFlags ) && mapLayer->isValid();
QList<QgsMapLayer *> newLayers;
newLayers << mapLayer.get();
Expand Down Expand Up @@ -1251,6 +1258,9 @@ bool QgsProject::readProjectFile( const QString &filename, QgsProject::ReadFlags
QFile projectFile( filename );
clearError();

QgsApplication::profiler()->clear( QStringLiteral( "projectload" ) );
QgsScopedRuntimeProfile profile( tr( "Setting up translations" ), QStringLiteral( "projectload" ) );

QgsSettings settings;

QString localeFileName = QStringLiteral( "%1_%2" ).arg( QFileInfo( projectFile.fileName() ).baseName(), settings.value( QStringLiteral( "locale/userLocale" ), QString() ).toString() );
Expand All @@ -1261,6 +1271,7 @@ bool QgsProject::readProjectFile( const QString &filename, QgsProject::ReadFlags
mTranslator->load( localeFileName, QFileInfo( projectFile.fileName() ).absolutePath() );
}

profile.switchTask( tr( "Reading project file" ) );
std::unique_ptr<QDomDocument> doc( new QDomDocument( QStringLiteral( "qgis" ) ) );

if ( !projectFile.open( QIODevice::ReadOnly | QIODevice::Text ) )
Expand Down Expand Up @@ -1304,6 +1315,7 @@ bool QgsProject::readProjectFile( const QString &filename, QgsProject::ReadFlags
QgsProjectVersion fileVersion = getVersion( *doc );
const QgsProjectVersion thisVersion( Qgis::version() );

profile.switchTask( tr( "Updating project file" ) );
if ( thisVersion > fileVersion )
{
QgsLogger::warning( "Loading a file that was saved with an older "
Expand All @@ -1320,6 +1332,7 @@ bool QgsProject::readProjectFile( const QString &filename, QgsProject::ReadFlags
}

// start new project, just keep the file name and auxiliary storage
profile.switchTask( tr( "Creating auxiliary storage" ) );
QString fileName = mFile.fileName();
std::unique_ptr<QgsAuxiliaryStorage> aStorage = std::move( mAuxiliaryStorage );
clear();
Expand All @@ -1330,6 +1343,7 @@ bool QgsProject::readProjectFile( const QString &filename, QgsProject::ReadFlags
mSaveVersion = fileVersion;

// now get any properties
profile.switchTask( tr( "Reading properties" ) );
_getProperties( *doc, mProperties );

// now get the data defined server properties
Expand Down Expand Up @@ -1485,7 +1499,7 @@ bool QgsProject::readProjectFile( const QString &filename, QgsProject::ReadFlags
}

// read the layer tree from project file

profile.switchTask( tr( "Loading layer tree" ) );
mRootGroup->setCustomProperty( QStringLiteral( "loading" ), 1 );

QDomElement layerTreeElem = doc->documentElement().firstChildElement( QStringLiteral( "layer-tree-group" ) );
Expand All @@ -1501,6 +1515,8 @@ bool QgsProject::readProjectFile( const QString &filename, QgsProject::ReadFlags
mLayerTreeRegistryBridge->setEnabled( false );

// get the map layers
profile.switchTask( tr( "Reading map layers" ) );

QList<QDomNode> brokenNodes;
bool clean = _getMapLayers( *doc, brokenNodes, flags );

Expand All @@ -1521,6 +1537,7 @@ bool QgsProject::readProjectFile( const QString &filename, QgsProject::ReadFlags

// Resolve references to other layers
// Needs to be done here once all dependent layers are loaded
profile.switchTask( tr( "Resolving layer references" ) );
QMap<QString, QgsMapLayer *> layers = mLayerStore->mapLayers();
for ( QMap<QString, QgsMapLayer *>::iterator it = layers.begin(); it != layers.end(); ++it )
{
Expand All @@ -1530,12 +1547,13 @@ bool QgsProject::readProjectFile( const QString &filename, QgsProject::ReadFlags
mLayerTreeRegistryBridge->setEnabled( true );

// load embedded groups and layers
profile.switchTask( tr( "Loading embedded layers" ) );
loadEmbeddedNodes( mRootGroup, flags );

// now that layers are loaded, we can resolve layer tree's references to the layers
profile.switchTask( tr( "Resolving references" ) );
mRootGroup->resolveReferences( this );


if ( !layerTreeElem.isNull() )
{
mRootGroup->readLayerOrderFromXml( layerTreeElem );
Expand Down Expand Up @@ -1576,16 +1594,23 @@ bool QgsProject::readProjectFile( const QString &filename, QgsProject::ReadFlags

mRootGroup->removeCustomProperty( QStringLiteral( "loading" ) );

profile.switchTask( tr( "Loading map themes" ) );
mMapThemeCollection.reset( new QgsMapThemeCollection( this ) );
emit mapThemeCollectionChanged();
mMapThemeCollection->readXml( *doc );

profile.switchTask( tr( "Loading label settings" ) );
mLabelingEngineSettings->readSettingsFromProject( this );
emit labelingEngineSettingsChanged();

profile.switchTask( tr( "Loading annotations" ) );
mAnnotationManager->readXml( doc->documentElement(), context );
if ( !( flags & QgsProject::ReadFlag::FlagDontLoadLayouts ) )
{
profile.switchTask( tr( "Loading layouts" ) );
mLayoutManager->readXml( doc->documentElement(), *doc );
}
profile.switchTask( tr( "Loading bookmarks" ) );
mBookmarkManager->readXml( doc->documentElement(), *doc );

// reassign change dependencies now that all layers are loaded
Expand All @@ -1595,9 +1620,11 @@ bool QgsProject::readProjectFile( const QString &filename, QgsProject::ReadFlags
it.value()->setDependencies( it.value()->dependencies() );
}

profile.switchTask( tr( "Loading snapping settings" ) );
mSnappingConfig.readProject( *doc );
mAvoidIntersectionsMode = static_cast<AvoidIntersectionsMode>( readNumEntry( QStringLiteral( "Digitizing" ), QStringLiteral( "/AvoidIntersectionsMode" ), static_cast<int>( AvoidIntersectionsMode::AvoidIntersectionsLayers ) ) );

profile.switchTask( tr( "Loading view settings" ) );
// restore older project scales settings
mViewSettings->setUseProjectScales( readBoolEntry( QStringLiteral( "Scales" ), QStringLiteral( "/useProjectScales" ) ) );
const QStringList scales = readListEntry( QStringLiteral( "Scales" ), QStringLiteral( "/ScalesList" ) );
Expand All @@ -1621,21 +1648,28 @@ bool QgsProject::readProjectFile( const QString &filename, QgsProject::ReadFlags
mViewSettings->readXml( viewSettingsElement, context );

// restore time settings
profile.switchTask( tr( "Loading temporal settings" ) );
QDomElement timeSettingsElement = doc->documentElement().firstChildElement( QStringLiteral( "ProjectTimeSettings" ) );
if ( !timeSettingsElement.isNull() )
mTimeSettings->readXml( timeSettingsElement, context );

profile.switchTask( tr( "Loading display settings" ) );
QDomElement displaySettingsElement = doc->documentElement().firstChildElement( QStringLiteral( "ProjectDisplaySettings" ) );
if ( !displaySettingsElement.isNull() )
mDisplaySettings->readXml( displaySettingsElement, context );

profile.switchTask( tr( "Updating variables" ) );
emit customVariablesChanged();
profile.switchTask( tr( "Updating CRS" ) );
emit crsChanged();
emit ellipsoidChanged( ellipsoid() );

// read the project: used by map canvas and legend
profile.switchTask( tr( "Reading external settings" ) );
emit readProject( *doc );
emit readProjectWithContext( *doc, context );

profile.switchTask( tr( "Updating interface" ) );
emit snappingConfigChanged( mSnappingConfig );
emit avoidIntersectionsModeChanged();
emit topologicalEditingChanged();
Expand Down
11 changes: 9 additions & 2 deletions src/core/qgsruntimeprofiler.cpp
View file
Expand Up @@ -570,11 +570,18 @@ QgsRuntimeProfilerNode *QgsRuntimeProfiler::index2node( const QModelIndex &index
//

QgsScopedRuntimeProfile::QgsScopedRuntimeProfile( const QString &name, const QString &group )
: mGroup( group )
{
QgsApplication::profiler()->start( name, group );
QgsApplication::profiler()->start( name, mGroup );
}

QgsScopedRuntimeProfile::~QgsScopedRuntimeProfile()
{
QgsApplication::profiler()->end();
QgsApplication::profiler()->end( mGroup );
}

void QgsScopedRuntimeProfile::switchTask( const QString &name )
{
QgsApplication::profiler()->end( mGroup );
QgsApplication::profiler()->start( name, mGroup );
}
14 changes: 14 additions & 0 deletions src/core/qgsruntimeprofiler.h
View file
Expand Up @@ -323,6 +323,20 @@ class CORE_EXPORT QgsScopedRuntimeProfile
*/
~QgsScopedRuntimeProfile();

/**
* Switches the current task managed by the scoped profile to a new task with the given \a name.
* The current task will be finalised before switching.
*
* This is useful for reusing an existing scoped runtime profiler with multi-step processes.
*
* \since QGIS 3.14
*/
void switchTask( const QString &name );

private:

QString mGroup;

};


Expand Down

0 comments on commit 005ac8a

Please sign in to comment.