ExtensionSystem: Always generate profiling data

The overhead is minimal and can be shown at a later point even
when not printing profiling data to the terminal.
Move the data to the plugin spec for later retrieval.

Task-number: QTCREATORBUG-29540
Change-Id: I392ff85a8a8b5c01ecba07fefd06e5029f692bf6
Reviewed-by: Cristian Adam <cristian.adam@qt.io>
Reviewed-by: hjk <hjk@qt.io>
Reviewed-by: Qt CI Bot <qt_ci_bot@qt-project.org>
(cherry picked from commit 4da8430cab)

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;

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;
 }
 

src/libs/extensionsystem/pluginmanager.cpp

@@ -949,7 +949,7 @@ void PluginManagerPrivate::nextDelayedInitialize()
         delayedInitializeQueue.pop();
         profilingReport(">delayedInitialize", spec);
         bool delay = spec->d->delayedInitialize();
-        profilingReport("<delayedInitialize", spec);
+        profilingReport("<delayedInitialize", spec, &spec->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<PluginSpec *> 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("<initializeExtensions", spec);
+        profilingReport("<initializeExtensions",
+                        spec,
+                        &spec->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("<loadLibrary", spec);
+        profilingReport("<loadLibrary", spec, &spec->d->performanceData.load);
         break;
     case PluginSpec::Initialized:
         profilingReport(">initializePlugin", spec);
         spec->d->initializePlugin();
-        profilingReport("<initializePlugin", spec);
+        profilingReport("<initializePlugin", spec, &spec->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_profilingVerbosity++;
-        m_profileTimer.reset(new QElapsedTimer);
+    if (!m_profileTimer)
-        m_profileTimer->start();
+        PluginManager::startProfiling();
-        m_profileElapsedMS = 0;
-        qDebug("Profiling started");
-    } else {
-        m_profilingVerbosity++;
-    }
 }
 
-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()) {
+    if (m_profileTimer) {
-        const int absoluteElapsedMS = int(m_profileTimer->elapsed());
+        const qint64 absoluteElapsedMS = m_profileTimer->elapsed();
-        const int elapsedMS = absoluteElapsedMS - m_profileElapsedMS;
+        const qint64 elapsedMS = absoluteElapsedMS - m_profileElapsedMS;
         m_profileElapsedMS = absoluteElapsedMS;
-        if (spec)
+        if (m_profilingVerbosity > 0) {
-            qDebug("%-22s %-22s %8dms (%8dms)", what, qPrintable(spec->name()), absoluteElapsedMS, elapsedMS);
+            qDebug("%-22s %-22s %8lldms (%8lldms)",
-        else
+                   what,
-            qDebug("%-45s %8dms (%8dms)", what, absoluteElapsedMS, elapsedMS);
+                   qPrintable(spec->name()),
-        if (what && *what == '<') {
+                   absoluteElapsedMS,
+                   elapsedMS);
+        }
+        if (target) {
             QString tc;
-            if (spec) {
+            *target = elapsedMS;
-                m_profileTotal[spec] += elapsedMS;
+            tc = spec->name() + '_';
-                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()) {
+    if (m_profilingVerbosity > 0) {
-        QMultiMap<int, const PluginSpec *> sorter;
+        const QVector<PluginSpec *> specs
-        int total = 0;
+            = Utils::sorted(pluginSpecs, [](PluginSpec *s1, PluginSpec *s2) {
-
+                  return s1->performanceData().total() < s2->performanceData().total();
-        auto totalEnd = m_profileTotal.constEnd();
+              });
-        for (auto it = m_profileTotal.constBegin(); it != totalEnd; ++it) {
+        const qint64 total
-            sorter.insert(it.value(), it.key());
+            = std::accumulate(specs.constBegin(), specs.constEnd(), 0, [](qint64 t, PluginSpec *s) {
-            total += it.value();
+                  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);
         }
-
+        qDebug("Total: %8lldms", total);
-        auto sorterEnd = sorter.constEnd();
+        Utils::Benchmarker::report("loadPlugins", "Total", total);
-        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);
     }
 }
 
@@ -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

src/libs/extensionsystem/pluginmanager.h

@@ -64,6 +64,7 @@ public:
 
     static QObject *getObjectByName(const QString &name);
 
+    static void startProfiling();
     // Plugin operations
     static QVector<PluginSpec *> loadQueue();
     static void loadPlugins();

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<QElapsedTimer> m_profileTimer;
-    QHash<const PluginSpec *, int> m_profileTotal;
+    qint64 m_profileElapsedMS = 0;
-    int m_profileElapsedMS = 0;
     unsigned m_profilingVerbosity = 0;
     Utils::QtcSettings *settings = nullptr;
     Utils::QtcSettings *globalSettings = nullptr;

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.
 */

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<PluginDependency> dependencies() const;
     QJsonObject metaData() const;
+    const PerformanceData &performanceData() const;
 
     using PluginArgumentDescriptions = QVector<PluginArgumentDescription>;
     PluginArgumentDescriptions argumentDescriptions() const;

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);