qplaintestlogger.cpp

Go to the documentation of this file.

// Copyright (C) 2022 The Qt Company Ltd.
// SPDX-License-Identifier: LicenseRef-Qt-Commercial OR LGPL-3.0-only OR GPL-2.0-only OR GPL-3.0-only
 
#include <QtTest/private/qtestresult_p.h>
#include <QtTest/qtestassert.h>
#include <QtTest/private/qtestlog_p.h>
#include <QtTest/private/qplaintestlogger_p.h>
#include <QtTest/private/qbenchmark_p.h>
#include <QtTest/private/qbenchmarkmetric_p.h>
 
#include <QtCore/private/qlogging_p.h>
 
#include <array>
#include <cstdio>
#include <optional>
 
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
 
#include <QtCore/QByteArray>
#include <QtCore/qmath.h>
#include <QtCore/QLibraryInfo>
 
#ifdef Q_OS_ANDROID
#  include <android/log.h>
#endif
 
#ifdef Q_OS_WIN
#  include <qt_windows.h>
#endif
 
#ifdef Q_OS_HARMONY
#  include <QtCore/private/qohoslogger_p.h>
#endif
 
QT_BEGIN_NAMESPACE
 
using namespace Qt::StringLiterals;
 
namespace {
static const char multiplePrefixes[] = "\0kMGTPE"; // kilo, mega, giga, tera, peta, exa
static const char submultiplePrefixes[] = "afpnum"; // atto, femto, pico, nano, micro, milli
 
template <int N> struct FixedBufString
{
    static constexpr size_t MaxSize = N;
    size_t used = 0;
    std::array<char, N + 2> buf;    // for the newline and terminating null
    FixedBufString()
    {
        clear();
    }
    void clear()
    {
        used = 0;
        buf[0] = '\0';
    }
 
    operator const char *() const
    {
        return buf.data();
    }
 
    void append(const char *text)
    {
        size_t len = qMin(strlen(text), MaxSize - used);
        memcpy(buf.data() + used, text, len);
        used += len;
        buf[used] = '\0';
    }
 
    template <typename... Args> void appendf(const char *format, Args... args)
    {
        // vsnprintf includes the terminating null
        used += std::snprintf(buf.data() + used, MaxSize - used + 1, format,
                              args...);
    }
 
    template <int Power = 1000> void appendScaled(qreal value, const char *unit)
    {
        char prefix[2] = {};
        qreal v = qAbs(value);
        qint64 ratio;
        if (v < 1 && Power == 1000) {
            const char *prefixes = submultiplePrefixes;
            ratio = qreal(std::atto::num) / qreal(std::atto::den);
            while (value * ratio > 1000 && *prefixes) {
                ++prefixes;
                ratio *= 1000;
            }
            prefix[0] = *prefixes;
        } else {
            const char *prefixes = multiplePrefixes;
            ratio = 1;
            while (value > 1000 * ratio) {  // yes, even for binary
                ++prefixes;
                ratio *= Power;
            }
            prefix[0] = *prefixes;
        }
 
        // adjust the value by the ratio
        value /= ratio;
        appendf(", %.3g %s%s", value, prefix, unit);
    }
};
} // unnamed namespace
 
namespace QTest {
 
    static const char *ptIncidentType2String(QAbstractTestLogger::IncidentTypes type)
    {
        switch (type) {
        case QAbstractTestLogger::Skip:
            return "SKIP   ";
        case QAbstractTestLogger::Pass:
            return "PASS   ";
        case QAbstractTestLogger::XFail:
            return "XFAIL  ";
        case QAbstractTestLogger::Fail:
            return "FAIL!  ";
        case QAbstractTestLogger::XPass:
            return "XPASS  ";
        case QAbstractTestLogger::BlacklistedPass:
            return "BPASS  ";
        case QAbstractTestLogger::BlacklistedFail:
            return "BFAIL  ";
        case QAbstractTestLogger::BlacklistedXPass:
            return "BXPASS ";
        case QAbstractTestLogger::BlacklistedXFail:
            return "BXFAIL ";
        }
        Q_UNREACHABLE_RETURN(nullptr);
    }
 
