Improve the TimedActivityLogger

- Get rid of the debug level parameter. Either we want to log the
  elapsed time or we don't. Enabling timing in verbose mode only
  is dubious anyway, as the debug output can influence the result.
- Log the time in more sensible places.

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

7 files changed, 16 insertions, 23 deletions

diff --git a/src/lib/corelib/api/internaljobs.cpp b/src/lib/corelib/api/internaljobs.cpp
index 21a2ee5df..8b0f5a5c7 100644
--- a/src/lib/corelib/api/internaljobs.cpp
+++ b/src/lib/corelib/api/internaljobs.cpp
@@ -77,8 +77,8 @@ private:
     void initialize(const QString &task, int maximum)
     {
         QBS_ASSERT(!m_timedLogger, delete m_timedLogger);
-        m_timedLogger = new TimedActivityLogger(m_job->logger(), task, QString(),
-                m_job->timed() ? LoggerInfo : LoggerDebug, m_job->timed());
+        if (m_job->timed())
+            m_timedLogger = new TimedActivityLogger(m_job->logger(), task, true);
         m_value = 0;
         m_maximum = maximum;
         m_canceled = false;
@@ -313,7 +313,7 @@ void InternalSetupProjectJob::resolveProjectFromScratch(ScriptEngine *engine)
 
 void InternalSetupProjectJob::resolveBuildDataFromScratch(const RulesEvaluationContextPtr &evalContext)
 {
-    TimedActivityLogger resolveLogger(logger(), QLatin1String("Resolving build project"));
+    TimedActivityLogger resolveLogger(logger(), QLatin1String("Resolving build project"), timed());
     BuildDataResolver(logger()).resolveBuildData(m_newProject, evalContext);
 }
 
diff --git a/src/lib/corelib/buildgraph/buildgraphloader.cpp b/src/lib/corelib/buildgraph/buildgraphloader.cpp
index 067460865..5a4c3d226 100644
--- a/src/lib/corelib/buildgraph/buildgraphloader.cpp
+++ b/src/lib/corelib/buildgraph/buildgraphloader.cpp
@@ -210,6 +210,8 @@ static void makeChangedProductsListComplete(QList<ResolvedProductPtr> &changedPr
 
 void BuildGraphLoader::trackProjectChanges()
 {
+    TimedActivityLogger trackingTimer(m_logger, Tr::tr("Change tracking"),
+                                      m_parameters.logElapsedTime());
     const TopLevelProjectPtr &restoredProject = m_result.loadedProject;
     QSet<QString> buildSystemFiles = restoredProject->buildSystemFiles;
     QList<ResolvedProductPtr> allRestoredProducts = restoredProject->allProducts();
diff --git a/src/lib/corelib/buildgraph/cycledetector.cpp b/src/lib/corelib/buildgraph/cycledetector.cpp
index 4fb01e9c4..9ef1daabe 100644
--- a/src/lib/corelib/buildgraph/cycledetector.cpp
+++ b/src/lib/corelib/buildgraph/cycledetector.cpp
@@ -57,10 +57,6 @@ CycleDetector::CycleDetector(const Logger &logger)
 
 void CycleDetector::visitProject(const TopLevelProjectConstPtr &project)
 {
-    const QString description = QString::fromLocal8Bit("Cycle detection for project '%1'")
-            .arg(project->name);
-    TimedActivityLogger timeLogger(m_logger, description, QLatin1String("[BG] "), LoggerTrace);
-
     project->accept(this);
 }
 
diff --git a/src/lib/corelib/language/moduleloader.cpp b/src/lib/corelib/language/moduleloader.cpp
index b821859ec..e29314002 100644
--- a/src/lib/corelib/language/moduleloader.cpp
+++ b/src/lib/corelib/language/moduleloader.cpp
@@ -222,6 +222,8 @@ void ModuleLoader::setOldProbes(const QHash<QString, QList<ProbeConstPtr>> &oldP
 
 ModuleLoaderResult ModuleLoader::load(const SetupProjectParameters &parameters)
 {
+    TimedActivityLogger moduleLoaderTimer(m_logger, Tr::tr("ModuleLoader"),
+                                          parameters.logElapsedTime());
     if (m_logger.traceEnabled())
         m_logger.qbsTrace() << "[MODLDR] load" << parameters.projectFilePath();
     m_parameters = parameters;
diff --git a/src/lib/corelib/language/projectresolver.cpp b/src/lib/corelib/language/projectresolver.cpp
index 2a648a70b..9913dd863 100644
--- a/src/lib/corelib/language/projectresolver.cpp
+++ b/src/lib/corelib/language/projectresolver.cpp
@@ -144,6 +144,8 @@ static void checkForDuplicateProductNames(const TopLevelProjectConstPtr &project
 
 TopLevelProjectPtr ProjectResolver::resolve()
 {
+    TimedActivityLogger projectResolverTimer(m_logger, Tr::tr("ProjectResolver"),
+                                             m_setupParams.logElapsedTime());
     if (m_logger.traceEnabled())
         m_logger.qbsTrace() << "[PR] resolving " << m_loadResult.root->file()->filePath();
 
diff --git a/src/lib/corelib/logging/logger.cpp b/src/lib/corelib/logging/logger.cpp
index 866ad8b00..9a7811fb5 100644
--- a/src/lib/corelib/logging/logger.cpp
+++ b/src/lib/corelib/logging/logger.cpp
@@ -43,6 +43,8 @@
 
 #include "logger.h"
 
+#include "translator.h"
+
 #include <QByteArray>
 #include <QElapsedTimer>
 #include <QMutex>
@@ -230,27 +232,20 @@ class TimedActivityLogger::TimedActivityLoggerPrivate
 {
 public:
     Logger logger;
-    QString prefix;
     QString activity;
-    LoggerLevel logLevel;
     QElapsedTimer timer;
-    bool alwaysLog;
 };
 
 TimedActivityLogger::TimedActivityLogger(const Logger &logger, const QString &activity,
-        const QString &prefix, LoggerLevel logLevel, bool alwaysLog)
+        bool enabled)
     : d(0)
 {
-    if (!alwaysLog && !logger.logSink()->willPrint(logLevel))
+    if (!enabled)
         return;
     d = new TimedActivityLoggerPrivate;
     d->logger = logger;
-    d->prefix = prefix;
     d->activity = activity;
-    d->logLevel = logLevel;
-    d->alwaysLog = alwaysLog;
-    d->logger.qbsLog(logLevel, alwaysLog) << QString::fromLocal8Bit("%1Starting activity '%2'.")
-            .arg(prefix, activity);
+    d->logger.qbsLog(LoggerInfo) << Tr::tr("Starting activity '%2'.").arg(activity);
     d->timer.start();
 }
 
@@ -272,9 +267,7 @@ void TimedActivityLogger::finishActivity()
         timeString.prepend(QString::fromLocal8Bit("%1m, ").arg(m));
     if (h)
         timeString.prepend(QString::fromLocal8Bit("%1h, ").arg(h));
-    d->logger.qbsLog(d->logLevel, d->alwaysLog)
-            << QString::fromLocal8Bit("%1Activity '%2' took %3.")
-               .arg(d->prefix, d->activity, timeString);
+    d->logger.qbsLog(LoggerInfo) << Tr::tr("Activity '%2' took %3.").arg(d->activity, timeString);
     delete d;
     d = 0;
 }
diff --git a/src/lib/corelib/logging/logger.h b/src/lib/corelib/logging/logger.h
index 2e3edc880..e587f8325 100644
--- a/src/lib/corelib/logging/logger.h
+++ b/src/lib/corelib/logging/logger.h
@@ -138,9 +138,7 @@ private:
 class TimedActivityLogger
 {
 public:
-    TimedActivityLogger(const Logger &logger, const QString &activity,
-                        const QString &prefix = QString(), LoggerLevel logLevel = LoggerDebug,
-                        bool alwaysLog = false);
+    TimedActivityLogger(const Logger &logger, const QString &activity, bool enabled);
     void finishActivity();
     ~TimedActivityLogger();