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>

5 files changed, 36 insertions, 13 deletions

diff --git a/src/testlib/qtestcase.cpp b/src/testlib/qtestcase.cpp
index 000470e9e5..0847d639fd 100644
--- a/src/testlib/qtestcase.cpp
+++ b/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()) {
diff --git a/src/testlib/qtestlog.cpp b/src/testlib/qtestlog.cpp
index 59aeb27ffe..3513e10eec 100644
--- a/src/testlib/qtestlog.cpp
+++ b/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
diff --git a/src/testlib/qtestlog_p.h b/src/testlib/qtestlog_p.h
index b4786b4904..b7e9d16ec3 100644
--- a/src/testlib/qtestlog_p.h
+++ b/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();
diff --git a/src/testlib/qxmltestlogger.cpp b/src/testlib/qxmltestlogger.cpp
index bf607b4702..f96b5647e4 100644
--- a/src/testlib/qxmltestlogger.cpp
+++ b/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());
 }
diff --git a/src/testlib/qxmltestlogger_p.h b/src/testlib/qxmltestlogger_p.h
index 5cf8b4596c..49a21d9ca1 100644
--- a/src/testlib/qxmltestlogger_p.h
+++ b/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