    static const char *benchmarkResult2String()
    {
        return "RESULT ";
    }
 
    static const char *ptMessageType2String(QAbstractTestLogger::MessageTypes type)
    {
        switch (type) {
        case QAbstractTestLogger::QDebug:
            return "QDEBUG ";
        case QAbstractTestLogger::QInfo:
            return "QINFO  ";
        case QAbstractTestLogger::QWarning:
            return "QWARN  ";
        case QAbstractTestLogger::QCritical:
            return "QCRITICAL";
        case QAbstractTestLogger::QFatal:
            return "QFATAL ";
        case QAbstractTestLogger::Info:
            return "INFO   ";
        case QAbstractTestLogger::Warn:
            return "WARNING";
        }
        Q_UNREACHABLE_RETURN(nullptr);
    }
 
    template <typename T>
    static int countSignificantDigits(T num)
    {
        if (num <= 0)
            return 0;
 
        int digits = 0;
        qreal divisor = 1;
 
        while (num / divisor >= 1) {
            divisor *= 10;
            ++digits;
        }
 
        return digits;
    }
 
    template <typename T> QByteArray specialValue(T number)
    {
        if (qIsNaN(number) || number < T(0)) // (includes -ve infinity)
            return "NaN";
        if (qIsInf(number))
            return "INF";
        if (number == T(0))
            return "0";
        return {};
    }
 
    // To use the same scale as mean, standard deviation passes a value for scale.
    // Use a multiple of 3 as exponent, with 0.1 <= mantissa < 1000.
    auto formatResult(qreal number, int significantDigits, std::optional<int> scale = {})
    {
        struct R {
            QByteArray text;
            std::optional<int> scale;
        } res = {{}, scale};
 
        if (QByteArray special = specialValue(number); !special.isEmpty()) {
            res.text = special;
            return res;
        }
 
        int decimals = significantDigits;
        qreal mantissa = number;
        int thous = 0;
        if (scale) {
            // Imposed scale (to use same for standard deviation and mean): this
            // may give us a mantissa outside the 0.1-to-100 range. Allow that
            // to give more, but not less, significant digits than asked for.
            Q_ASSERT(*scale % 3 == 0);
            thous = *scale / 3;
            int i = thous;
            for (; i < 0; ++i)
                mantissa *= 1e3;
            for (; i > 0; --i)
                mantissa /= 1e3;
            // When mean's mantissa was < 1, if standard deviation is small
            // (less than .1 at the same scale), allow for its leading zeros:
            for (qreal extra = 1.0; mantissa * extra < 0.1; extra *= 10)
                ++decimals;
        } else {
            // Find the nearest-zeroth power of 1000 for which 0.1 <= number /
            // 1e{3*thous} <= 1000. (This leaves no exponent from 0.1 to
            // 999.49...9, with positive exponents getting 1 <= mantissa < 1000
            // and negative exponents getting 0.1 <= mantissa < 100; a slight
            // asymmetry, to make exponent-free more common.) Iterative, because
            // we expect values at scales between nano and mega, so few
            // iterations are needed. (Theoretical worst case for double would
            // be about 100 iterations; for long double about 1650 - but
            // measurements with precision outside float's dozen-iteration range
            // are unrealistic.)
            while (mantissa >= 1000) {
                mantissa /= 1e3;
                ++thous;
            }
            while (mantissa < 0.1) {
                mantissa *= 1e3;
                --thous;
            }
        }
        res.scale = 3 * thous;
 
        // Format mantissa:
        // 'f' format's precision is the number of digits in the fractional
        // part; we need to correct for earlier significant digits:
        if (mantissa >= 100)
            decimals -= 3;
        else if (mantissa >= 10)
            decimals -= 2;
        else if (mantissa >= 1)
            --decimals;
        // When scale is imposed, that might take decimals < 0 (e.g. if std.dev
        // is bigger than mean), which is ignored, so clip to 0:
        res.text = QByteArray::number(mantissa, 'f', qMax(decimals, 0));
 
        if (thous) {
            // Format exponent and append it:
            QByteArray tail = QByteArray::number(*res.scale);
            if (tail.startsWith('-')) {
                if (tail.size() < 3) // zero-pad after the sign:
                    tail.insert(1, '0');
            } else {
                if (tail.size() < 2) // zero-pad at start:
                    tail.prepend('0');
                tail.prepend('+'); // always include a sign
            }
            tail.prepend('e');
            res.text += tail;
        }
 
        return res;
    }
}
 
