Time more operations

Change-Id: I1aa46693cb71fe284083ee5305ce2650de1307ac
Reviewed-by: Jake Petroules <jake.petroules@qt.io>

19 files changed, 323 insertions, 74 deletions

diff --git a/src/lib/corelib/api/internaljobs.cpp b/src/lib/corelib/api/internaljobs.cpp
index 8b0f5a5c7..339a7fa0f 100644
--- a/src/lib/corelib/api/internaljobs.cpp
+++ b/src/lib/corelib/api/internaljobs.cpp
@@ -54,6 +54,7 @@
 #include <logging/translator.h>
 #include <tools/buildgraphlocker.h>
 #include <tools/error.h>
+#include <tools/profiling.h>
 #include <tools/progressobserver.h>
 #include <tools/preferences.h>
 #include <tools/qbsassert.h>
diff --git a/src/lib/corelib/buildgraph/buildgraphloader.cpp b/src/lib/corelib/buildgraph/buildgraphloader.cpp
index 5a4c3d226..a0b769775 100644
--- a/src/lib/corelib/buildgraph/buildgraphloader.cpp
+++ b/src/lib/corelib/buildgraph/buildgraphloader.cpp
@@ -57,6 +57,7 @@
 #include <logging/translator.h>
 #include <tools/fileinfo.h>
 #include <tools/persistence.h>
+#include <tools/profiling.h>
 #include <tools/propertyfinder.h>
 #include <tools/qbsassert.h>
 
diff --git a/src/lib/corelib/buildgraph/executor.cpp b/src/lib/corelib/buildgraph/executor.cpp
index cca64efd0..42b96eee6 100644
--- a/src/lib/corelib/buildgraph/executor.cpp
+++ b/src/lib/corelib/buildgraph/executor.cpp
@@ -58,6 +58,7 @@
 #include <logging/translator.h>
 #include <tools/error.h>
 #include <tools/fileinfo.h>
+#include <tools/profiling.h>
 #include <tools/progressobserver.h>
 #include <tools/qbsassert.h>
 
@@ -227,6 +228,9 @@ void Executor::doBuild()
             = RulesEvaluationContextPtr(new RulesEvaluationContext(m_logger));
     m_evalContext = m_project->buildData->evaluationContext;
 
