From 9b6cd2764a1516f3f6a13f9c3379603fe0d563a7 Mon Sep 17 00:00:00 2001 From: Friedemann Kleint Date: Fri, 25 Sep 2015 15:55:31 +0200 Subject: 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 --- src/testlib/qtestcase.cpp | 15 +++++++++---- src/testlib/qtestlog.cpp | 17 +++++++++++++++ src/testlib/qtestlog_p.h | 5 +++++ src/testlib/qxmltestlogger.cpp | 9 +++----- src/testlib/qxmltestlogger_p.h | 3 --- .../auto/testlib/selftests/expected_crashes_3.txt | 1 + tests/auto/testlib/selftests/tst_selftests.cpp | 25 +++++++++++++++++----- 7 files changed, 57 insertions(+), 18 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 #include +#include #include #include @@ -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 #include +#include #include #include #include @@ -124,15 +125,13 @@ void QXmlTestLogger::startLogging() " " QTEST_VERSION_STR "\n" "\n", qVersion(), quotedBuild.constData()); outputString(buf.constData()); - m_totalTime.start(); } void QXmlTestLogger::stopLogging() { QTestCharBuffer buf; QTest::qt_asprintf(&buf, - "\n", - m_totalTime.nsecsElapsed() / 1000000.); + "\n", QTestLog::msecsTotalTime()); outputString(buf.constData()); if (xmlmode == QXmlTestLogger::Complete) { outputString("\n"); @@ -148,8 +147,6 @@ void QXmlTestLogger::enterTestFunction(const char *function) xmlQuote("edFunction, function); QTest::qt_asprintf(&buf, "\n", quotedFunction.constData()); outputString(buf.constData()); - - m_functionTime.start(); } void QXmlTestLogger::leaveTestFunction() @@ -158,7 +155,7 @@ void QXmlTestLogger::leaveTestFunction() QTest::qt_asprintf(&buf, " \n" "\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 -#include QT_BEGIN_NAMESPACE @@ -79,8 +78,6 @@ public: private: XmlMode xmlmode; - QElapsedTimer m_functionTime; - QElapsedTimer m_totalTime; }; QT_END_NAMESPACE diff --git a/tests/auto/testlib/selftests/expected_crashes_3.txt b/tests/auto/testlib/selftests/expected_crashes_3.txt index 57c3ddc2ba..0e3f60dd1b 100644 --- a/tests/auto/testlib/selftests/expected_crashes_3.txt +++ b/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 diff --git a/tests/auto/testlib/selftests/tst_selftests.cpp b/tests/auto/testlib/selftests/tst_selftests.cpp index 11de65c3c0..63c48fc809 100644 --- a/tests/auto/testlib/selftests/tst_selftests.cpp +++ b/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 res = splitLines(actualOutputs[n]); const QString expectedFileName = expectedFileNameFromTest(subdir, logger); QList exp = expectedResult(expectedFileName); -- cgit v1.2.3