Utils: Introduce QTC_STATIC_SCOPED_TIMER()

This macro, similar to QTC_SCOPED_TIMER(), measures
the time spent in a block of code. In addition, the
time spent in a block is saved in a static variable.

This macro enables measuring a cumulative time
spent inside a certain block of code for all invocations.
When a long freeze is being tracked, and QTC_SCOPED_TIMER()
indicates that the most of the freeze is spent inside a loop
with a big amount of iterations, placing
QTC_STATIC_SCOPED_TIMER() inside the loop may detect
the part of the loop that composes in total for the
longest freeze.

In contrary to the QTC_SCOPED_TIMER(), this macro
it doesn't print the message when it's entered.
It prints the output at first hit, and later,
as not to clog the debug output, only at 10ms resolution.

Change-Id: I3360a3ab9147d544f90ce914fb78359f7179c767
Reviewed-by: hjk <hjk@qt.io>
Reviewed-by: Qt CI Bot <qt_ci_bot@qt-project.org>

src/libs/utils/CMakeLists.txt

@@ -147,6 +147,7 @@ add_qtc_library(Utils
     runextensions.cpp runextensions.h
     savefile.cpp savefile.h
     scopedswap.h
+    scopedtimer.cpp scopedtimer.h
     searchresultitem.cpp searchresultitem.h
     set_algorithm.h
     settingsaccessor.cpp settingsaccessor.h

src/libs/utils/qtcassert.cpp

@@ -8,8 +8,6 @@
 #include <QMutex>
 #include <QTime>
 
-#include <chrono>
-
 #if defined(Q_OS_UNIX)
 #include <stdio.h>
 #include <signal.h>
@@ -132,30 +130,4 @@ void writeAssertLocation(const char *msg)
         dumpBacktrace(maxdepth);
 }
 
-using namespace std::chrono;
-
-class ScopedTimerPrivate
-{
-public:
-    const char *m_fileName = nullptr;
-    const int m_line = 0;
-    const time_point<system_clock, nanoseconds> m_start = system_clock::now();
-};
-
-ScopedTimer::ScopedTimer(const char *fileName, int line)
-    : d(new ScopedTimerPrivate{fileName, line})
-{
-    const QByteArray time = QTime::currentTime().toString(Qt::ISODateWithMs).toLatin1();
-    qDebug("SCOPED TIMER [%s] in %s:%d started", time.data(), d->m_fileName, d->m_line);
-}
-
-ScopedTimer::~ScopedTimer()
-{
-    const auto end = system_clock::now();
-    const auto elapsed = duration_cast<milliseconds>(end - d->m_start);
-    const QByteArray time = QTime::currentTime().toString(Qt::ISODateWithMs).toLatin1();
-    qDebug("SCOPED TIMER [%s] in %s:%d stopped with timeout: %ldms",
-           time.data(), d->m_fileName, d->m_line, elapsed.count());
-}
-
 } // namespace Utils

src/libs/utils/qtcassert.h

@@ -5,25 +5,9 @@
 
 #include "utils_global.h"
 
-#include <memory>
-
 namespace Utils {
-
 QTCREATOR_UTILS_EXPORT void writeAssertLocation(const char *msg);
 QTCREATOR_UTILS_EXPORT void dumpBacktrace(int maxdepth);
-
-class ScopedTimerPrivate;
-
-class QTCREATOR_UTILS_EXPORT ScopedTimer
-{
-public:
-    ScopedTimer(const char *fileName, int line);
-    ~ScopedTimer();
-
-private:
-    std::unique_ptr<ScopedTimerPrivate> d;
-};
-
 } // Utils
 
 #define QTC_ASSERT_STRINGIFY_HELPER(x) #x
@@ -37,7 +21,3 @@ private:
 #define QTC_ASSERT(cond, action) if (Q_LIKELY(cond)) {} else { QTC_ASSERT_STRING(#cond); action; } do {} while (0)
 #define QTC_CHECK(cond) if (Q_LIKELY(cond)) {} else { QTC_ASSERT_STRING(#cond); } do {} while (0)
 #define QTC_GUARD(cond) ((Q_LIKELY(cond)) ? true : (QTC_ASSERT_STRING(#cond), false))
-
-#define QTC_CONCAT_HELPER(x, y) x ## y
-#define QTC_CONCAT(x, y) QTC_CONCAT_HELPER(x, y)
-#define QTC_SCOPED_TIMER() ::Utils::ScopedTimer QTC_CONCAT(_qtc_scoped_timer_, __LINE__)(__FILE__, __LINE__)

src/libs/utils/scopedtimer.cpp

