diff options
author | Eike Ziller <eike.ziller@qt.io> | 2023-08-30 15:04:29 +0200 |
---|---|---|
committer | Eike Ziller <eike.ziller@qt.io> | 2023-09-12 07:32:07 +0000 |
commit | dab19c4a8c60ed482d1082064d23609a1acf4e5e (patch) | |
tree | 8b4279bffe8b1b58ffb81ef95845c53459fad1fb /src/libs | |
parent | 66c8eda94397f929cca2f8f6697aeeba396e1a5d (diff) |
Use Nanotrace to generate startup performance report
Add various trace points to the code, including the plugin
initialization methods (centrally in plugin manager), code that is
scheduled on the event loop with QTimer::singleShot or
QMetaObject::invokeMethod during initialization, and code that is
triggered from ICore::coreOpened
Can be turned on by configuring with `BUILD_LIBRARY_NANOTRACE=ON`
Run with `-trace <file>` to write trace file. If Nanotrace is not built,
the added code expands to nothing.
Changes in Nanotrace:
- turned generated data to microseconds instead of nanoseconds, because
that is what Chrome tracing expects
- fixed serialization of duration (needs to be an item of the event, not
in a "arg" subitem)
- fixed shutdown() to reset the initEvent
Change-Id: I994de82023b820d771e1be0a859ebd8da0b73d4d
Reviewed-by: <github-actions-qt-creator@cristianadam.eu>
Reviewed-by: Alessandro Portale <alessandro.portale@qt.io>
Diffstat (limited to 'src/libs')
-rw-r--r-- | src/libs/CMakeLists.txt | 2 | ||||
-rw-r--r-- | src/libs/extensionsystem/CMakeLists.txt | 5 | ||||
-rw-r--r-- | src/libs/extensionsystem/optionsparser.cpp | 13 | ||||
-rw-r--r-- | src/libs/extensionsystem/optionsparser.h | 2 | ||||
-rw-r--r-- | src/libs/extensionsystem/pluginmanager.cpp | 77 | ||||
-rw-r--r-- | src/libs/extensionsystem/pluginmanager_p.h | 1 | ||||
-rw-r--r-- | src/libs/nanotrace/nanotrace.cpp | 113 | ||||
-rw-r--r-- | src/libs/nanotrace/nanotrace.h | 2 | ||||
-rw-r--r-- | src/libs/utils/CMakeLists.txt | 5 | ||||
-rw-r--r-- | src/libs/utils/mimetypes2/mimedatabase.cpp | 3 |
10 files changed, 148 insertions, 75 deletions
diff --git a/src/libs/CMakeLists.txt b/src/libs/CMakeLists.txt index 73a554bae8b..536e3734949 100644 --- a/src/libs/CMakeLists.txt +++ b/src/libs/CMakeLists.txt @@ -1,5 +1,6 @@ add_subdirectory(3rdparty) +add_subdirectory(nanotrace) add_subdirectory(advanceddockingsystem) add_subdirectory(aggregation) add_subdirectory(cplusplus) @@ -8,7 +9,6 @@ add_subdirectory(glsl) add_subdirectory(languageserverprotocol) add_subdirectory(languageutils) add_subdirectory(modelinglib) -add_subdirectory(nanotrace) add_subdirectory(qmldebug) add_subdirectory(qmleditorwidgets) add_subdirectory(qmljs) diff --git a/src/libs/extensionsystem/CMakeLists.txt b/src/libs/extensionsystem/CMakeLists.txt index 0e4e6607a55..edc1daa2455 100644 --- a/src/libs/extensionsystem/CMakeLists.txt +++ b/src/libs/extensionsystem/CMakeLists.txt @@ -26,3 +26,8 @@ extend_qtc_library(ExtensionSystem DEPENDS Qt::Test DEFINES WITH_TESTS ) + +extend_qtc_library(ExtensionSystem + CONDITION TARGET Nanotrace + PUBLIC_DEPENDS Nanotrace +) diff --git a/src/libs/extensionsystem/optionsparser.cpp b/src/libs/extensionsystem/optionsparser.cpp index 116a1f4fe21..205442488e6 100644 --- a/src/libs/extensionsystem/optionsparser.cpp +++ b/src/libs/extensionsystem/optionsparser.cpp @@ -22,6 +22,7 @@ const char *OptionsParser::TEST_OPTION = "-test"; const char *OptionsParser::NOTEST_OPTION = "-notest"; const char *OptionsParser::SCENARIO_OPTION = "-scenario"; const char *OptionsParser::PROFILE_OPTION = "-profile"; +const char *OptionsParser::TRACE_OPTION = "-trace"; const char *OptionsParser::NO_CRASHCHECK_OPTION = "-no-crashcheck"; OptionsParser::OptionsParser(const QStringList &args, @@ -60,6 +61,8 @@ bool OptionsParser::parse() continue; if (checkForProfilingOption()) continue; + if (checkForTraceOption()) + continue; if (checkForNoCrashcheckOption()) continue; #ifdef WITH_TESTS @@ -243,6 +246,16 @@ bool OptionsParser::checkForProfilingOption() return true; } +bool OptionsParser::checkForTraceOption() +{ + if (m_currentArg != QLatin1String(TRACE_OPTION)) + return false; + if (nextToken(RequiredToken)) { + m_pmPrivate->enableTracing(m_currentArg); + } + return true; +} + bool OptionsParser::checkForNoCrashcheckOption() { if (m_currentArg != QLatin1String(NO_CRASHCHECK_OPTION)) diff --git a/src/libs/extensionsystem/optionsparser.h b/src/libs/extensionsystem/optionsparser.h index ee11582c3b0..93f3812c8d3 100644 --- a/src/libs/extensionsystem/optionsparser.h +++ b/src/libs/extensionsystem/optionsparser.h @@ -28,6 +28,7 @@ public: static const char *NOTEST_OPTION; static const char *SCENARIO_OPTION; static const char *PROFILE_OPTION; + static const char *TRACE_OPTION; static const char *NO_CRASHCHECK_OPTION; private: @@ -41,6 +42,7 @@ private: bool checkForAppOption(); bool checkForPluginOption(); bool checkForProfilingOption(); + bool checkForTraceOption(); bool checkForNoCrashcheckOption(); bool checkForUnknownOption(); void forceDisableAllPluginsExceptTestedAndForceEnabled(); diff --git a/src/libs/extensionsystem/pluginmanager.cpp b/src/libs/extensionsystem/pluginmanager.cpp index 6d56fdb2dc3..e24f92447df 100644 --- a/src/libs/extensionsystem/pluginmanager.cpp +++ b/src/libs/extensionsystem/pluginmanager.cpp @@ -10,6 +10,8 @@ #include "pluginspec.h" #include "pluginspec_p.h" +#include <nanotrace/nanotrace.h> + #include <utils/algorithm.h> #include <utils/benchmarker.h> #include <utils/fileutils.h> @@ -722,6 +724,12 @@ void PluginManager::formatOptions(QTextStream &str, int optionIndentation, int d QString(), QLatin1String("Profile plugin loading"), optionIndentation, descriptionIndentation); formatOption(str, + QLatin1String(OptionsParser::TRACE_OPTION), + QLatin1String("file"), + QLatin1String("Write trace file (CTF) for plugin loading"), + optionIndentation, + descriptionIndentation); + formatOption(str, QLatin1String(OptionsParser::NO_CRASHCHECK_OPTION), QString(), QLatin1String("Disable startup check for previously crashed instance"), @@ -932,9 +940,16 @@ PluginSpecPrivate *PluginManagerPrivate::privateSpec(PluginSpec *spec) void PluginManagerPrivate::nextDelayedInitialize() { + static bool first = true; + if (first) { + first = false; + NANOTRACE_BEGIN("ExtensionSystem", "DelayedInitialize"); + } while (!delayedInitializeQueue.empty()) { PluginSpec *spec = delayedInitializeQueue.front(); + const std::string specName = spec->name().toStdString(); delayedInitializeQueue.pop(); + NANOTRACE_SCOPE(specName, specName + "::delayedInitialized"); profilingReport(">delayedInitialize", spec); bool delay = spec->d->delayedInitialize(); profilingReport("<delayedInitialize", spec, &spec->d->performanceData.delayedInitialize); @@ -948,6 +963,8 @@ void PluginManagerPrivate::nextDelayedInitialize() if (m_profileTimer) m_totalStartupMS = m_profileTimer->elapsed(); printProfilingSummary(); + NANOTRACE_END("ExtensionSystem", "DelayedInitialize"); + NANOTRACE_SHUTDOWN(); emit q->initializationDone(); #ifdef WITH_TESTS if (PluginManager::testRunRequested()) @@ -1340,23 +1357,32 @@ void PluginManagerPrivate::loadPlugins() const QVector<PluginSpec *> queue = loadQueue(); Utils::setMimeStartupPhase(MimeStartupPhase::PluginsLoading); - for (PluginSpec *spec : queue) - loadPlugin(spec, PluginSpec::Loaded); + { + NANOTRACE_SCOPE("ExtensionSystem", "Load"); + for (PluginSpec *spec : queue) + loadPlugin(spec, PluginSpec::Loaded); + } Utils::setMimeStartupPhase(MimeStartupPhase::PluginsInitializing); - for (PluginSpec *spec : queue) - loadPlugin(spec, PluginSpec::Initialized); + { + NANOTRACE_SCOPE("ExtensionSystem", "Initialize"); + for (PluginSpec *spec : queue) + loadPlugin(spec, PluginSpec::Initialized); + } Utils::setMimeStartupPhase(MimeStartupPhase::PluginsDelayedInitializing); - Utils::reverseForeach(queue, [this](PluginSpec *spec) { - loadPlugin(spec, PluginSpec::Running); - if (spec->state() == PluginSpec::Running) { - delayedInitializeQueue.push(spec); - } else { - // Plugin initialization failed, so cleanup after it - spec->d->kill(); - } - }); + { + NANOTRACE_SCOPE("ExtensionSystem", "ExtensionsInitialized"); + Utils::reverseForeach(queue, [this](PluginSpec *spec) { + loadPlugin(spec, PluginSpec::Running); + if (spec->state() == PluginSpec::Running) { + delayedInitializeQueue.push(spec); + } else { + // Plugin initialization failed, so cleanup after it + spec->d->kill(); + } + }); + } emit q->pluginsChanged(); Utils::setMimeStartupPhase(MimeStartupPhase::UpAndRunning); @@ -1582,14 +1608,18 @@ void PluginManagerPrivate::loadPlugin(PluginSpec *spec, PluginSpec::State destSt if (enableCrashCheck && destState < PluginSpec::Stopped) lockFile.reset(new LockFile(this, spec)); + const std::string specName = spec->name().toStdString(); + switch (destState) { - case PluginSpec::Running: + case PluginSpec::Running: { + NANOTRACE_SCOPE(specName, specName + "::extensionsInitialized"); profilingReport(">initializeExtensions", spec); spec->d->initializeExtensions(); profilingReport("<initializeExtensions", spec, &spec->d->performanceData.extensionsInitialized); return; + } case PluginSpec::Deleted: profilingReport(">delete", spec); spec->d->kill(); @@ -1613,16 +1643,20 @@ void PluginManagerPrivate::loadPlugin(PluginSpec *spec, PluginSpec::State destSt } } switch (destState) { - case PluginSpec::Loaded: + case PluginSpec::Loaded: { + NANOTRACE_SCOPE(specName, specName + "::load"); profilingReport(">loadLibrary", spec); spec->d->loadLibrary(); profilingReport("<loadLibrary", spec, &spec->d->performanceData.load); break; - case PluginSpec::Initialized: + } + case PluginSpec::Initialized: { + NANOTRACE_SCOPE(specName, specName + "::initialize"); profilingReport(">initializePlugin", spec); spec->d->initializePlugin(); profilingReport("<initializePlugin", spec, &spec->d->performanceData.initialize); break; + } case PluginSpec::Stopped: profilingReport(">stop", spec); if (spec->d->stop() == IPlugin::AsynchronousShutdown) { @@ -1764,6 +1798,17 @@ void PluginManagerPrivate::increaseProfilingVerbosity() PluginManager::startProfiling(); } +void PluginManagerPrivate::enableTracing(const QString &filePath) +{ + const QString jsonFilePath = filePath.endsWith(".json") ? filePath : filePath + ".json"; +#ifdef NANOTRACE_ENABLED + qDebug() << "Trace event file (CTF) will be saved at" << qPrintable(jsonFilePath); +#endif + NANOTRACE_INIT(QCoreApplication::applicationName().toStdString(), + "Main", + jsonFilePath.toStdString()); +} + void PluginManagerPrivate::profilingReport(const char *what, const PluginSpec *spec, qint64 *target) { if (m_profileTimer) { diff --git a/src/libs/extensionsystem/pluginmanager_p.h b/src/libs/extensionsystem/pluginmanager_p.h index 63d017ac556..a0ea60ed483 100644 --- a/src/libs/extensionsystem/pluginmanager_p.h +++ b/src/libs/extensionsystem/pluginmanager_p.h @@ -59,6 +59,7 @@ public: void resolveDependencies(); void enableDependenciesIndirectly(); void increaseProfilingVerbosity(); + void enableTracing(const QString &filePath); QString profilingSummary(qint64 *totalOut = nullptr) const; void printProfilingSummary() const; void profilingReport(const char *what, const PluginSpec *spec, qint64 *target = nullptr); diff --git a/src/libs/nanotrace/nanotrace.cpp b/src/libs/nanotrace/nanotrace.cpp index 6af2db58bcf..658d84a43f1 100644 --- a/src/libs/nanotrace/nanotrace.cpp +++ b/src/libs/nanotrace/nanotrace.cpp @@ -73,6 +73,7 @@ struct TraceEvent int64_t oh; int64_t ts; + int64_t dur = 0; std::vector< Nanotrace::Arg > args; @@ -100,7 +101,10 @@ std::ostream& operator<<(std::ostream &stream, const TraceEvent &event) << "{ \"cat\":\"" << event.cat << "\", \"pid\":" << event.pid << ", \"tid\":\"" << event.tid << "\"" - << ", \"ts\":" << event.ts + << ", \"ts\":" << event.ts; + if (event.dur > -1) + stream << ", \"dur\":" << event.dur; + stream << ", \"ph\":\"" << event.ph << "\", \"name\":\"" << event.name << "\", \"args\": { \"overhead\": " << event.oh; @@ -112,7 +116,6 @@ std::ostream& operator<<(std::ostream &stream, const TraceEvent &event) return stream; } - void init(const std::string &process, const std::string &thread, const std::string &path) { auto now = Clock::now(); @@ -125,43 +128,40 @@ void init(const std::string &process, const std::string &thread, const std::stri initEvent.ts = now; events.reserve(eventCount); - events.push_back(TraceEvent { - getProcessId(), - std::this_thread::get_id(), - "process_name", - "", - 'M', - 0, - 0, - {{"name", process}} - } ); - - events.push_back(TraceEvent { - getProcessId(), - std::this_thread::get_id(), - "thread_name", - "", - 'M', - 0, - 0, - {{"name", thread}} - } ); + events.push_back(TraceEvent{getProcessId(), + std::this_thread::get_id(), + "process_name", + "", + 'M', + 0, + 0, + -1, + {{"name", process}}}); + + events.push_back(TraceEvent{getProcessId(), + std::this_thread::get_id(), + "thread_name", + "", + 'M', + 0, + 0, + -1, + {{"name", thread}}}); if (std::ofstream stream(path, std::ios::trunc); stream.good()) stream << "{ \"traceEvents\": [\n"; else std::cout << "Nanotrace::init: stream not good" << std::endl; - events.push_back(TraceEvent { - getProcessId(), - std::this_thread::get_id(), - "Initialize", - "Initialize", - 'I', - 0, - std::chrono::duration_cast< Units >(Clock::now() - now).count(), - {} - } ); + events.push_back(TraceEvent{getProcessId(), + std::this_thread::get_id(), + "Initialize", + "Initialize", + 'I', + 0, + std::chrono::duration_cast<Units>(Clock::now() - now).count(), + -1, + {}}); initEvent.overhead = std::chrono::duration_cast< Units >(Clock::now() - now).count(); } @@ -174,6 +174,7 @@ void shutdown() stream << "\n] }"; else std::cout << "Nanotrace::shutdown: stream not good" << std::endl; + initEvent = {}; } void addTracePoint( @@ -188,16 +189,15 @@ void addTracePoint( auto now = Clock::now(); auto beg = std::chrono::duration_cast< Units >(now - initEvent.ts); - events.push_back( TraceEvent { - getProcessId(), - std::this_thread::get_id(), - name, - cat, - phase, - initEvent.overhead, - beg.count(), - {arguments} - } ); + events.push_back(TraceEvent{getProcessId(), + std::this_thread::get_id(), + name, + cat, + phase, + initEvent.overhead, + beg.count(), + -1, + {arguments}}); if (events.size() >= eventCount - 1) flush(); @@ -238,20 +238,19 @@ ScopeTracer::~ScopeTracer() return; auto now = Clock::now(); - auto beg = std::chrono::duration_cast< Units >(m_start - initEvent.ts); - - m_args.push_back(Arg("dur", std::chrono::duration_cast< Units >(now - m_start).count())); - - events.push_back(TraceEvent { - getProcessId(), - std::this_thread::get_id(), - m_name, - m_cat, - 'X', - initEvent.overhead, - beg.count(), - { m_args } - } ); + auto beg = std::chrono::duration_cast<Units>(m_start - initEvent.ts); + const int64_t dur = std::chrono::duration_cast<Units>(now - m_start).count(); + + m_args.push_back(Arg("dur", dur)); + events.push_back(TraceEvent{getProcessId(), + std::this_thread::get_id(), + m_name, + m_cat, + 'X', + initEvent.overhead, + beg.count(), + dur, + {m_args}}); if (events.size() >= eventCount - 1) flush(); diff --git a/src/libs/nanotrace/nanotrace.h b/src/libs/nanotrace/nanotrace.h index ab390519caf..65bc66d0cf2 100644 --- a/src/libs/nanotrace/nanotrace.h +++ b/src/libs/nanotrace/nanotrace.h @@ -50,7 +50,7 @@ namespace Nanotrace { -using Units = std::chrono::nanoseconds; +using Units = std::chrono::microseconds; using Clock = std::chrono::high_resolution_clock; using TimePoint = std::chrono::time_point< Clock >; diff --git a/src/libs/utils/CMakeLists.txt b/src/libs/utils/CMakeLists.txt index 79f2bc323ae..b7f956f968f 100644 --- a/src/libs/utils/CMakeLists.txt +++ b/src/libs/utils/CMakeLists.txt @@ -276,6 +276,11 @@ extend_qtc_library(Utils fsengine/filepathinfocache.h ) +extend_qtc_library(Utils + CONDITION TARGET Nanotrace + DEPENDS Nanotrace +) + if (WIN32) add_qtc_executable(qtcreator_ctrlc_stub DEPENDS user32 shell32 diff --git a/src/libs/utils/mimetypes2/mimedatabase.cpp b/src/libs/utils/mimetypes2/mimedatabase.cpp index cba76f733ae..b4966a952dd 100644 --- a/src/libs/utils/mimetypes2/mimedatabase.cpp +++ b/src/libs/utils/mimetypes2/mimedatabase.cpp @@ -13,6 +13,8 @@ #include "algorithm.h" +#include <nanotrace/nanotrace.h> + #include <QFile> #include <QFileInfo> #include <QStandardPaths> @@ -90,6 +92,7 @@ static void updateOverriddenMimeTypes(std::vector<std::unique_ptr<MimeProviderBa void MimeDatabasePrivate::loadProviders() { + NANOTRACE_SCOPE("Utils", "MimeDatabasePrivate::loadProviders"); #if 0 // We use QStandardPaths every time to check if new files appeared const QStringList mimeDirs = QStandardPaths::locateAll(QStandardPaths::GenericDataLocation, QLatin1String("mime"), QStandardPaths::LocateDirectory); |