nils/ebusd
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

measure and log min/max send-receive latency and add to info command and json output

Browse Source
This commit is contained in:
john30
2017-11-12 17:37:30 +01:00
parent 35767fb2e3
commit dd50389643
3 changed files with 70 additions and 22 deletions
Download Patch File Download Diff File Expand all files Collapse all files
src/ebusd/bushandler.cpp
+36 -21
View File
@@ -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;
src/ebusd/bushandler.h
+26 -1
View File
@@ -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;
src/ebusd/mainloop.cpp
+8
View File
@@ -1567,6 +1567,10 @@ result_t MainLoop::executeInfo(const vector<string>& 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<string>& 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<unsigned>(m_address);