@@ -0,0 +1,64 @@
+// Copyright (C) 2023 The Qt Company Ltd.
+// SPDX-License-Identifier: LicenseRef-Qt-Commercial OR GPL-3.0-only WITH Qt-GPL-exception-1.0
+
+#include "scopedtimer.h"
+
+#include <QByteArray>
+#include <QDebug>
+#include <QTime>
+
+#include <chrono>
+
+namespace Utils {
+
+static QString currentTime() { return QTime::currentTime().toString(Qt::ISODateWithMs); }
+
+using namespace std::chrono;
+
+class ScopedTimerPrivate
+{
+public:
+    const char *m_fileName = nullptr;
+    const int m_line = 0;
+    std::atomic<int64_t> *m_cumulative = nullptr;
+    const time_point<system_clock, nanoseconds> m_start = system_clock::now();
+};
+
+static const char s_scoped[] = "SCOPED TIMER";
+static const char s_scopedCumulative[] = "STATIC SCOPED TIMER";
+
+ScopedTimer::ScopedTimer(const char *fileName, int line, std::atomic<int64_t> *cumulative)
+    : d(new ScopedTimerPrivate{fileName, line, cumulative})
+{
+    if (d->m_cumulative)
+        return;
+    qDebug().noquote().nospace() << s_scoped << " [" << currentTime() << "] in " << d->m_fileName
+                                 << ':' << d->m_line << " started";
+}
+
+static int64_t toMs(int64_t ns) { return ns / 1000000; }
+
+ScopedTimer::~ScopedTimer()
+{
+    const auto elapsed = duration_cast<nanoseconds>(system_clock::now() - d->m_start);
+    QString suffix;
+    if (d->m_cumulative) {
+        const int64_t nsOld = d->m_cumulative->fetch_add(elapsed.count());
+        const int64_t msOld = toMs(nsOld);
+        const int64_t nsNew = nsOld + elapsed.count();
+        const int64_t msNew = toMs(nsNew);
+        // Always report the first hit, and later, as not to clog the debug output,
+        // only at 10ms resolution.
+        if (nsOld != 0 && msOld / 10 == msNew / 10)
+            return;
+
+        suffix = " cumulative timeout: " + QString::number(msNew) + "ms";
+    } else {
+        suffix = " stopped with timeout: " + QString::number(toMs(elapsed.count())) + "ms";
+    }
+    const char *header = d->m_cumulative ? s_scopedCumulative : s_scoped;
+    qDebug().noquote().nospace() << header << " [" << currentTime() << "] in " << d->m_fileName
+                                 << ':' << d->m_line << suffix;
+}
+
+} // namespace Utils

src/libs/utils/scopedtimer.h

@@ -0,0 +1,38 @@
+// Copyright (C) 2023 The Qt Company Ltd.
+// SPDX-License-Identifier: LicenseRef-Qt-Commercial OR GPL-3.0-only WITH Qt-GPL-exception-1.0
+
+#pragma once
+
+#include "utils_global.h"
+
+#include <atomic>
+#include <memory>
+
+namespace Utils {
+
+class ScopedTimerPrivate;
+
+class QTCREATOR_UTILS_EXPORT ScopedTimer
+{
+public:
+    ScopedTimer(const char *fileName, int line, std::atomic<int64_t> *cumulative = nullptr);
+    ~ScopedTimer();
+
+private:
+    std::unique_ptr<ScopedTimerPrivate> d;
+};
+
+} // Utils
+
+#define QTC_CONCAT_HELPER(x, y) x ## y
+#define QTC_CONCAT(x, y) QTC_CONCAT_HELPER(x, y)
+#define QTC_SCOPED_TIMER() ::Utils::ScopedTimer QTC_CONCAT(_qtc_scoped_timer_, __LINE__)\
+(__FILE__, __LINE__)
+
+// The macro below expands as follows (in one line):
+// static std::atomic<int64_t> _qtc_static_scoped_timer___LINE__ = 0;
+// ScopedTimer _qtc_scoped_timer___LINE__(__FILE__, __LINE__, &_qtc_static_scoped_timer___LINE__)
+#define QTC_STATIC_SCOPED_TIMER() static std::atomic<int64_t> \
+QTC_CONCAT(_qtc_static_scoped_timer_, __LINE__) = 0; \
+::Utils::ScopedTimer QTC_CONCAT(_qtc_scoped_timer_, __LINE__)\
+(__FILE__, __LINE__, &QTC_CONCAT(_qtc_static_scoped_timer_, __LINE__))

src/libs/utils/utils.qbs

@@ -275,6 +275,8 @@ Project {
             "savefile.cpp",
             "savefile.h",
             "scopedswap.h",
+            "scopedtimer.cpp",
+            "scopedtimer.h",
             "searchresultitem.cpp",
             "searchresultitem.h",
             "set_algorithm.h",