Skip to content

Commit

Permalink
Show startup profile timings in developer/debugging tools panel
Browse files Browse the repository at this point in the history 
Instead of hiding this information on the console, let's expose it
to users. QGIS startup times have been an ongoing issue for a number
of years, so let's help provide users with some tools to help
track down what's causing these (*hint* it's probably a plugin *hint*)
  • Loading branch information
@nyalldawson
nyalldawson committed May 18, 2020
1 parent 175910c commit 82c298a
Show file tree
Hide file tree
Showing 9 changed files with 409 additions and 13 deletions.
46 changes: 46 additions & 0 deletions python/core/additions/runtimeprofiler.py
View file
@@ -0,0 +1,46 @@
# -*- coding: utf-8 -*-

"""
***************************************************************************
runtimeprofiler.py
---------------------
Date : May 2020
Copyright : (C) 2020 by Nyall Dawson
Email : nyall dot dawson at gmail dot com
***************************************************************************
* *
* This program is free software; you can redistribute it and/or modify *
* it under the terms of the GNU General Public License as published by *
* the Free Software Foundation; either version 2 of the License, or *
* (at your option) any later version. *
* *
***************************************************************************
"""


from qgis._core import QgsScopedRuntimeProfile


class ScopedRuntimeProfileContextManager():
"""
Context manager used to profile blocks of code in the QgsApplication.profiler() registry.
.. code-block:: python
with QgsRuntimeProfiler.profile('My operation'):
# do something
.. versionadded:: 3.14
"""

def __init__(self, operation):
self.operation = operation
self.profiler = None

def __enter__(self):
self.profiler = QgsScopedRuntimeProfile(self.operation)
return self.operation