/*! \internal
    \class QPlainTestLogger
    \inmodule QtTest
 
    QPlainTestLogger implements basic logging of test results.
 
    The format is Qt-specific and aims to be easy to read.
*/
 
void QPlainTestLogger::outputMessage(const char *str)
{
#if defined(Q_OS_WIN)
    // Log to system log only if output is not redirected and stderr not preferred
    if (stream == stdout && !QtPrivate::shouldLogToStderr()) {
        OutputDebugStringA(str);
        return;
    }
#elif defined(Q_OS_ANDROID)
    __android_log_write(ANDROID_LOG_INFO, "QTestLib", str);
#elif defined(Q_OS_HARMONY)
    qOhosLogMessage(LOG_INFO, "QTestLib", str);
#endif
    outputString(str);
}
 
void QPlainTestLogger::printMessage(MessageSource source, const char *type, const char *msg,
                                    const char *file, int line)
{
    QTEST_ASSERT(type);
    QTEST_ASSERT(msg);
 
    QTestCharBuffer messagePrefix;
 
    QTestCharBuffer messageLocation;
#ifdef Q_OS_WIN
    constexpr const char *INCIDENT_LOCATION_STR = "\n%s(%d) : failure location";
    constexpr const char *OTHER_LOCATION_STR = "\n%s(%d) : message location";
#else
    constexpr const char *INCIDENT_LOCATION_STR = "\n   Loc: [%s(%d)]";
    constexpr const char *OTHER_LOCATION_STR = INCIDENT_LOCATION_STR;
#endif
 
    if (file) {
        switch (source) {
        case MessageSource::Incident:
            QTest::qt_asprintf(&messageLocation, INCIDENT_LOCATION_STR, file, line);
            break;
        case MessageSource::Other:
            QTest::qt_asprintf(&messageLocation, OTHER_LOCATION_STR, file, line);
            break;
        }
    }
 
    const char *msgFiller = msg[0] ? " " : "";
    QTestCharBuffer testIdentifier;
    QTestPrivate::generateTestIdentifier(&testIdentifier);
    QTest::qt_asprintf(&messagePrefix, "%s: %s%s%s%s\n",
                       type, testIdentifier.data(), msgFiller, msg, messageLocation.data());
 
    // In colored mode, printf above stripped our nonprintable control characters.
    // Put them back.
    memcpy(messagePrefix.data(), type, strlen(type));
 
    outputMessage(messagePrefix.data());
}
 
void QPlainTestLogger::printBenchmarkResultsHeader(const QBenchmarkResult &result)
{
    FixedBufString<1022> buf;
    buf.appendf("%s: %s::%s", QTest::benchmarkResult2String(),
                QTestResult::currentTestObjectName(), result.context.slotName.toLatin1().data());
 
    QByteArray tag = QTestResult::currentDataTag();
    QByteArray gtag = QTestResult::currentGlobalDataTag();
 
    if (!gtag.isEmpty() && !tag.isEmpty())
        buf.appendf(":\"%s:%s\":\n", gtag.constData(), tag.constData());
    else if (!gtag.isEmpty())
        buf.appendf(":\"%s\":\n", gtag.constData());
    else if (!tag.isEmpty())
        buf.appendf(":\"%s\":\n", tag.constData());
    else
        buf.append(":\n");
    outputMessage(buf);
}
 