+    m_elapsedTimeRules = m_elapsedTimeScanners = m_elapsedTimeInstalling = 0;
+    m_evalContext->engine()->enableProfiling(m_buildOptions.logElapsedTime());
+
     InstallOptions installOptions;
     installOptions.setDryRun(m_buildOptions.dryRun());
     installOptions.setInstallRoot(m_productsToBuild.first()->moduleProperties
@@ -443,6 +447,8 @@ void Executor::buildArtifact(Artifact *artifact)
 
 void Executor::executeRuleNode(RuleNode *ruleNode)
 {
+    AccumulatingTimer rulesTimer(m_buildOptions.logElapsedTime() ? &m_elapsedTimeRules : nullptr);
+
     if (!checkNodeProduct(ruleNode))
         return;
 
@@ -880,7 +886,10 @@ void Executor::potentiallyRunTransformer(const TransformerPtr &transformer)
         // Scan all input artifacts. If new dependencies were found during scanning, delay
         // execution of this transformer.
         InputArtifactScanner scanner(output, m_inputArtifactScanContext, m_logger);
+        AccumulatingTimer scanTimer(m_buildOptions.logElapsedTime()
+                                    ? &m_elapsedTimeScanners : nullptr);
         scanner.scan();
+        scanTimer.stop();
         if (scanner.newDependencyAdded() && checkForUnbuiltDependencies(output))
             return;
     }
@@ -926,6 +935,9 @@ void Executor::finishTransformer(const TransformerPtr &transformer)
 
 void Executor::possiblyInstallArtifact(const Artifact *artifact)
 {
+    AccumulatingTimer installTimer(m_buildOptions.logElapsedTime()
+                                   ? &m_elapsedTimeInstalling : nullptr);
+
     if (m_buildOptions.install() && !m_buildOptions.executeRulesOnly()
             && (m_activeFileTags.isEmpty() || artifactHasMatchingOutputTags(artifact))
             && artifact->properties->qbsPropertyValue(QLatin1String("install")).toBool()) {
@@ -1034,6 +1046,15 @@ void Executor::finish()
     EmptyDirectoriesRemover(m_project.data(), m_logger)
             .removeEmptyParentDirectories(m_artifactsRemovedFromDisk);
 
+    if (m_buildOptions.logElapsedTime()) {
+        m_logger.qbsLog(LoggerInfo, true) << "\t" << Tr::tr("Rule execution took %1.")
+                                             .arg(elapsedTimeString(m_elapsedTimeRules));
+        m_logger.qbsLog(LoggerInfo, true) << "\t" << Tr::tr("Artifact scanning took %1.")
+                                             .arg(elapsedTimeString(m_elapsedTimeScanners));
+        m_logger.qbsLog(LoggerInfo, true) << "\t" << Tr::tr("Installing artifacts took %1.")
+                                             .arg(elapsedTimeString(m_elapsedTimeInstalling));
+    }
+
     emit finished();
 }
 
diff --git a/src/lib/corelib/buildgraph/executor.h b/src/lib/corelib/buildgraph/executor.h
index 8aecfdd85..1f6bfc7de 100644
--- a/src/lib/corelib/buildgraph/executor.h
+++ b/src/lib/corelib/buildgraph/executor.h
@@ -172,6 +172,9 @@ private:
     QTimer * const m_cancelationTimer;
     QStringList m_artifactsRemovedFromDisk;
     bool m_partialBuild;
+    qint64 m_elapsedTimeRules;
+    qint64 m_elapsedTimeScanners;
+    qint64 m_elapsedTimeInstalling;
     const bool m_doTrace;
     const bool m_doDebug;
 };
diff --git a/src/lib/corelib/corelib.qbs b/src/lib/corelib/corelib.qbs
index e12a37a45..024b0ed8b 100644
--- a/src/lib/corelib/corelib.qbs
+++ b/src/lib/corelib/corelib.qbs
@@ -370,6 +370,8 @@ QbsLibrary {
             "processutils.cpp",
             "processutils.h",
             "profile.cpp",
+            "profiling.cpp",
+            "profiling.h",
             "progressobserver.cpp",
             "progressobserver.h",
             "projectgeneratormanager.cpp",
diff --git a/src/lib/corelib/language/itemreader.cpp b/src/lib/corelib/language/itemreader.cpp
index 6386aaebc..4f6a315b2 100644
--- a/src/lib/corelib/language/itemreader.cpp
+++ b/src/lib/corelib/language/itemreader.cpp
@@ -41,6 +41,8 @@
 
 #include "itemreadervisitorstate.h"
 
+#include <tools/profiling.h>
+
 namespace qbs {
 namespace Internal {
 
@@ -84,6 +86,7 @@ QStringList ItemReader::searchPaths() const
 
 Item *ItemReader::readFile(const QString &filePath)
 {
+    AccumulatingTimer readFileTimer(m_elapsedTime != -1 ? &m_elapsedTime : nullptr);
     return m_visitorState->readFile(filePath, searchPaths(), m_pool);
 }
 
@@ -92,5 +95,10 @@ QSet<QString> ItemReader::filesRead() const
     return m_visitorState->filesRead();
 }
 
+void ItemReader::setEnableTiming(bool on)
+{
+    m_elapsedTime = on ? 0 : -1;
+}
+
 } // namespace Internal
 } // namespace qbs
diff --git a/src/lib/corelib/language/itemreader.h b/src/lib/corelib/language/itemreader.h
index 091aa6734..20cfc0e1e 100644
--- a/src/lib/corelib/language/itemreader.h
+++ b/src/lib/corelib/language/itemreader.h
@@ -82,11 +82,15 @@ public:
 
     QSet<QString> filesRead() const;
 
+    void setEnableTiming(bool on);
+    qint64 elapsedTime() const { return m_elapsedTime; }
+
 private:
     ItemPool *m_pool = nullptr;
     QStringList m_searchPaths;
     QStack<QStringList> m_extraSearchPaths;
     ItemReaderVisitorState * const m_visitorState;
+    qint64 m_elapsedTime = -1;
 };
 
 } // namespace Internal
diff --git a/src/lib/corelib/language/loader.cpp b/src/lib/corelib/language/loader.cpp
index 29eff18a1..bec581a27 100644
--- a/src/lib/corelib/language/loader.cpp
+++ b/src/lib/corelib/language/loader.cpp
@@ -98,6 +98,7 @@ TopLevelProjectPtr Loader::loadProject(const SetupProjectParameters &parameters)
     m_engine->clearExceptions();
     m_engine->clearImportsCache();
     m_engine->clearRequestedProperties();
