diff --git a/src/app/main.cpp b/src/app/main.cpp index 46233ba19ca..ac982d54672 100644 --- a/src/app/main.cpp +++ b/src/app/main.cpp @@ -642,6 +642,7 @@ int main(int argc, char **argv) PluginManager::setPluginIID(QLatin1String("org.qt-project.Qt.QtCreatorPlugin")); PluginManager::setGlobalSettings(globalSettings); PluginManager::setSettings(settings); + PluginManager::startProfiling(); QTranslator translator; QTranslator qtTranslator; diff --git a/src/libs/extensionsystem/optionsparser.cpp b/src/libs/extensionsystem/optionsparser.cpp index 8e3a5d900e7..116a1f4fe21 100644 --- a/src/libs/extensionsystem/optionsparser.cpp +++ b/src/libs/extensionsystem/optionsparser.cpp @@ -239,7 +239,7 @@ bool OptionsParser::checkForProfilingOption() { if (m_currentArg != QLatin1String(PROFILE_OPTION)) return false; - m_pmPrivate->initProfiling(); + m_pmPrivate->increaseProfilingVerbosity(); return true; } diff --git a/src/libs/extensionsystem/pluginmanager.cpp b/src/libs/extensionsystem/pluginmanager.cpp index 45b9807958e..5fa8b4a8cfd 100644 --- a/src/libs/extensionsystem/pluginmanager.cpp +++ b/src/libs/extensionsystem/pluginmanager.cpp @@ -949,7 +949,7 @@ void PluginManagerPrivate::nextDelayedInitialize() delayedInitializeQueue.pop(); profilingReport(">delayedInitialize", spec); bool delay = spec->d->delayedInitialize(); - profilingReport("d->performanceData.delayedInitialize); if (delay) break; // do next delayedInitialize after a delay } @@ -1305,7 +1305,7 @@ void PluginManagerPrivate::addObject(QObject *obj) if (debugLeaks) qDebug() << "PluginManagerPrivate::addObject" << obj << obj->objectName(); - if (m_profilingVerbosity && !m_profileTimer.isNull()) { + if (m_profilingVerbosity > 1 && m_profileTimer) { // Report a timestamp when adding an object. Useful for profiling // its initialization time. const int absoluteElapsedMS = int(m_profileTimer->elapsed()); @@ -1345,6 +1345,9 @@ void PluginManagerPrivate::removeObject(QObject *obj) */ void PluginManagerPrivate::loadPlugins() { + if (m_profilingVerbosity > 0) + qDebug("Profiling started"); + const QVector queue = loadQueue(); Utils::setMimeStartupPhase(MimeStartupPhase::PluginsLoading); for (PluginSpec *spec : queue) @@ -1593,7 +1596,9 @@ void PluginManagerPrivate::loadPlugin(PluginSpec *spec, PluginSpec::State destSt case PluginSpec::Running: profilingReport(">initializeExtensions", spec); spec->d->initializeExtensions(); - profilingReport("d->performanceData.extensionsInitialized); return; case PluginSpec::Deleted: profilingReport(">delete", spec); @@ -1621,12 +1626,12 @@ void PluginManagerPrivate::loadPlugin(PluginSpec *spec, PluginSpec::State destSt case PluginSpec::Loaded: profilingReport(">loadLibrary", spec); spec->d->loadLibrary(); - profilingReport("d->performanceData.load); break; case PluginSpec::Initialized: profilingReport(">initializePlugin", spec); spec->d->initializePlugin(); - profilingReport("d->performanceData.initialize); break; case PluginSpec::Stopped: profilingReport(">stop", spec); @@ -1762,34 +1767,30 @@ PluginSpec *PluginManagerPrivate::pluginByName(const QString &name) const return Utils::findOrDefault(pluginSpecs, [name](PluginSpec *spec) { return spec->name() == name; }); } -void PluginManagerPrivate::initProfiling() +void PluginManagerPrivate::increaseProfilingVerbosity() { - if (m_profileTimer.isNull()) { - m_profileTimer.reset(new QElapsedTimer); - m_profileTimer->start(); - m_profileElapsedMS = 0; - qDebug("Profiling started"); - } else { - m_profilingVerbosity++; - } + m_profilingVerbosity++; + if (!m_profileTimer) + PluginManager::startProfiling(); } -void PluginManagerPrivate::profilingReport(const char *what, const PluginSpec *spec /* = 0 */) +void PluginManagerPrivate::profilingReport(const char *what, const PluginSpec *spec, qint64 *target) { - if (!m_profileTimer.isNull()) { - const int absoluteElapsedMS = int(m_profileTimer->elapsed()); - const int elapsedMS = absoluteElapsedMS - m_profileElapsedMS; + if (m_profileTimer) { + const qint64 absoluteElapsedMS = m_profileTimer->elapsed(); + const qint64 elapsedMS = absoluteElapsedMS - m_profileElapsedMS; m_profileElapsedMS = absoluteElapsedMS; - if (spec) - qDebug("%-22s %-22s %8dms (%8dms)", what, qPrintable(spec->name()), absoluteElapsedMS, elapsedMS); - else - qDebug("%-45s %8dms (%8dms)", what, absoluteElapsedMS, elapsedMS); - if (what && *what == '<') { + if (m_profilingVerbosity > 0) { + qDebug("%-22s %-22s %8lldms (%8lldms)", + what, + qPrintable(spec->name()), + absoluteElapsedMS, + elapsedMS); + } + if (target) { QString tc; - if (spec) { - m_profileTotal[spec] += elapsedMS; - tc = spec->name() + '_'; - } + *target = elapsedMS; + tc = spec->name() + '_'; tc += QString::fromUtf8(QByteArray(what + 1)); Utils::Benchmarker::report("loadPlugins", tc, elapsedMS); } @@ -1798,22 +1799,23 @@ void PluginManagerPrivate::profilingReport(const char *what, const PluginSpec *s void PluginManagerPrivate::profilingSummary() const { - if (!m_profileTimer.isNull()) { - QMultiMap sorter; - int total = 0; - - auto totalEnd = m_profileTotal.constEnd(); - for (auto it = m_profileTotal.constBegin(); it != totalEnd; ++it) { - sorter.insert(it.value(), it.key()); - total += it.value(); + if (m_profilingVerbosity > 0) { + const QVector specs + = Utils::sorted(pluginSpecs, [](PluginSpec *s1, PluginSpec *s2) { + return s1->performanceData().total() < s2->performanceData().total(); + }); + const qint64 total + = std::accumulate(specs.constBegin(), specs.constEnd(), 0, [](qint64 t, PluginSpec *s) { + return t + s->performanceData().total(); + }); + for (PluginSpec *s : specs) { + if (!s->isEffectivelyEnabled()) + continue; + const qint64 t = s->performanceData().total(); + qDebug("%-22s %8lldms ( %5.2f%% )", qPrintable(s->name()), t, 100.0 * t / total); } - - auto sorterEnd = sorter.constEnd(); - for (auto it = sorter.constBegin(); it != sorterEnd; ++it) - qDebug("%-22s %8dms ( %5.2f%% )", qPrintable(it.value()->name()), - it.key(), 100.0 * it.key() / total); - qDebug("Total: %8dms", total); - Utils::Benchmarker::report("loadPlugins", "Total", total); + qDebug("Total: %8lldms", total); + Utils::Benchmarker::report("loadPlugins", "Total", total); } } @@ -1857,4 +1859,11 @@ QObject *PluginManager::getObjectByName(const QString &name) }); } +void PluginManager::startProfiling() +{ + d->m_profileTimer.reset(new QElapsedTimer); + d->m_profileTimer->start(); + d->m_profileElapsedMS = 0; +} + } // ExtensionSystem diff --git a/src/libs/extensionsystem/pluginmanager.h b/src/libs/extensionsystem/pluginmanager.h index ecd0ee70b73..251db275ca7 100644 --- a/src/libs/extensionsystem/pluginmanager.h +++ b/src/libs/extensionsystem/pluginmanager.h @@ -64,6 +64,7 @@ public: static QObject *getObjectByName(const QString &name); + static void startProfiling(); // Plugin operations static QVector loadQueue(); static void loadPlugins(); diff --git a/src/libs/extensionsystem/pluginmanager_p.h b/src/libs/extensionsystem/pluginmanager_p.h index c7a4291a6b7..75197013a8b 100644 --- a/src/libs/extensionsystem/pluginmanager_p.h +++ b/src/libs/extensionsystem/pluginmanager_p.h @@ -58,9 +58,9 @@ public: void loadPlugin(PluginSpec *spec, PluginSpec::State destState); void resolveDependencies(); void enableDependenciesIndirectly(); - void initProfiling(); + void increaseProfilingVerbosity(); void profilingSummary() const; - void profilingReport(const char *what, const PluginSpec *spec = nullptr); + void profilingReport(const char *what, const PluginSpec *spec, qint64 *target = nullptr); void setSettings(Utils::QtcSettings *settings); void setGlobalSettings(Utils::QtcSettings *settings); void readSettings(); @@ -106,8 +106,7 @@ public: QStringList arguments; QStringList argumentsForRestart; QScopedPointer m_profileTimer; - QHash m_profileTotal; - int m_profileElapsedMS = 0; + qint64 m_profileElapsedMS = 0; unsigned m_profilingVerbosity = 0; Utils::QtcSettings *settings = nullptr; Utils::QtcSettings *globalSettings = nullptr; diff --git a/src/libs/extensionsystem/pluginspec.cpp b/src/libs/extensionsystem/pluginspec.cpp index 62b3c0096f6..c633eaad610 100644 --- a/src/libs/extensionsystem/pluginspec.cpp +++ b/src/libs/extensionsystem/pluginspec.cpp @@ -402,6 +402,11 @@ QJsonObject PluginSpec::metaData() const return d->metaData; } +const PerformanceData &PluginSpec::performanceData() const +{ + return d->performanceData; +} + /*! Returns a list of descriptions of command line arguments the plugin processes. */ diff --git a/src/libs/extensionsystem/pluginspec.h b/src/libs/extensionsystem/pluginspec.h index 9abb4bf4475..43e39efeb1b 100644 --- a/src/libs/extensionsystem/pluginspec.h +++ b/src/libs/extensionsystem/pluginspec.h @@ -53,6 +53,16 @@ struct EXTENSIONSYSTEM_EXPORT PluginArgumentDescription QString description; }; +struct EXTENSIONSYSTEM_EXPORT PerformanceData +{ + qint64 load = 0; + qint64 initialize = 0; + qint64 extensionsInitialized = 0; + qint64 delayedInitialize = 0; + + qint64 total() const { return load + initialize + extensionsInitialized + delayedInitialize; } +}; + class EXTENSIONSYSTEM_EXPORT PluginSpec { public: @@ -84,6 +94,7 @@ public: bool isForceDisabled() const; QVector dependencies() const; QJsonObject metaData() const; + const PerformanceData &performanceData() const; using PluginArgumentDescriptions = QVector; PluginArgumentDescriptions argumentDescriptions() const; diff --git a/src/libs/extensionsystem/pluginspec_p.h b/src/libs/extensionsystem/pluginspec_p.h index 568ab943a31..c87111f02ae 100644 --- a/src/libs/extensionsystem/pluginspec_p.h +++ b/src/libs/extensionsystem/pluginspec_p.h @@ -84,6 +84,8 @@ public: bool hasError = false; QString errorString; + PerformanceData performanceData; + static bool isValidVersion(const QString &version); static int versionCompare(const QString &version1, const QString &version2);