Testlib: Output function / total time along with crash dump.

Previously, only QXmlTestLogger had timers to take elapsed times
and log them. Move those into class QTestLog for access by
the loggers and output the times in the crash dump to make it
easier to spot hangs/recursion crashes.

Produces:

QFATAL : foo() Received signal 11
         Function time: 22ms Total time: 23ms

A crash occurred in ...
Function time: 24ms Total time: 26ms

Task-number: QTBUG-47370
Change-Id: Ia530a63104087daffc9a15f68c15d93378b9407e
Reviewed-by: Simon Hausmann <simon.hausmann@theqtcompany.com>

src/testlib/qtestcase.cpp

@@ -2597,9 +2597,13 @@ private:
 
 void FatalSignalHandler::signal(int signum)
 {
+    const int msecsFunctionTime = qRound(QTestLog::msecsFunctionTime());
+    const int msecsTotalTime = qRound(QTestLog::msecsTotalTime());
     if (signum != SIGINT)
         stackTrace();
-    qFatal("Received signal %d", signum);
+    qFatal("Received signal %d\n"
+           "         Function time: %dms Total time: %dms",
+           signum, msecsFunctionTime, msecsTotalTime);
 #if defined(Q_OS_INTEGRITY)
     {
         struct sigaction act;
@@ -2794,12 +2798,15 @@ static LONG WINAPI windowsFaultHandler(struct _EXCEPTION_POINTERS *exInfo)
     char appName[MAX_PATH];
     if (!GetModuleFileNameA(NULL, appName, MAX_PATH))
         appName[0] = 0;
-
+    const int msecsFunctionTime = qRound(QTestLog::msecsFunctionTime());
+    const int msecsTotalTime = qRound(QTestLog::msecsTotalTime());
     const void *exceptionAddress = exInfo->ExceptionRecord->ExceptionAddress;
-    printf("A crash occurred in %s.\n\n"
+    printf("A crash occurred in %s.\n"
+           "Function time: %dms Total time: %dms\n\n"
            "Exception address: 0x%p\n"
            "Exception code   : 0x%lx\n",
-           appName, exceptionAddress, exInfo->ExceptionRecord->ExceptionCode);
+           appName, msecsFunctionTime, msecsTotalTime,
+           exceptionAddress, exInfo->ExceptionRecord->ExceptionCode);
 
     DebugSymbolResolver resolver(GetCurrentProcess());
     if (resolver.isValid()) {

src/testlib/qtestlog.cpp

@@ -46,6 +46,7 @@
 
 #include <QtCore/qatomic.h>
 #include <QtCore/qbytearray.h>
+#include <QtCore/QElapsedTimer>
 #include <QtCore/QVariant>
 #include <QtCore/QRegularExpression>
 
@@ -75,6 +76,9 @@ static void saveCoverageTool(const char * appname, bool testfailed, bool install
 #endif
 }
 
+static QElapsedTimer elapsedFunctionTime;
+static QElapsedTimer elapsedTotalTime;
+
 namespace QTest {
 
     int fails = 0;
@@ -325,6 +329,7 @@ namespace QTest {
 
 void QTestLog::enterTestFunction(const char* function)
 {
+    elapsedFunctionTime.restart();
     if (printAvailableTags)
         return;
 
@@ -450,6 +455,8 @@ void QTestLog::addBenchmarkResult(const QBenchmarkResult &result)
 
 void QTestLog::startLogging()
 {
+    elapsedTotalTime.start();
+    elapsedFunctionTime.start();
     QTest::TestLoggers::startLogging();
     QTest::oldMessageHandler = qInstallMessageHandler(QTest::messageHandler);
 }
@@ -597,4 +604,14 @@ bool QTestLog::installedTestCoverage()
     return QTest::installedTestCoverage;
 }
 
+qint64 QTestLog::nsecsTotalTime()
+{
+    return elapsedTotalTime.nsecsElapsed();
+}
+
+qint64 QTestLog::nsecsFunctionTime()
+{
+    return elapsedFunctionTime.nsecsElapsed();
+}
+
 QT_END_NAMESPACE

src/testlib/qtestlog_p.h

@@ -110,6 +110,11 @@ public:
     static void setInstalledTestCoverage(bool installed);
     static bool installedTestCoverage();
 
+    static qint64 nsecsTotalTime();
+    static qreal msecsTotalTime()    { return QTestLog::nsecsTotalTime() / 1000000.; }
+    static qint64 nsecsFunctionTime();
+    static qreal msecsFunctionTime() { return QTestLog::nsecsFunctionTime() / 1000000.; }
+
 private:
     QTestLog();
     ~QTestLog();

src/testlib/qxmltestlogger.cpp

@@ -36,6 +36,7 @@
 #include <QtCore/qglobal.h>
 #include <QtCore/qlibraryinfo.h>
 
+#include <QtTest/private/qtestlog_p.h>
 #include <QtTest/private/qxmltestlogger_p.h>
 #include <QtTest/private/qtestresult_p.h>
 #include <QtTest/private/qbenchmark_p.h>
@@ -124,15 +125,13 @@ void QXmlTestLogger::startLogging()
                 "    <QTestVersion>" QTEST_VERSION_STR "</QTestVersion>\n"
                 "</Environment>\n", qVersion(), quotedBuild.constData());
     outputString(buf.constData());
-    m_totalTime.start();
 }
 
 void QXmlTestLogger::stopLogging()
 {
     QTestCharBuffer buf;
     QTest::qt_asprintf(&buf,
-                "<Duration msecs=\"%f\"/>\n",
-        m_totalTime.nsecsElapsed() / 1000000.);
+                "<Duration msecs=\"%f\"/>\n", QTestLog::msecsTotalTime());
     outputString(buf.constData());
     if (xmlmode == QXmlTestLogger::Complete) {
         outputString("</TestCase>\n");
@@ -148,8 +147,6 @@ void QXmlTestLogger::enterTestFunction(const char *function)
     xmlQuote(&quotedFunction, function);
     QTest::qt_asprintf(&buf, "<TestFunction name=\"%s\">\n", quotedFunction.constData());
     outputString(buf.constData());
-
-    m_functionTime.start();
 }
 
 void QXmlTestLogger::leaveTestFunction()
@@ -158,7 +155,7 @@ void QXmlTestLogger::leaveTestFunction()
     QTest::qt_asprintf(&buf,
                 "    <Duration msecs=\"%f\"/>\n"
                 "</TestFunction>\n",
-        m_functionTime.nsecsElapsed() / 1000000.);
+        QTestLog::msecsFunctionTime());
 
     outputString(buf.constData());
 }

src/testlib/qxmltestlogger_p.h

@@ -47,7 +47,6 @@
 
 
 #include <QtTest/private/qabstracttestlogger_p.h>
-#include <QtCore/qelapsedtimer.h>
 
 QT_BEGIN_NAMESPACE
 
@@ -79,8 +78,6 @@ public:
 
 private:
     XmlMode xmlmode;
-    QElapsedTimer m_functionTime;
-    QElapsedTimer m_totalTime;
 };
 
 QT_END_NAMESPACE