+    m_engine->enableProfiling(parameters.logElapsedTime());
     m_logger.clearWarnings();
 
     QTimer cancelationTimer;
diff --git a/src/lib/corelib/language/moduleloader.cpp b/src/lib/corelib/language/moduleloader.cpp
index e29314002..3a4611ba1 100644
--- a/src/lib/corelib/language/moduleloader.cpp
+++ b/src/lib/corelib/language/moduleloader.cpp
@@ -58,6 +58,7 @@
 #include <tools/fileinfo.h>
 #include <tools/preferences.h>
 #include <tools/profile.h>
+#include <tools/profiling.h>
 #include <tools/progressobserver.h>
 #include <tools/qbsassert.h>
 #include <tools/scripttools.h>
@@ -231,6 +232,8 @@ ModuleLoaderResult ModuleLoader::load(const SetupProjectParameters &parameters)
     m_modulePrototypeItemCache.clear();
     m_disabledItems.clear();
     m_reader->clearExtraSearchPathsStack();
+    m_reader->setEnableTiming(parameters.logElapsedTime());
+    m_elapsedTimeProbes = 0;
 
     ModuleLoaderResult result;
     m_pool = result.itemPool.data();
@@ -260,6 +263,7 @@ ModuleLoaderResult ModuleLoader::load(const SetupProjectParameters &parameters)
                   QSet<QString>() << QDir::cleanPath(parameters.projectFilePath()));
     result.root = root;
     result.qbsFiles = m_reader->filesRead();
+    printProfilingInfo();
     return result;
 }
 
@@ -975,6 +979,18 @@ ProbeConstPtr ModuleLoader::findCurrentProbe(const CodeLocation &location, bool
     return ProbeConstPtr();
 }
 
+void ModuleLoader::printProfilingInfo()
+{
+    if (!m_parameters.logElapsedTime())
+        return;
+    m_logger.qbsLog(LoggerInfo, true) << "\t"
+                                      << Tr::tr("Project file loading and parsing took %1.")
+                                         .arg(elapsedTimeString(m_reader->elapsedTime()));
+    m_logger.qbsLog(LoggerInfo, true) << "\t"
+                                      << Tr::tr("Running Probes took %1.")
+                                         .arg(elapsedTimeString(m_elapsedTimeProbes));
+}
+
 void ModuleLoader::mergeExportItems(const ProductContext &productContext)
 {
     QVector<Item *> exportItems;
@@ -1812,6 +1828,7 @@ void ModuleLoader::createChildInstances(ProductContext *productContext, Item *in
 
 void ModuleLoader::resolveProbes(ProductContext *productContext, Item *item)
 {
+    AccumulatingTimer probesTimer(m_parameters.logElapsedTime() ? &m_elapsedTimeProbes : nullptr);
     foreach (Item *child, item->children())
         if (child->type() == ItemType::Probe)
             resolveProbe(productContext, item, child);
diff --git a/src/lib/corelib/language/moduleloader.h b/src/lib/corelib/language/moduleloader.h
index 8f576786d..04b93dd3e 100644
--- a/src/lib/corelib/language/moduleloader.h
+++ b/src/lib/corelib/language/moduleloader.h
@@ -261,6 +261,7 @@ private:
                                const QString &sourceCode) const;
     ProbeConstPtr findCurrentProbe(const CodeLocation &location, bool condition,
                                    const QVariantMap &initialProperties) const;
+    void printProfilingInfo();
 
     ScriptEngine *m_engine;
     ItemPool *m_pool;
@@ -280,6 +281,7 @@ private:
     SetupProjectParameters m_parameters;
     Version m_qbsVersion;
     Item *m_tempScopeItem = nullptr;
+    qint64 m_elapsedTimeProbes;
 };
 
 } // namespace Internal
diff --git a/src/lib/corelib/language/projectresolver.cpp b/src/lib/corelib/language/projectresolver.cpp
index 9913dd863..eeb33662b 100644
--- a/src/lib/corelib/language/projectresolver.cpp
+++ b/src/lib/corelib/language/projectresolver.cpp
@@ -53,6 +53,7 @@
 #include <logging/translator.h>
 #include <tools/error.h>
 #include <tools/fileinfo.h>
