From dd50389643287f15123cb388d4b51d1a5c6ca17c Mon Sep 17 00:00:00 2001 From: john30 Date: Sun, 12 Nov 2017 17:37:30 +0100 Subject: [PATCH] measure and log min/max send-receive latency and add to info command and json output --- src/ebusd/bushandler.cpp | 57 +++++++++++++++++++++++++--------------- src/ebusd/bushandler.h | 27 ++++++++++++++++++- src/ebusd/mainloop.cpp | 8 ++++++ 3 files changed, 70 insertions(+), 22 deletions(-) diff --git a/src/ebusd/bushandler.cpp b/src/ebusd/bushandler.cpp index 234f0491..efb7494d 100644 --- a/src/ebusd/bushandler.cpp +++ b/src/ebusd/bushandler.cpp @@ -419,6 +419,7 @@ void BusHandler::run() { setState(bs_noSignal, result); } symCount = 0; + m_symLatencyMin = m_symLatencyMax = -1; time(&lastTime); lastTime += 2; } @@ -544,6 +545,7 @@ result_t BusHandler::handleSymbol() { // send symbol if necessary result_t result; + struct timespec sentTime, recvTime; if (sending) { if (m_state != bs_sendSyn && (sendSymbol == ESC || sendSymbol == SYN)) { if (m_escape) { @@ -554,6 +556,7 @@ result_t BusHandler::handleSymbol() { } } result = m_device->send(sendSymbol); + clockGettime(&sentTime); if (result == RESULT_OK) { if (m_state == bs_ready) { timeout = m_transferLatency+m_busAcquireTimeout; @@ -573,13 +576,18 @@ result_t BusHandler::handleSymbol() { // receive next symbol (optionally check reception of sent symbol) symbol_t recvSymbol; result = m_device->recv(timeout+m_transferLatency, &recvSymbol); + if (sending) { + clockGettime(&recvTime); + } if (!sending && result == RESULT_ERR_TIMEOUT && m_generateSynInterval > 0 && timeout >= m_generateSynInterval && (m_state == bs_noSignal || m_state == bs_skip)) { // check if acting as AUTO-SYN generator is required result = m_device->send(SYN); if (result == RESULT_OK) { + clockGettime(&sentTime); recvSymbol = ESC; result = m_device->recv(SEND_TIMEOUT+m_transferLatency, &recvSymbol); + clockGettime(&recvTime); if (result == RESULT_ERR_TIMEOUT) { return setState(bs_noSignal, result); } @@ -588,6 +596,7 @@ result_t BusHandler::handleSymbol() { } else if (recvSymbol != SYN) { logError(lf_bus, "received %2.2x instead of AUTO-SYN symbol", recvSymbol); } else { + measureLatency(&sentTime, &recvTime); if (m_generateSynInterval != SYN_TIMEOUT) { // received own AUTO-SYN symbol back again: act as AUTO-SYN generator now m_generateSynInterval = SYN_TIMEOUT; @@ -623,6 +632,13 @@ result_t BusHandler::handleSymbol() { return setState(bs_ready, m_state == bs_skip ? RESULT_OK : RESULT_ERR_SYN); } + if (sending && m_state != bs_ready) { // check received symbol for equality if not in arbitration + if (recvSymbol != sendSymbol) { + return setState(bs_skip, RESULT_ERR_SYMBOL); + } + measureLatency(&sentTime, &recvTime); + } + switch (m_state) { case bs_ready: case bs_recvCmd: @@ -638,9 +654,6 @@ result_t BusHandler::handleSymbol() { if (m_escape) { // check escape/unescape state if (sending) { - if (recvSymbol != sendSymbol) { - return setState(bs_skip, RESULT_ERR_SYMBOL); - } if (sendSymbol == ESC) { return RESULT_OK; } @@ -811,9 +824,6 @@ result_t BusHandler::handleSymbol() { if (!sending || m_currentRequest == NULL) { return setState(bs_skip, RESULT_ERR_INVALID_ARG); } - if (recvSymbol != sendSymbol) { - return setState(bs_skip, RESULT_ERR_SYMBOL); - } m_nextSendPos++; if (m_nextSendPos >= m_currentRequest->m_master.size()) { return setState(bs_sendCmdCrc, RESULT_OK); @@ -831,9 +841,6 @@ result_t BusHandler::handleSymbol() { if (!sending || m_currentRequest == NULL) { return setState(bs_skip, RESULT_ERR_INVALID_ARG); } - if (recvSymbol != sendSymbol) { - return setState(bs_skip, RESULT_ERR_SYMBOL); - } if (!m_crcValid) { if (!m_repeat) { m_repeat = true; @@ -848,9 +855,6 @@ result_t BusHandler::handleSymbol() { if (!sending || !m_answer) { return setState(bs_skip, RESULT_ERR_INVALID_ARG); } - if (recvSymbol != sendSymbol) { - return setState(bs_skip, RESULT_ERR_SYMBOL); - } if (!m_crcValid) { if (!m_repeat) { m_repeat = true; @@ -897,9 +901,6 @@ result_t BusHandler::handleSymbol() { if (!sending || !m_answer) { return setState(bs_skip, RESULT_ERR_INVALID_ARG); } - if (recvSymbol != sendSymbol) { - return setState(bs_skip, RESULT_ERR_SYMBOL); - } m_nextSendPos++; if (m_nextSendPos >= m_response.size()) { // slave data completely sent @@ -911,18 +912,12 @@ result_t BusHandler::handleSymbol() { if (!sending || !m_answer) { return setState(bs_skip, RESULT_ERR_INVALID_ARG); } - if (recvSymbol != sendSymbol) { - return setState(bs_skip, RESULT_ERR_SYMBOL); - } return setState(bs_recvResAck, RESULT_OK); case bs_sendSyn: if (!sending) { return setState(bs_skip, RESULT_ERR_INVALID_ARG); } - if (recvSymbol != sendSymbol) { - return setState(bs_skip, RESULT_ERR_SYMBOL); - } return setState(bs_skip, RESULT_OK); } return RESULT_OK; @@ -1003,6 +998,26 @@ result_t BusHandler::setState(BusState state, result_t result, bool firstRepetit return result; } +void BusHandler::measureLatency(struct timespec* sentTime, struct timespec* recvTime) { + long long latencyLong = (recvTime->tv_sec*1000000000 + recvTime->tv_nsec + - sentTime->tv_sec*1000000000 - sentTime->tv_nsec)/1000000; + if (latencyLong < 0 || latencyLong > 1000) { + return; // clock skew or out of reasonable range + } + int latency = (int)latencyLong; + logDebug(lf_bus, "send/receive symbol latency %d ms", latency); + if (m_symLatencyMin >= 0 && (latency >= m_symLatencyMin && latency <= m_symLatencyMax)) { + return; + } + if (m_symLatencyMin == -1 || latency < m_symLatencyMin) { + m_symLatencyMin = latency; + } + if (m_symLatencyMax == -1 || latency > m_symLatencyMax) { + m_symLatencyMax = latency; + } + logInfo(lf_bus, "send/receive symbol latency %lld - %lld ms", m_symLatencyMin, m_symLatencyMax); +} + bool BusHandler::addSeenAddress(symbol_t address) { if (!isValidAddress(address, false)) { return false; diff --git a/src/ebusd/bushandler.h b/src/ebusd/bushandler.h index b441b8f9..08a394a8 100644 --- a/src/ebusd/bushandler.h +++ b/src/ebusd/bushandler.h @@ -378,7 +378,7 @@ class BusHandler : public WaitThread { m_masterCount(device->isReadOnly()?0:1), m_autoLockCount(lockCount == 0), m_lockCount(lockCount <= 3 ? 3 : lockCount), m_remainLockCount(m_autoLockCount ? 1 : 0), m_generateSynInterval(generateSyn ? SYN_TIMEOUT*getMasterNumber(ownAddress)+SYMBOL_DURATION : 0), - m_pollInterval(pollInterval), m_lastReceive(0), m_lastPoll(0), + m_pollInterval(pollInterval), m_symLatencyMin(-1), m_symLatencyMax(-1), m_lastReceive(0), m_lastPoll(0), m_currentRequest(NULL), m_currentAnswering(false), m_runningScans(0), m_nextSendPos(0), m_symPerSec(0), m_maxSymPerSec(0), m_state(bs_noSignal), m_escape(0), m_crc(0), m_crcValid(false), m_repeat(false), @@ -544,6 +544,18 @@ class BusHandler : public WaitThread { */ unsigned int getMaxSymbolRate() const { return m_maxSymPerSec; } + /** + * Return the minimal measured latency between send and receive of a symbol. + * @return the minimal measured latency between send and receive of a symbol in milliseconds, -1 if not yet known. + */ + int getMinSymbolLatency() const { return m_symLatencyMin; } + + /** + * Return the maximal measured latency between send and receive of a symbol. + * @return the maximal measured latency between send and receive of a symbol in milliseconds, -1 if not yet known. + */ + int getMaxSymbolLatency() const { return m_symLatencyMax; } + /** * Return the number of masters already seen. * @return the number of masters already seen (including ebusd itself). @@ -588,6 +600,13 @@ class BusHandler : public WaitThread { */ bool addSeenAddress(symbol_t address); + /** + * Called to measure the latency between send and receive of a symbol. + * @param sentTime the time the symbol was sent. + * @param recvTime the time the symbol was received. + */ + void measureLatency(struct timespec* sentTime, struct timespec* recvTime); + /** * Called when a passive reception was successfully completed. */ @@ -658,6 +677,12 @@ class BusHandler : public WaitThread { /** the interval in seconds in which poll messages are cycled, or 0 if disabled. */ const unsigned int m_pollInterval; + /** the minimal measured latency between send and receive of a symbol in milliseconds, -1 if not yet known. */ + int m_symLatencyMin; + + /** the maximal measured latency between send and receive of a symbol in milliseconds, -1 if not yet known. */ + int m_symLatencyMax; + /** the time of the last received symbol, or 0 for never. */ time_t m_lastReceive; diff --git a/src/ebusd/mainloop.cpp b/src/ebusd/mainloop.cpp index 0ad814cf..5e396cb6 100644 --- a/src/ebusd/mainloop.cpp +++ b/src/ebusd/mainloop.cpp @@ -1567,6 +1567,10 @@ result_t MainLoop::executeInfo(const vector& args, const string& user, o *ostream << "signal: acquired\n" << "symbol rate: " << m_busHandler->getSymbolRate() << "\n" << "max symbol rate: " << m_busHandler->getMaxSymbolRate() << "\n"; + if (m_busHandler->getMinSymbolLatency() >= 0) { + *ostream << "min symbol latency: " << m_busHandler->getMinSymbolLatency() << "\n" + << "max symbol latency: " << m_busHandler->getMaxSymbolLatency() << "\n"; + } } else { *ostream << "signal: no signal\n"; } @@ -1785,6 +1789,10 @@ result_t MainLoop::executeGet(const vector& args, bool* connected, ostri if (m_busHandler->hasSignal()) { *ostream << ",\n \"symbolrate\": " << m_busHandler->getSymbolRate() << ",\n \"maxsymbolrate\": " << m_busHandler->getMaxSymbolRate(); + if (m_busHandler->getMinSymbolLatency() >= 0) { + *ostream << ",\n \"minsymbollatency\": " << m_busHandler->getMinSymbolLatency() + << ",\n \"maxsymbollatency\": " << m_busHandler->getMaxSymbolLatency(); + } } if (!m_device->isReadOnly()) { *ostream << ",\n \"qq\": " << static_cast(m_address);