tests/auto/testlib/selftests/expected_crashes_3.txt

@@ -2,6 +2,7 @@
 Config: Using QtTest library @INSERT_QT_VERSION_HERE@, Qt @INSERT_QT_VERSION_HERE@
 PASS   : tst_Crashes::initTestCase()
 QFATAL : tst_Crashes::crash() Received signal 11
+         Function time: ms Total time: ms
 FAIL!  : tst_Crashes::crash() Received a fatal error.
    Loc: [Unknown file(0)]
 Totals: 1 passed, 1 failed, 0 skipped, 0 blacklisted

tests/auto/testlib/selftests/tst_selftests.cpp

@@ -626,13 +626,28 @@ void tst_Selftests::doRunSubTest(QString const& subdir, QStringList const& logge
 
     for (int n = 0; n < loggers.count(); ++n) {
         QString logger = loggers[n];
-#if defined(Q_OS_WIN)
-        if (n == 0 && subdir == QLatin1String("crashes")) { // Remove stack trace which is output to stdout.
-            const int exceptionLogStart = actualOutputs.first().indexOf("A crash occurred in ");
+        if (n == 0 && subdir == QLatin1String("crashes")) {
+            QByteArray &actual = actualOutputs[0];
+#ifndef Q_OS_WIN
+             // Remove digits of times to match the expected file.
+            const QLatin1String timePattern("Function time:");
+            int timePos = actual.indexOf(timePattern);
+            if (timePos >= 0) {
+                timePos += timePattern.size();
+                const int nextLinePos = actual.indexOf('\n', timePos);
+                for (int c = (nextLinePos != -1 ? nextLinePos : actual.size()) - 1; c >= timePos; --c) {
+                    if (actual.at(c) >= '0' && actual.at(c) <= '9')
+                        actual.remove(c, 1);
+                }
+            }
+#else // !Q_OS_WIN
+            // Remove stack trace which is output to stdout.
+            const int exceptionLogStart = actual.indexOf("A crash occurred in ");
             if (exceptionLogStart >= 0)
-                actualOutputs[0].truncate(exceptionLogStart);
-        }
+                actual.truncate(exceptionLogStart);
 #endif // Q_OS_WIN
+        }
+
         QList<QByteArray> res = splitLines(actualOutputs[n]);
         const QString expectedFileName = expectedFileNameFromTest(subdir, logger);
         QList<QByteArray> exp = expectedResult(expectedFileName);