+#include <tools/profiling.h>
 #include <tools/progressobserver.h>
 #include <tools/scripttools.h>
 #include <tools/qbsassert.h>
@@ -151,7 +152,10 @@ TopLevelProjectPtr ProjectResolver::resolve()
 
     m_productContext = 0;
     m_moduleContext = 0;
-    return resolveTopLevelProject();
+    m_elapsedTimeModPropEval = m_elapsedTimeAllPropEval = m_elapsedTimeGroups = 0;
+    const TopLevelProjectPtr tlp = resolveTopLevelProject();
+    printProfilingInfo();
+    return tlp;
 }
 
 void ProjectResolver::checkCancelation() const
@@ -549,6 +553,9 @@ void ProjectResolver::resolveGroup(Item *item, ProjectContext *projectContext)
         m_evaluator->setCachingEnabled(false);
     }
 
+    AccumulatingTimer groupTimer(m_setupParams.logElapsedTime()
+                                       ? &m_elapsedTimeGroups : nullptr);
+
     bool isEnabled = m_evaluator->boolValue(item, QLatin1String("condition"));
     if (m_productContext->currentGroup)
         isEnabled = isEnabled && m_productContext->currentGroup->enabled;
@@ -925,6 +932,20 @@ void ProjectResolver::matchArtifactProperties(const ResolvedProductPtr &product,
     }
 }
 
+void ProjectResolver::printProfilingInfo()
+{
+    if (!m_setupParams.logElapsedTime())
+        return;
+    m_logger.qbsLog(LoggerInfo, true) << "\t" << Tr::tr("All property evaluation took %1.")
+                                         .arg(elapsedTimeString(m_elapsedTimeAllPropEval));
+    m_logger.qbsLog(LoggerInfo, true) << "\t" << Tr::tr("Module property evaluation took %1.")
+                                         .arg(elapsedTimeString(m_elapsedTimeModPropEval));
+    m_logger.qbsLog(LoggerInfo, true) << "\t"
+                                      << Tr::tr("Resolving groups (without module property "
+                                                "evaluation) took %1.")
+                                         .arg(elapsedTimeString(m_elapsedTimeGroups));
+}
+
 static bool hasDependencyCycle(QSet<ResolvedProduct *> *checked,
                                QSet<ResolvedProduct *> *branch,
                                const ResolvedProductPtr &product,
@@ -1050,8 +1071,10 @@ void ProjectResolver::applyFileTaggers(const SourceArtifactPtr &artifact,
     }
 }
 