void QPlainTestLogger::printBenchmarkResults(const QList<QBenchmarkResult> &results)
{
    using namespace std::chrono;
    FixedBufString<1022> buf;
    auto findResultFor = [&results](QTest::QBenchmarkMetric metric) -> std::optional<qreal> {
        for (const QBenchmarkResult &result : results) {
            if (result.measurement.metric == metric)
                return result.measurement.value;
        }
        return std::nullopt;
    };
 
    // we need the execution time quite often, so find it first
    qreal executionTime = 0;
    if (auto ns = findResultFor(QTest::WalltimeNanoseconds))
        executionTime = *ns / (1000 * 1000 * 1000);
    else if (auto ms = findResultFor(QTest::WalltimeMilliseconds))
        executionTime = *ms / 1000;
 
    for (const QBenchmarkResult &result : results) {
        buf.clear();
 
        const char * unitText = QTest::benchmarkMetricUnit(result.measurement.metric);
        int significantDigits = QTest::countSignificantDigits(result.measurement.value);
        qreal valuePerIteration = qreal(result.measurement.value) / qreal(result.iterations);
        auto midForm = QTest::formatResult(valuePerIteration, significantDigits);
        buf.appendf("     %s %s%s", midForm.text.constData(), unitText,
                    result.setByMacro ? " per iteration" : "");
 
        switch (result.measurement.metric) {
        case QTest::BitsPerSecond:
            // for bits/s, we'll use powers of 10 (1 Mbit/s = 1000 kbit/s = 1000000 bit/s)
            buf.appendScaled<1000>(result.measurement.value, "bit/s");
            break;
        case QTest::BytesPerSecond:
            // for B/s, we'll use powers of 2 (1 MB/s = 1024 kB/s = 1048576 B/s)
            buf.appendScaled<1024>(result.measurement.value, "B/s");
            break;
 
        case QTest::CPUCycles:
        case QTest::RefCPUCycles:
            if (!qIsNull(executionTime))
                buf.appendScaled(result.measurement.value / executionTime, "Hz");
            break;
 
        case QTest::Instructions:
            if (auto cycles = findResultFor(QTest::CPUCycles)) {
                buf.appendf(", %.3f instr/cycle", result.measurement.value / *cycles);
                break;
            }
            Q_FALLTHROUGH();
 
        case QTest::InstructionReads:
        case QTest::Events:
        case QTest::BytesAllocated:
        case QTest::CPUMigrations:
        case QTest::BusCycles:
        case QTest::StalledCycles:
        case QTest::BranchInstructions:
        case QTest::BranchMisses:
        case QTest::CacheReferences:
        case QTest::CacheReads:
        case QTest::CacheWrites:
        case QTest::CachePrefetches:
        case QTest::CacheMisses:
        case QTest::CacheReadMisses:
        case QTest::CacheWriteMisses:
        case QTest::CachePrefetchMisses:
        case QTest::ContextSwitches:
        case QTest::PageFaults:
        case QTest::MinorPageFaults:
        case QTest::MajorPageFaults:
        case QTest::AlignmentFaults:
        case QTest::EmulationFaults:
            if (!qIsNull(executionTime))
                buf.appendScaled(result.measurement.value / executionTime, "/sec");
            break;
 
        case QTest::FramesPerSecond:
        case QTest::CPUTicks:
        case QTest::WalltimeMilliseconds:
        case QTest::WalltimeNanoseconds:
            break;  // no additional information
        }
 
        Q_ASSERT(result.iterations > 0);
        auto totForm = QTest::formatResult(result.measurement.value, significantDigits);
        if (result.measurement.variance) {
            auto stdForm = QTest::formatResult(sqrt(result.measurement.variance),
                                               significantDigits, midForm.scale);
            buf.appendf(" (total: %s %s, std.dev: %s %s, iterations: %d)\n",
                        totForm.text.constData(), unitText,
                        stdForm.text.constData(), unitText,
                        result.iterations);
        } else {
            buf.appendf(" (total: %s %s, iterations: %d)\n",
                        totForm.text.constData(), unitText,
                        result.iterations);
        }
        outputMessage(buf);
    }
}
 
