Index: tools/CANDumpPlayer/main.cpp =================================================================== diff -u -r46d7af4d93047a9c416f93447bd91f94513a000a -re9aa2c82ccb8cb5662f05ed878d2f7b5ef9f4a65 --- tools/CANDumpPlayer/main.cpp (.../main.cpp) (revision 46d7af4d93047a9c416f93447bd91f94513a000a) +++ tools/CANDumpPlayer/main.cpp (.../main.cpp) (revision e9aa2c82ccb8cb5662f05ed878d2f7b5ef9f4a65) @@ -13,6 +13,9 @@ #include #include +constexpr quint8 syncByte = 0xA5; +constexpr int headerMsgIdOffset = 3; + int main(int argc, char *argv[]) { QCoreApplication app(argc, argv); @@ -90,7 +93,7 @@ // Candump files may use either Unix epoch ("1234567890.123456") or // wall-clock ("YYYY-MM-DD HH:MM:SS.ffffff") timestamp format. - // We parse both and normalise to microseconds since epoch as qint64. + // Parse both and normalise to microseconds since epoch as qint64. const QString datetimeFormat = QStringLiteral("yyyy-MM-dd HH:mm:ss.zzz"); auto parseTimestampUs = [&](const QString &raw) -> qint64 { @@ -115,16 +118,31 @@ }; // Record the monotonic clock origin at the start of replay. - // Each frame's absolute wake time is: origin + (logOffset / speed). - // This absorbs per-frame overshoot automatically — no drift accumulation. + // Use origin + (logOffset / speed) for frame replay time to prevent accumulating drift. struct timespec replayOrigin; clock_gettime(CLOCK_MONOTONIC, &replayOrigin); qint64 firstTimestampUs = -1; + qint64 lastTimestampUs = -1; qint64 prevTimestampUs = -1; QElapsedTimer wallTimer; unsigned int lineCount = 1; + quint64 playedCount = 0; + qint64 totalDeltaNs = 0; + qint64 avgDeltaNs = 0; + QElapsedTimer replayTimer; + replayTimer.start(); + + quint64 messageCount = 0; + QElapsedTimer msgTimer; + qint64 msgTotalDeltaNs = 0; + qint64 msgAvgDeltaNs = 0; + qint64 msgDeltaNs = 0; + qint64 msgCalcDeltaUs = 0; + qint64 msgPrevTimestampUs = -1; + unsigned int msgId = 0; + while (stream.readLineInto(&line)) { auto match = regexEntry.match(line); if (match.hasMatch()) { @@ -135,13 +153,22 @@ payload.append(static_cast(payloadMatch.captured(1).toUInt(nullptr, 16))); } + // Grossly count sent messages based off frames that start with the sync byte, + // this may not be completely accurate, but close enough. + const bool isMessageStart = !payload.isEmpty() && static_cast(payload.at(0)) == syncByte; + const qint64 timestampUs = parseTimestampUs(match.captured(QStringLiteral("timestamp"))); const qint64 calcDeltaUs = (prevTimestampUs >= 0 && timestampUs >= 0) ? timestampUs - prevTimestampUs : 0; - if (speed > 0.0 && timestampUs >= 0) { + // Save the first and last time stamps for reporting later + if (timestampUs >= 0) { if (firstTimestampUs < 0) { firstTimestampUs = timestampUs; } + lastTimestampUs = timestampUs; + } + + if (speed > 0.0 && timestampUs >= 0) { const qint64 offsetUs = static_cast((timestampUs - firstTimestampUs) / speed); struct timespec wakeTime; wakeTime.tv_sec = replayOrigin.tv_sec + offsetUs / 1'000'000; @@ -151,20 +178,61 @@ clock_nanosleep(CLOCK_MONOTONIC, TIMER_ABSTIME, &wakeTime, nullptr); } - if (testMode) { - const qint64 actualDeltaUs = (prevTimestampUs >= 0) ? wallTimer.nsecsElapsed() / 1000 : 0; - wallTimer.restart(); - qInfo().noquote() << QString("delta(calc=%1us, actual=%2us) %3") - .arg(calcDeltaUs, 6) - .arg(actualDeltaUs, 6) - .arg(line.trimmed()); + // Wall-clock interval since the previous frame. + // start() on an already-running timer restarts it. + const qint64 actualDeltaNs = wallTimer.isValid() ? wallTimer.nsecsElapsed() : 0; + wallTimer.start(); + playedCount++; + if (playedCount > 1) { + totalDeltaNs += actualDeltaNs; + avgDeltaNs = totalDeltaNs / qint64(playedCount - 1); } - else { - const unsigned int canId = match.captured(QStringLiteral("can_id")).toUInt(nullptr, 16); + + // Same interval measurement, but only across message starts, so it spans a + // whole message rather than one frame of it. + if (isMessageStart) { + msgDeltaNs = msgTimer.isValid() ? msgTimer.nsecsElapsed() : 0; + msgTimer.start(); + messageCount++; + if (messageCount > 1) { + msgTotalDeltaNs += msgDeltaNs; + msgAvgDeltaNs = msgTotalDeltaNs / qint64(messageCount - 1); + } + // Logged interval between sync byte frames + msgCalcDeltaUs = (msgPrevTimestampUs >= 0 && timestampUs >= 0) ? timestampUs - msgPrevTimestampUs : 0; + msgPrevTimestampUs = timestampUs; + + msgId = (payload.size() >= headerMsgIdOffset + 2) + ? (static_cast(payload.at(headerMsgIdOffset)) << 8) + | static_cast(payload.at(headerMsgIdOffset + 1)) + : 0; + } + + const unsigned int canId = match.captured(QStringLiteral("can_id")).toUInt(nullptr, 16); + if (!testMode) { QCanBusFrame frame(canId, payload); canDevice->writeFrame(frame); } + qInfo().noquote() << QString("Frame %1: canId=0x%2, time since last frame [actual=%3ms, calc=%4ms], " + "avg time between frames=%5ms, avg time between messages=%6ms") + .arg(playedCount) + .arg(QString("%1").arg(canId, 4, 16, QChar('0')).toUpper()) + .arg((playedCount > 1) ? actualDeltaNs / 1'000'000.0 : 0.0, 6, 'f', 3, QChar(' ')) + .arg((playedCount > 1) ? calcDeltaUs / 1000.0 : 0.0, 6, 'f', 3, QChar(' ')) + .arg(avgDeltaNs / 1'000'000.0, 6, 'f', 3, QChar(' ')) + .arg(msgAvgDeltaNs / 1'000'000.0, 6, 'f', 3, QChar(' ')); + + if (isMessageStart) { + qInfo().noquote() << QString("Message %1: msgId=0x%2, time since last [actual=%3ms, calc=%4ms], " + "avg time between=%5ms.") + .arg(messageCount) + .arg(QString("%1").arg(QString("%1").arg(msgId, 4, 16, QChar('0')).toUpper()).toUpper()) + .arg((messageCount > 1) ? msgDeltaNs / 1'000'000.0 : 0.0, 6, 'f', 3, QChar(' ')) + .arg((messageCount > 1) ? msgCalcDeltaUs / 1000.0 : 0.0, 6, 'f', 3, QChar(' ')) + .arg(msgAvgDeltaNs / 1'000'000.0, 6, 'f', 3, QChar(' ')); + } + prevTimestampUs = timestampUs; } else { @@ -174,6 +242,19 @@ lineCount++; } + // Span the dump covers, i.e. the last frame timestamp minus the first. Compare + // against the replay time to see how faithfully the replay tracked the log. + const qint64 logDurationUs = (firstTimestampUs >= 0) ? (lastTimestampUs - firstTimestampUs) : 0; + + qInfo().noquote() << QString("replay complete: messages(approx)=%1, frames=%2, avg time between frames=%3ms, " + "avg time between messages=%4ms, total replay time=%5ms, total log time=%6m") + .arg(messageCount) + .arg(playedCount) + .arg(avgDeltaNs / 1'000'000.0, 0, 'f', 3, QChar(' ')) + .arg(msgAvgDeltaNs / 1'000'000.0, 0, 'f', 3, QChar(' ')) + .arg(replayTimer.nsecsElapsed() / 1'000'000.0, 0, 'f', 3, QChar(' ')) + .arg(logDurationUs / 60'000'000.0, 0, 'f', 2, QChar(' ')); + file.close(); if (canDevice) { canDevice->disconnectDevice();