-QVariantMap ProjectResolver::evaluateModuleValues(Item *item, bool lookupPrototype) const
+QVariantMap ProjectResolver::evaluateModuleValues(Item *item, bool lookupPrototype)
 {
+    AccumulatingTimer modPropEvalTimer(m_setupParams.logElapsedTime()
+                                       ? &m_elapsedTimeModPropEval : nullptr);
     QVariantMap moduleValues;
     foreach (const Item::Module &module, item->modules()) {
         const QString fullName = module.name.toString();
@@ -1063,15 +1086,17 @@ QVariantMap ProjectResolver::evaluateModuleValues(Item *item, bool lookupPrototy
     return result;
 }
 
-QVariantMap ProjectResolver::evaluateProperties(Item *item, bool lookupPrototype) const
+QVariantMap ProjectResolver::evaluateProperties(Item *item, bool lookupPrototype)
 {
     const QVariantMap tmplt;
     return evaluateProperties(item, item, tmplt, lookupPrototype);
 }
 
 QVariantMap ProjectResolver::evaluateProperties(Item *item, Item *propertiesContainer,
-        const QVariantMap &tmplt, bool lookupPrototype) const
+        const QVariantMap &tmplt, bool lookupPrototype)
 {
+    AccumulatingTimer propEvalTimer(m_setupParams.logElapsedTime()
+                                    ? &m_elapsedTimeAllPropEval : nullptr);
     QVariantMap result = tmplt;
     for (QMap<QString, ValuePtr>::const_iterator it = propertiesContainer->properties().begin();
          it != propertiesContainer->properties().end(); ++it)
@@ -1129,7 +1154,7 @@ QVariantMap ProjectResolver::evaluateProperties(Item *item, Item *propertiesCont
             : result;
 }
 
-QVariantMap ProjectResolver::createProductConfig() const
+QVariantMap ProjectResolver::createProductConfig()
 {
     m_evaluator->setCachingEnabled(true);
     QVariantMap cfg = evaluateModuleValues(m_productContext->item);
diff --git a/src/lib/corelib/language/projectresolver.h b/src/lib/corelib/language/projectresolver.h
index 820cc2a20..817f54522 100644
--- a/src/lib/corelib/language/projectresolver.h
+++ b/src/lib/corelib/language/projectresolver.h
@@ -105,11 +105,11 @@ private:
     void resolveProductDependencies(const ProjectContext &projectContext);
     void postProcess(const ResolvedProductPtr &product, ProjectContext *projectContext) const;
     void applyFileTaggers(const ResolvedProductPtr &product) const;
-    QVariantMap evaluateModuleValues(Item *item, bool lookupPrototype = true) const;
-    QVariantMap evaluateProperties(Item *item, bool lookupPrototype = true) const;
+    QVariantMap evaluateModuleValues(Item *item, bool lookupPrototype = true);
+    QVariantMap evaluateProperties(Item *item, bool lookupPrototype = true);
     QVariantMap evaluateProperties(Item *item, Item *propertiesContainer, const QVariantMap &tmplt,
-            bool lookupPrototype = true) const;
-    QVariantMap createProductConfig() const;
+            bool lookupPrototype = true);
+    QVariantMap createProductConfig();
     QString convertPathProperty(const QString &path, const QString &dirPath) const;
     QStringList convertPathListProperty(const QStringList &paths, const QString &dirPath) const;
     ProjectContext createProjectContext(ProjectContext *parentProjectContext) const;
@@ -117,6 +117,7 @@ private:
             const ModuleLoaderResult::ProductInfo &productInfo, bool &disabledDependency);
     static void matchArtifactProperties(const ResolvedProductPtr &product,
             const QList<SourceArtifactPtr> &artifacts);
+    void printProfilingInfo();
 
     Evaluator *m_evaluator;
     Logger &m_logger;
@@ -130,6 +131,9 @@ private:
     mutable QHash<FileContextConstPtr, ResolvedFileContextPtr> m_fileContextMap;
     const SetupProjectParameters &m_setupParams;
     const ModuleLoaderResult &m_loadResult;
+    qint64 m_elapsedTimeModPropEval;
+    qint64 m_elapsedTimeAllPropEval;
+    qint64 m_elapsedTimeGroups;
 
     typedef void (ProjectResolver::*ItemFuncPtr)(Item *item, ProjectContext *projectContext);
     typedef QMap<ItemType, ItemFuncPtr> ItemFuncMap;
diff --git a/src/lib/corelib/language/scriptengine.cpp b/src/lib/corelib/language/scriptengine.cpp
index 75b7c8aab..5be7b6ad0 100644
--- a/src/lib/corelib/language/scriptengine.cpp
+++ b/src/lib/corelib/language/scriptengine.cpp
@@ -48,8 +48,10 @@
 #include <buildgraph/artifact.h>
 #include <jsextensions/environmentextension.h>
 #include <jsextensions/jsextensions.h>
+#include <logging/translator.h>
 #include <tools/error.h>
 #include <tools/fileinfo.h>
+#include <tools/profiling.h>
 #include <tools/qbsassert.h>
 
 #include <QDebug>
@@ -107,6 +109,10 @@ ScriptEngine::~ScriptEngine()
 {
     qDeleteAll(m_ownedVariantMaps);
     delete (m_scriptImporter);
+    if (m_elapsedTimeImporting != -1) {
+        m_logger.qbsLog(LoggerInfo, true) << Tr::tr("Setting up imports took %1.")
+                                             .arg(elapsedTimeString(m_elapsedTimeImporting));
+    }
 }
 
 void ScriptEngine::import(const FileContextBaseConstPtr &fileCtx, QScriptValue &targetObject)
@@ -159,6 +165,11 @@ void ScriptEngine::addPropertyRequestedFromArtifact(const Artifact *artifact,
     m_propertiesRequestedFromArtifact[artifact->filePath()] << property;
 }
 
+void ScriptEngine::enableProfiling(bool enable)
+{
+    m_elapsedTimeImporting = enable ? 0 : -1;
+}
+
 void ScriptEngine::addToPropertyCache(const QString &moduleName, const QString &propertyName,
         const PropertyMapConstPtr &propertyMap, const QVariant &value)
 {
@@ -243,6 +254,7 @@ void ScriptEngine::setEnvironment(const QProcessEnvironment &env)
 
 void ScriptEngine::importFile(const QString &filePath, QScriptValue &targetObject)
 {
+    AccumulatingTimer importTimer(m_elapsedTimeImporting != -1 ? &m_elapsedTimeImporting : nullptr);
     QFile file(filePath);
     if (Q_UNLIKELY(!file.open(QFile::ReadOnly)))
         throw ErrorInfo(tr("Cannot open '%1'.").arg(filePath));
diff --git a/src/lib/corelib/language/scriptengine.h b/src/lib/corelib/language/scriptengine.h
index 192d337b5..146a4db00 100644
--- a/src/lib/corelib/language/scriptengine.h
+++ b/src/lib/corelib/language/scriptengine.h
@@ -85,6 +85,8 @@ public:
         return m_propertiesRequestedFromArtifact;
     }
 
+    void enableProfiling(bool enable);
+
     void setPropertyCacheEnabled(bool enable) { m_propertyCacheEnabled = enable; }
     bool isPropertyCacheEnabled() const { return m_propertyCacheEnabled; }
     void addToPropertyCache(const QString &moduleName, const QString &propertyName,
@@ -188,6 +190,7 @@ private:
     QScriptValue m_consoleObject;
     QScriptValue m_cancelationError;
     QList<QVariantMap *> m_ownedVariantMaps;
+    qint64 m_elapsedTimeImporting = -1;
 };
 
 } // namespace Internal
diff --git a/src/lib/corelib/logging/logger.cpp b/src/lib/corelib/logging/logger.cpp
index 9a7811fb5..7aadd785b 100644
--- a/src/lib/corelib/logging/logger.cpp
+++ b/src/lib/corelib/logging/logger.cpp
@@ -43,8 +43,6 @@
 
 #include "logger.h"
 
-#include "translator.h"
-
 #include <QByteArray>
 #include <QElapsedTimer>
 #include <QMutex>
@@ -227,55 +225,5 @@ LogWriter Logger::qbsLog(LoggerLevel level, bool force) const
     return LogWriter(m_logSink, level, force);
 }
 