QPlainTestLogger::QPlainTestLogger(const char *filename)
    : QAbstractTestLogger(filename)
{
}
 
QPlainTestLogger::~QPlainTestLogger() = default;
 
void QPlainTestLogger::startLogging()
{
    QAbstractTestLogger::startLogging();
 
    char buf[1024];
    if (QTestLog::verboseLevel() < 0) {
        std::snprintf(buf, sizeof(buf), "Testing %s\n", QTestResult::currentTestObjectName());
    } else {
        std::snprintf(buf, sizeof(buf),
                      "********* Start testing of %s *********\n"
                      "Config: Using QtTest library " QTEST_VERSION_STR
                      ", %s, %s %s\n", QTestResult::currentTestObjectName(), QLibraryInfo::build(),
                      qPrintable(QSysInfo::productType()), qPrintable(QSysInfo::productVersion()));
    }
    outputMessage(buf);
}
 
void QPlainTestLogger::stopLogging()
{
    char buf[1024];
    const int timeMs = qRound(QTestLog::msecsTotalTime());
    if (QTestLog::verboseLevel() < 0) {
        std::snprintf(buf, sizeof(buf),
                      "Totals: %d passed, %d failed, %d skipped, %d blacklisted, %dms\n",
                      QTestLog::passCount(), QTestLog::failCount(),
                      QTestLog::skipCount(), QTestLog::blacklistCount(), timeMs);
    } else {
        std::snprintf(buf, sizeof(buf),
                      "Totals: %d passed, %d failed, %d skipped, %d blacklisted, %dms\n"
                      "********* Finished testing of %s *********\n",
                      QTestLog::passCount(), QTestLog::failCount(),
                      QTestLog::skipCount(), QTestLog::blacklistCount(), timeMs,
                      QTestResult::currentTestObjectName());
    }
    outputMessage(buf);
 
    QAbstractTestLogger::stopLogging();
}
 
 
void QPlainTestLogger::enterTestFunction(const char * /*function*/)
{
    if (QTestLog::verboseLevel() >= 1)
        printMessage(MessageSource::Other, QTest::ptMessageType2String(Info), "entering");
}
 
void QPlainTestLogger::leaveTestFunction()
{
}
 
void QPlainTestLogger::addIncident(IncidentTypes type, const char *description,
                                   const char *file, int line)
{
    // suppress B?PASS and B?XFAIL in silent mode
    if ((type == Pass || type == BlacklistedPass || type == XFail || type == BlacklistedXFail)
        && QTestLog::verboseLevel() < 0)
        return;
 
    printMessage(MessageSource::Incident, QTest::ptIncidentType2String(type), description, file, line);
}
 
void QPlainTestLogger::addBenchmarkResults(const QList<QBenchmarkResult> &results)
{
    // suppress benchmark results in silent mode
    if (QTestLog::verboseLevel() < 0 || results.isEmpty())
        return;
 
    printBenchmarkResultsHeader(results.first());
    printBenchmarkResults(results);
}
 
void QPlainTestLogger::addMessage(QtMsgType type, const QMessageLogContext &context, const QString &message)
{
    QAbstractTestLogger::addMessage(type, context, message);
}
 
void QPlainTestLogger::addMessage(MessageTypes type, const QString &message,
                                  const char *file, int line)
{
    // suppress non-fatal messages in silent mode
    if (type != QFatal && QTestLog::verboseLevel() < 0)
        return;
 
    printMessage(MessageSource::Other, QTest::ptMessageType2String(type), qPrintable(message), file, line);
}
 
bool QPlainTestLogger::isRepeatSupported() const
{
    // The plain text logger creates unstructured reports. Such reports are not
    // parser friendly, and are unlikely to be parsed by any test reporting
    // tools. We can therefore allow repeated test runs with minimum risk that
    // any parsers fails to handle repeated test names.
    return true;
}
 
QT_END_NAMESPACE