def __exit__(self, ex_type, ex_value, traceback):
del self.profiler
return True
2 changes: 2 additions & 0 deletions src/app/CMakeLists.txt
View file
Expand Up @@ -172,6 +172,8 @@ SET(QGIS_APP_SRCS
devtools/networklogger/qgsnetworkloggernode.cpp
devtools/networklogger/qgsnetworkloggerpanelwidget.cpp
devtools/networklogger/qgsnetworkloggerwidgetfactory.cpp
devtools/profiler/qgsprofilerpanelwidget.cpp
devtools/profiler/qgsprofilerwidgetfactory.cpp

labeling/qgslabelpropertydialog.cpp
labeling/qgsmaptoolchangelabelproperties.cpp
Expand Down
125 changes: 125 additions & 0 deletions src/app/devtools/profiler/qgsprofilerpanelwidget.cpp
View file
@@ -0,0 +1,125 @@
/***************************************************************************
qgsprofilerpanelwidget.cpp
-------------------------
begin : May 2020
copyright : (C) 2020 by Nyall Dawson
email : nyall dot dawson at gmail dot com
***************************************************************************
* *
* This program is free software; you can redistribute it and/or modify *
* it under the terms of the GNU General Public License as published by *
* the Free Software Foundation; either version 2 of the License, or *
* (at your option) any later version. *
* *
***************************************************************************/

#include "qgsprofilerpanelwidget.h"
#include "qgsruntimeprofiler.h"
#include "qgslogger.h"
#include <QPainter>

//
// QgsProfilerPanelWidget
//

QgsProfilerPanelWidget::QgsProfilerPanelWidget( QgsRuntimeProfiler *profiler, QWidget *parent )
: QgsDevToolWidget( parent )
, mProfiler( profiler )
{
setupUi( this );

mTreeWidget->setColumnCount( 2 );
mTreeWidget->setHeaderLabels( QStringList() << tr( "Task" ) << tr( "Time (seconds)" ) );

std::function< void( const QString &topLevel, QTreeWidgetItem *parentItem, double parentCost ) > addGroup;
addGroup = [&]( const QString & topLevel, QTreeWidgetItem * parentItem, double parentCost )
{
const QStringList children = mProfiler->childGroups( topLevel );
for ( const QString &child : children )
{
double profileTime = mProfiler->profileTime( topLevel.isEmpty() ? child : topLevel + '/' + child );
QTreeWidgetItem *item = new QTreeWidgetItem( QStringList() << child << QString::number( profileTime ) );
if ( !topLevel.isEmpty() )
{
item->setData( 1, Qt::UserRole + 1, parentCost * 1000 );
item->setData( 1, Qt::InitialSortOrderRole, profileTime * 1000 );
}
if ( !parentItem )
mTreeWidget->addTopLevelItem( item );
else
parentItem->addChild( item );

addGroup( topLevel.isEmpty() ? child : topLevel + '/' + child, item, profileTime );
}
};
addGroup( QString(), nullptr, 0 );

mTreeWidget->resizeColumnToContents( 0 );
mTreeWidget->resizeColumnToContents( 1 );

mTreeWidget->setItemDelegateForColumn( 1, new CostDelegate( Qt::InitialSortOrderRole, Qt::UserRole + 1 ) );
}


//
// CostDelegate
//

// adapted from KDAB's excellent "hotspot" application!

CostDelegate::CostDelegate( quint32 sortRole, quint32 totalCostRole, QObject *parent )
: QStyledItemDelegate( parent )
, m_sortRole( sortRole )
, m_totalCostRole( totalCostRole )
{
}

CostDelegate::~CostDelegate() = default;

void CostDelegate::paint( QPainter *painter, const QStyleOptionViewItem &option, const QModelIndex &index ) const
{
// TODO: handle negative values
const auto cost = index.data( m_sortRole ).toULongLong();
if ( cost == 0 )
{
QStyledItemDelegate::paint( painter, option, index );
return;
}

const auto totalCost = index.data( m_totalCostRole ).toULongLong();
const auto fraction = std::abs( float( cost ) / totalCost );

auto rect = option.rect;
rect.setWidth( rect.width() * fraction );

const auto &brush = painter->brush();
const auto &pen = painter->pen();

painter->setPen( Qt::NoPen );

if ( option.features & QStyleOptionViewItem::Alternate )
{
// we must handle this ourselves as otherwise the custom background
// would get painted over with the alternate background color
painter->setBrush( option.palette.alternateBase() );
painter->drawRect( option.rect );
}

auto color = QColor::fromHsv( 120 - fraction * 120, 255, 255, ( -( ( fraction - 1 ) * ( fraction - 1 ) ) ) * 120 + 120 );
painter->setBrush( color );
painter->drawRect( rect );

painter->setBrush( brush );
painter->setPen( pen );

if ( option.features & QStyleOptionViewItem::Alternate )
{
auto o = option;
o.features &= ~QStyleOptionViewItem::Alternate;
QStyledItemDelegate::paint( painter, o, index );
}
else
{
QStyledItemDelegate::paint( painter, option, index );
}
}
66 changes: 66 additions & 0 deletions src/app/devtools/profiler/qgsprofilerpanelwidget.h
View file
@@ -0,0 +1,66 @@
/***************************************************************************
qgsprofilerpanelwidget.h
-------------------------
begin : May 2020
copyright : (C) 2020 by Nyall Dawson
email : nyall dot dawson at gmail dot com
***************************************************************************
* *
* This program is free software; you can redistribute it and/or modify *
* it under the terms of the GNU General Public License as published by *
* the Free Software Foundation; either version 2 of the License, or *
* (at your option) any later version. *
* *
***************************************************************************/
#ifndef QGSPROFILERPANELWIDGET_H
#define QGSPROFILERPANELWIDGET_H

#include "qgsdevtoolwidget.h"
#include "ui_qgsprofilerpanelbase.h"
#include <QTreeView>
#include <QStyledItemDelegate>

class QgsRuntimeProfiler;

/**
* \ingroup app
* \class QgsProfilerPanelWidget
* \brief A panel widget showing profiled startup times for debugging.
*
* \since QGIS 3.14
*/
class QgsProfilerPanelWidget : public QgsDevToolWidget, private Ui::QgsProfilerPanelBase
{
Q_OBJECT

public:

/**
* Constructor for QgsProfilerPanelWidget.
*/
QgsProfilerPanelWidget( QgsRuntimeProfiler *profiler, QWidget *parent );

private:

QgsRuntimeProfiler *mProfiler = nullptr;

};

// adapted from KDAB's "hotspot"

class CostDelegate : public QStyledItemDelegate
{
Q_OBJECT
public:
explicit CostDelegate( quint32 sortRole, quint32 totalCostRole, QObject *parent = nullptr );
~CostDelegate();

void paint( QPainter *painter, const QStyleOptionViewItem &option, const QModelIndex &index ) const override;

private:
quint32 m_sortRole;
quint32 m_totalCostRole;
};


#endif // QGSPROFILERPANELWIDGET_H
29 changes: 29 additions & 0 deletions src/app/devtools/profiler/qgsprofilerwidgetfactory.cpp
View file
@@ -0,0 +1,29 @@
/***************************************************************************
qgsprofilerwidgetfactory.cpp
-------------------------
begin : May 2020
copyright : (C) 2020 by Nyall Dawson
email : nyall dot dawson at gmail dot com
***************************************************************************
* *
* This program is free software; you can redistribute it and/or modify *
* it under the terms of the GNU General Public License as published by *
* the Free Software Foundation; either version 2 of the License, or *
* (at your option) any later version. *
* *
***************************************************************************/

#include "qgsprofilerwidgetfactory.h"
#include "qgsprofilerpanelwidget.h"
#include "qgsapplication.h"

QgsProfilerWidgetFactory::QgsProfilerWidgetFactory( QgsRuntimeProfiler *profiler )
: QgsDevToolWidgetFactory( QObject::tr( "Startup Profiler" ), QgsApplication::getThemeIcon( QStringLiteral( "mIconNetworkLogger.svg" ) ) )
, mProfiler( profiler )
{
}

QgsDevToolWidget *QgsProfilerWidgetFactory::createWidget( QWidget *parent ) const
{
return new QgsProfilerPanelWidget( mProfiler, parent );
}
36 changes: 36 additions & 0 deletions src/app/devtools/profiler/qgsprofilerwidgetfactory.h
View file
@@ -0,0 +1,36 @@
/***************************************************************************
qgsprofilerwidgetfactory.h
-------------------------
begin : May 2020
copyright : (C) 2020 by Nyall Dawson
email : nyall dot dawson at gmail dot com
***************************************************************************
* *
* This program is free software; you can redistribute it and/or modify *
* it under the terms of the GNU General Public License as published by *
* the Free Software Foundation; either version 2 of the License, or *
* (at your option) any later version. *
* *
***************************************************************************/
#ifndef QGSPROFILERWIDGETFACTORY_H
#define QGSPROFILERWIDGETFACTORY_H

#include "qgsdevtoolwidgetfactory.h"

class QgsRuntimeProfiler;

class QgsProfilerWidgetFactory: public QgsDevToolWidgetFactory
{
public:

QgsProfilerWidgetFactory( QgsRuntimeProfiler *profiler );
QgsDevToolWidget *createWidget( QWidget *parent = nullptr ) const override;

private:

QgsRuntimeProfiler *mProfiler = nullptr;

};


#endif // QGSPROFILERWIDGETFACTORY_H
16 changes: 3 additions & 13 deletions src/app/qgisapp.cpp
View file
Expand Up @@ -377,6 +377,7 @@ Q_GUI_EXPORT extern int qt_defaultDpiX();
#include "qgsuserprofilemanager.h"
#include "qgsuserprofile.h"
#include "qgsnetworkloggerwidgetfactory.h"
#include "devtools/profiler/qgsprofilerwidgetfactory.h"

#include "browser/qgsinbuiltdataitemproviders.h"

Expand Down Expand Up @@ -1628,20 +1629,9 @@ QgisApp::QgisApp( QSplashScreen *splash, bool restorePlugins, bool skipVersionCh
#ifdef ANDROID
toggleFullScreen();
#endif
profiler->endGroup();
profiler->end();

QgsDebugMsg( QStringLiteral( "PROFILE TIMES" ) );
QgsDebugMsg( QStringLiteral( "PROFILE TIMES TOTAL - %1 " ).arg( profiler->totalTime() ) );
#ifdef QGISDEBUG
QList<QPair<QString, double> > profileTimes = profiler->profileTimes();
QList<QPair<QString, double> >::const_iterator it = profileTimes.constBegin();
for ( ; it != profileTimes.constEnd(); ++it )
{
QString name = ( *it ).first;
double time = ( *it ).second;
QgsDebugMsg( QStringLiteral( " - %1 - %2" ).arg( name ).arg( time ) );
}
#endif
mStartupProfilerWidgetFactory.reset( qgis::make_unique< QgsProfilerWidgetFactory >( profiler ) );

auto toggleRevert = [ = ]
{
Expand Down
1 change: 1 addition & 0 deletions src/app/qgisapp.h
View file
Expand Up @@ -2520,6 +2520,7 @@ class APP_EXPORT QgisApp : public QMainWindow, private Ui::MainWindow

QgsNetworkLogger *mNetworkLogger = nullptr;
QgsScopedDevToolWidgetFactory mNetworkLoggerWidgetFactory;
QgsScopedDevToolWidgetFactory mStartupProfilerWidgetFactory;

class QgsCanvasRefreshBlocker
{
Expand Down

0 comments on commit 82c298a

Please sign in to comment.