-
-class TimedActivityLogger::TimedActivityLoggerPrivate
-{
-public:
-    Logger logger;
-    QString activity;
-    QElapsedTimer timer;
-};
-
-TimedActivityLogger::TimedActivityLogger(const Logger &logger, const QString &activity,
-        bool enabled)
-    : d(0)
-{
-    if (!enabled)
-        return;
-    d = new TimedActivityLoggerPrivate;
-    d->logger = logger;
-    d->activity = activity;
-    d->logger.qbsLog(LoggerInfo) << Tr::tr("Starting activity '%2'.").arg(activity);
-    d->timer.start();
-}
-
-void TimedActivityLogger::finishActivity()
-{
-    if (!d)
-        return;
-    qint64 ms = d->timer.elapsed();
-    qint64 s = ms/1000;
-    ms -= s*1000;
-    qint64 m = s/60;
-    s -= m*60;
-    const qint64 h = m/60;
-    m -= h*60;
-    QString timeString = QString::fromLocal8Bit("%1ms").arg(ms);
-    if (h || m || s)
-        timeString.prepend(QString::fromLocal8Bit("%1s, ").arg(s));
-    if (h || m)
-        timeString.prepend(QString::fromLocal8Bit("%1m, ").arg(m));
-    if (h)
-        timeString.prepend(QString::fromLocal8Bit("%1h, ").arg(h));
-    d->logger.qbsLog(LoggerInfo) << Tr::tr("Activity '%2' took %3.").arg(d->activity, timeString);
-    delete d;
-    d = 0;
-}
-
-TimedActivityLogger::~TimedActivityLogger()
-{
-    finishActivity();
-}
-
 } // namespace Internal
 } // namespace qbs
diff --git a/src/lib/corelib/logging/logger.h b/src/lib/corelib/logging/logger.h
index e587f8325..ef35198be 100644
--- a/src/lib/corelib/logging/logger.h
+++ b/src/lib/corelib/logging/logger.h
@@ -134,19 +134,6 @@ private:
     bool m_storeWarnings = false;
 };
 
-
-class TimedActivityLogger
-{
-public:
-    TimedActivityLogger(const Logger &logger, const QString &activity, bool enabled);
-    void finishActivity();
-    ~TimedActivityLogger();
-
-private:
-    class TimedActivityLoggerPrivate;
-    TimedActivityLoggerPrivate *d;
-};
-
 } // namespace Internal
 } // namespace qbs
 
diff --git a/src/lib/corelib/tools/profiling.cpp b/src/lib/corelib/tools/profiling.cpp
new file mode 100644
index 000000000..ede35e2fa
--- /dev/null
+++ b/src/lib/corelib/tools/profiling.cpp
@@ -0,0 +1,126 @@
+/****************************************************************************
+**
+** Copyright (C) 2016 The Qt Company Ltd.
+** Contact: https://www.qt.io/licensing/
+**
+** This file is part of Qbs.
+**
+** $QT_BEGIN_LICENSE:LGPL$
+** Commercial License Usage
+** Licensees holding valid commercial Qt licenses may use this file in
+** accordance with the commercial license agreement provided with the
+** Software or, alternatively, in accordance with the terms contained in
+** a written agreement between you and The Qt Company. For licensing terms
+** and conditions see https://www.qt.io/terms-conditions. For further
+** information use the contact form at https://www.qt.io/contact-us.
+**
+** GNU Lesser General Public License Usage
+** Alternatively, this file may be used under the terms of the GNU Lesser
+** General Public License version 3 as published by the Free Software
+** Foundation and appearing in the file LICENSE.LGPL3 included in the
+** packaging of this file. Please review the following information to
+** ensure the GNU Lesser General Public License version 3 requirements
+** will be met: https://www.gnu.org/licenses/lgpl-3.0.html.
+**
+** GNU General Public License Usage
+** Alternatively, this file may be used under the terms of the GNU
+** General Public License version 2.0 or (at your option) the GNU General
+** Public license version 3 or any later version approved by the KDE Free
+** Qt Foundation. The licenses are as published by the Free Software
+** Foundation and appearing in the file LICENSE.GPL2 and LICENSE.GPL3
+** included in the packaging of this file. Please review the following
+** information to ensure the GNU General Public License requirements will
+** be met: https://www.gnu.org/licenses/gpl-2.0.html and
+** https://www.gnu.org/licenses/gpl-3.0.html.
+**
+** $QT_END_LICENSE$
+**
+****************************************************************************/
+
+#include "profiling.h"
+
+#include <logging/logger.h>
+#include <logging/translator.h>
+
+#include <QString>
+
+namespace qbs {
+namespace Internal {
+
+class TimedActivityLogger::TimedActivityLoggerPrivate
+{
+public:
+    Logger logger;
+    QString activity;
+    QElapsedTimer timer;
+};
+
+TimedActivityLogger::TimedActivityLogger(const Logger &logger, const QString &activity,
+        bool enabled)
+    : d(0)
+{
+    if (!enabled)
+        return;
+    d = new TimedActivityLoggerPrivate;
+    d->logger = logger;
+    d->activity = activity;
+    d->logger.qbsLog(LoggerInfo, true) << Tr::tr("Starting activity '%2'.").arg(activity);
+    d->timer.start();
+}
+
+void TimedActivityLogger::finishActivity()
+{
+    if (!d)
+        return;
+    const QString timeString = elapsedTimeString(d->timer.elapsed());
+    d->logger.qbsLog(LoggerInfo, true)
+            << Tr::tr("Activity '%2' took %3.").arg(d->activity, timeString);
+    delete d;
+    d = 0;
+}
+
+TimedActivityLogger::~TimedActivityLogger()
+{
+    finishActivity();
+}
+
+AccumulatingTimer::AccumulatingTimer(qint64 *elapsedTime) : m_elapsedTime(elapsedTime)
+{
+    if (elapsedTime)
+        m_timer.start();
+}
+
+AccumulatingTimer::~AccumulatingTimer()
+{
+    stop();
+}
+
+void AccumulatingTimer::stop()
+{
+    if (!m_timer.isValid())
+        return;
+    *m_elapsedTime += m_timer.elapsed();
+    m_timer.invalidate();
+}
+
+QString elapsedTimeString(qint64 elapsedTimeInMs)
+{
+    qint64 ms = elapsedTimeInMs;
+    qint64 s = ms/1000;
+    ms -= s*1000;
+    qint64 m = s/60;
+    s -= m*60;
+    const qint64 h = m/60;
+    m -= h*60;
+    QString timeString = QString::fromLocal8Bit("%1ms").arg(ms);
+    if (h || m || s)
+        timeString.prepend(QString::fromLocal8Bit("%1s, ").arg(s));
+    if (h || m)
+        timeString.prepend(QString::fromLocal8Bit("%1m, ").arg(m));
+    if (h)
+        timeString.prepend(QString::fromLocal8Bit("%1h, ").arg(h));
+    return timeString;
+}
+
+} // namespace Internal
+} // namespace qbs
diff --git a/src/lib/corelib/tools/profiling.h b/src/lib/corelib/tools/profiling.h
new file mode 100644
index 000000000..f532eac2a
--- /dev/null
+++ b/src/lib/corelib/tools/profiling.h
@@ -0,0 +1,82 @@
+/****************************************************************************
+**
+** Copyright (C) 2016 The Qt Company Ltd.
+** Contact: https://www.qt.io/licensing/
+**
+** This file is part of Qbs.
+**
+** $QT_BEGIN_LICENSE:LGPL$
+** Commercial License Usage
+** Licensees holding valid commercial Qt licenses may use this file in
+** accordance with the commercial license agreement provided with the
+** Software or, alternatively, in accordance with the terms contained in
+** a written agreement between you and The Qt Company. For licensing terms
+** and conditions see https://www.qt.io/terms-conditions. For further
+** information use the contact form at https://www.qt.io/contact-us.
+**
+** GNU Lesser General Public License Usage
+** Alternatively, this file may be used under the terms of the GNU Lesser
+** General Public License version 3 as published by the Free Software
+** Foundation and appearing in the file LICENSE.LGPL3 included in the
+** packaging of this file. Please review the following information to
+** ensure the GNU Lesser General Public License version 3 requirements
+** will be met: https://www.gnu.org/licenses/lgpl-3.0.html.
+**
+** GNU General Public License Usage
+** Alternatively, this file may be used under the terms of the GNU
+** General Public License version 2.0 or (at your option) the GNU General
+** Public license version 3 or any later version approved by the KDE Free
+** Qt Foundation. The licenses are as published by the Free Software
+** Foundation and appearing in the file LICENSE.GPL2 and LICENSE.GPL3
+** included in the packaging of this file. Please review the following
+** information to ensure the GNU General Public License requirements will
+** be met: https://www.gnu.org/licenses/gpl-2.0.html and
+** https://www.gnu.org/licenses/gpl-3.0.html.
+**
+** $QT_END_LICENSE$
+**
+****************************************************************************/
+
+#ifndef QBS_PROFILING_H
+#define QBS_PROFILING_H
+
+#include <QElapsedTimer>
+
+QT_BEGIN_NAMESPACE
+class QString;
+QT_END_NAMESPACE
+
+namespace qbs {
+namespace Internal {
+class Logger;
+
+QString elapsedTimeString(qint64 elapsedTimeInMs);
+
+class TimedActivityLogger
+{
+public:
+    TimedActivityLogger(const Logger &logger, const QString &activity, bool enabled);
+    void finishActivity();
+    ~TimedActivityLogger();
+
+private:
+    class TimedActivityLoggerPrivate;
+    TimedActivityLoggerPrivate *d;
+};
+
+class AccumulatingTimer
+{
+public:
+    AccumulatingTimer(qint64 *elapsedTime);
+    ~AccumulatingTimer();
+    void stop();
+
+private:
+    QElapsedTimer m_timer;
+    qint64 * const m_elapsedTime;
+};
+
+} // namespace Internal
+} // namespace qbs
+
+#endif // Header guard
diff --git a/src/lib/corelib/tools/tools.pri b/src/lib/corelib/tools/tools.pri
index 7bcf60516..344f9924e 100644
--- a/src/lib/corelib/tools/tools.pri
+++ b/src/lib/corelib/tools/tools.pri
@@ -24,6 +24,7 @@ HEADERS += \
     $$PWD/pathutils.h \
     $$PWD/preferences.h \
     $$PWD/profile.h \
+    $$PWD/profiling.h \
     $$PWD/processresult.h \
     $$PWD/processresult_p.h \
     $$PWD/processutils.h \
@@ -69,6 +70,7 @@ SOURCES += \
     $$PWD/processresult.cpp \
     $$PWD/processutils.cpp \
     $$PWD/profile.cpp \
+    $$PWD/profiling.cpp \
     $$PWD/progressobserver.cpp \
     $$PWD/projectgeneratormanager.cpp \
     $$PWD/propertyfinder.cpp \