This is an automatic generated email to let you know that the following patch were queued at the http://git.linuxtv.org/cgit.cgi/v4l-utils.git tree:
Subject: cec-compliance: improve testLostMsgs test Author: Hans Verkuil <hverkuil-ci...@xs4all.nl> Date: Wed Aug 11 13:55:03 2021 +0200 Properly comment this function. As part of the commenting process several bugs were also fixed: - when determining the Signal Free Time, ignore messages with non-OK and non-NACK results, since in those cases nothing was actually transmitted. - always show the detected SFTs: this helps verifying that the measured SFTs are sane. Before they were only shown if there were failures or warnings, or if --verbose was used. - the meaning of the first 'sft' array dimension was changed (effectively inverted), making it a bit easier to explain what it stood for. - replace the various pending_tx_rx_*_msgs counters with just one (pending_tx_rx_msgs). This really shouldn't happen at all, so it is overkill to split it up by the possible rx results. - multiple tx_status bits could be set, count them all and don't stop at the first detected bit. - add a new check to verify that only the oldest transmit result was lost in the message queue. Signed-off-by: Hans Verkuil <hverkuil-ci...@xs4all.nl> utils/cec-compliance/cec-test-adapter.cpp | 193 +++++++++++++++++++++--------- 1 file changed, 135 insertions(+), 58 deletions(-) --- http://git.linuxtv.org/cgit.cgi/v4l-utils.git/commit/?id=ce02e60bf829f47d6c546ff7488425f3ea31bc2d diff --git a/utils/cec-compliance/cec-test-adapter.cpp b/utils/cec-compliance/cec-test-adapter.cpp index 81eb4013c497..08c856af9cee 100644 --- a/utils/cec-compliance/cec-test-adapter.cpp +++ b/utils/cec-compliance/cec-test-adapter.cpp @@ -1012,6 +1012,24 @@ static void print_sfts(unsigned sft[12], const char *descr) printf("\t\t%s: %s\n", descr, s.c_str()); } +// testLostMsgs() checks if the CEC_EVENT_LOST_MSGS event works. But it +// actually tests a lot more: it also checks Signal Free Time behavior +// and if the speed of the CEC bus is as expected. + +// Some defines dealing with SFTs (from include/media/cec.h): +// Correct Signal Free times are: +#define CEC_SIGNAL_FREE_TIME_RETRY 3 +#define CEC_SIGNAL_FREE_TIME_NEW_INITIATOR 5 +#define CEC_SIGNAL_FREE_TIME_NEXT_XFER 7 +// but for measuring we support up to 11: +#define CEC_SIGNAL_FREE_TIME_MAX 11 + +// Two defines (copied from include/media/cec.h) that give the maximum +// number of CEC messages that can be queued up in the transmit and +// receive queues (this is per filehandle): +#define CEC_MAX_MSG_TX_QUEUE_SZ (18 * 1) +#define CEC_MAX_MSG_RX_QUEUE_SZ (18 * 3) + static int testLostMsgs(struct node *node) { struct cec_msg msg; @@ -1019,11 +1037,15 @@ static int testLostMsgs(struct node *node) __u8 me = node->log_addr[0]; __u8 remote = CEC_LOG_ADDR_INVALID; __u32 mode = CEC_MODE_INITIATOR | CEC_MODE_FOLLOWER; -#define MAX_SFT 11 - unsigned sft[2][2][MAX_SFT + 1]; - - memset(sft, 0, sizeof(sft)); - + // Store counts of detected SFTs: the first dimension + // is whether it is a repeating initiator (1) or not (0). + // The second dimension is whether it is a transmit (1) + // or not (0). + // The third dimension is a count of the corresponding SFT + // (0-CEC_SIGNAL_FREE_TIME_MAX). + unsigned sft[2][2][CEC_SIGNAL_FREE_TIME_MAX + 1] = {}; + + // Find the first available remote LA to use for this test for (unsigned i = 0; i < 15; i++) { if (node->remote_la_mask & (1 << i)) { remote = i; @@ -1032,6 +1054,9 @@ static int testLostMsgs(struct node *node) } fail_on_test(flush_pending_msgs(node)); + // We now switch to non-blocking mode. + // This will cause CEC_TRANSMIT to return at once, and when the + // transmit is done it will appear in the receive queue. fcntl(node->fd, F_SETFL, fcntl(node->fd, F_GETFL) | O_NONBLOCK); // Become follower for this test, otherwise all the replies to @@ -1048,7 +1073,13 @@ static int testLostMsgs(struct node *node) bool got_busy = false; unsigned xfer_cnt = 0; unsigned tx_queue_depth = 0; + unsigned tx_first_seq = 0; + unsigned rx_first_seq = 0; + // Transmit <Get CEC Version> until an event was queued up. + // We never dequeue received messages, so once the receive + // queue is full the LOST_MSGS event is queued by the CEC + // core framework, at which point we stop. do { int res; @@ -1056,20 +1087,33 @@ static int testLostMsgs(struct node *node) res = doioctl(node, CEC_TRANSMIT, &msg); fail_on_test(res && res != EBUSY); - if (!res) + if (!res) { + if (!xfer_cnt) + tx_first_seq = msg.sequence; xfer_cnt++; + } if (res == EBUSY) { + // If the CEC device was busy (i.e. the transmit + // queue was full), then wait 10 ms and try again. struct timeval tv = { 0, 10000 }; // 10 ms select(0, nullptr, nullptr, nullptr, &tv); + // Mark that we got a busy error got_busy = true; } else if (!got_busy) { + // If we didn't get a EBUSY yet, then increment this + // variable to detect the TX queue depth. tx_queue_depth++; } + // Keep retrying as long as the transmit failed with EBUSY. } while (res == EBUSY); + // Keep transmitting until an event was queued } while (doioctl(node, CEC_DQEVENT, &ev)); + // We expect the LOST_MSGS event due to a full RX queue. fail_on_test(ev.event != CEC_EVENT_LOST_MSGS); + // Since the transmit queue is one-third of the receive queue, + // it would be very weird if we never got an EBUSY error. fail_on_test(!got_busy); /* @@ -1077,7 +1121,7 @@ static int testLostMsgs(struct node *node) * might finish transmitting before the queue fills up, so * check for 19 instead. */ - fail_on_test(tx_queue_depth == 0 || tx_queue_depth > 19); + fail_on_test(tx_queue_depth == 0 || tx_queue_depth > CEC_MAX_MSG_TX_QUEUE_SZ + 1); if (show_info) printf("\n\t\tFinished transmitting\n\n"); @@ -1091,11 +1135,7 @@ static int testLostMsgs(struct node *node) unsigned pending_tx_low_drive_msgs = 0; unsigned pending_tx_error_msgs = 0; unsigned pending_tx_aborted_msgs = 0; - unsigned pending_tx_rx_no_reply_msgs = 0; - unsigned pending_tx_rx_ok_msgs = 0; - unsigned pending_tx_rx_timed_out_msgs = 0; - unsigned pending_tx_rx_feat_abort_msgs = 0; - unsigned pending_tx_rx_aborted_msgs = 0; + unsigned pending_tx_rx_msgs = 0; unsigned pending_rx_msgs = 0; unsigned pending_rx_cec_version_msgs = 0; time_t start = time(nullptr); @@ -1103,37 +1143,76 @@ static int testLostMsgs(struct node *node) __u64 last_ts = 0; unsigned tx_repeats = 0; + // Now we start reading from the receive queue and analyze the + // timestamps. Remember that the receive queue contains both + // the finished transmit messages from the local LA ('me') and + // the received replies from the remote LA. + // + // We do the while-loop twice, the first time (i == 0) the file handle + // is still in non-blocking mode and so we effectively just drain the + // receive queue quickly. Then we switch to blocking mode (i == 1) and + // keep receiving messages (waiting up to 3 seconds) until no more + // messages are received. for (unsigned i = 0; i < 2; i++) { + // note: timeout is ignored in non-blocking mode (i == 0) msg.timeout = 3000; while (!doioctl(node, CEC_RECEIVE, &msg)) { __u64 ts = msg.tx_ts ? : msg.rx_ts; __u8 initiator = cec_msg_initiator(&msg); - __u64 delta = last_ts ? ts - last_ts : 0; - - delta -= msg.len * 24000000ULL + 4500000ULL; - unsigned sft_real = (delta + 1200000ULL) / 2400000ULL; - - if (last_ts && sft_real <= MAX_SFT) - sft[last_init == me][initiator == me][sft_real]++; - - if (!i && last_ts) { - if (last_init == initiator && initiator == me) { - tx_repeats++; - } else { - if (tx_repeats > 2) - warn("Too many transmits (%d) without receives\n", - tx_repeats); - tx_repeats = 0; + bool ok_or_nack = (msg.tx_status & (CEC_TX_STATUS_OK | CEC_TX_STATUS_NACK)) || + (msg.rx_status & CEC_RX_STATUS_OK); + + if (last_ts && ok_or_nack) { + __u64 delta = last_ts ? ts - last_ts : 0; + + // The timestamp ts is when the transmit was done + // or the message was received. + // To get the time when the message started transmitting + // we subtract the time spent transmitting the message. + delta -= msg.len * 24000000ULL + 4500000ULL; + //unsigned sft_real = (delta + 1200000ULL) / 2400000ULL; + unsigned sft_real = delta / 2400000ULL; + + // Count the detected SFT in the sft array. + if (last_ts && sft_real <= CEC_SIGNAL_FREE_TIME_MAX) + sft[last_init == initiator][initiator == me][sft_real]++; + + if (!i && last_ts) { + if (last_init == initiator && initiator == me) { + tx_repeats++; + } else { + // Too many repeated transmits means that + // the transmitter is hogging the bus, preventing + // the remote LA to transmit the reply. + if (tx_repeats > 2) + warn("Too many transmits (%d) without receives\n", + tx_repeats); + tx_repeats = 0; + } } } - last_ts = ts; - last_init = initiator; + if (ok_or_nack) { + last_ts = ts; + last_init = initiator; + } + // Count total number of received messages (both non-blocking + // transmit results and actual received replies). pending_msgs++; - if (i == 0) + // Count number of received msgs when quickly draining the + // receive queue in the non-blocking phase. + if (i == 0) { + // The result of the first transmit will also be the + // message that was lost since it was the oldest: check + // that that's actually the case. + if (!rx_first_seq && msg.sequence) + rx_first_seq = msg.sequence; pending_quick_msgs++; + } if (!msg.sequence) { + // Count remote messages and the number of + // received <CEC Version> messages. pending_rx_msgs++; if (msg.len == 3 && msg.msg[1] == CEC_MSG_CEC_VERSION) pending_rx_cec_version_msgs++; @@ -1144,25 +1223,19 @@ static int testLostMsgs(struct node *node) pending_tx_aborted_msgs++; else if (msg.tx_status & CEC_TX_STATUS_OK) { pending_tx_ok_msgs++; - if (msg.rx_status & CEC_RX_STATUS_OK) - pending_tx_rx_ok_msgs++; - else if (msg.rx_status & CEC_RX_STATUS_FEATURE_ABORT) - pending_tx_rx_feat_abort_msgs++; - else if (msg.rx_status & CEC_RX_STATUS_TIMEOUT) - pending_tx_rx_timed_out_msgs++; - else if (msg.rx_status & CEC_RX_STATUS_ABORTED) - pending_tx_rx_aborted_msgs++; - else - pending_tx_rx_no_reply_msgs++; - } else if (msg.tx_status & CEC_TX_STATUS_NACK) - pending_tx_nack_msgs++; - else if (msg.tx_status & CEC_TX_STATUS_ARB_LOST) - pending_tx_arb_lost_msgs++; - else if (msg.tx_status & CEC_TX_STATUS_LOW_DRIVE) - pending_tx_low_drive_msgs++; - else - pending_tx_error_msgs++; + if (msg.rx_status) + pending_tx_rx_msgs++; + } + if (msg.tx_status & CEC_TX_STATUS_NACK) + pending_tx_nack_msgs += msg.tx_nack_cnt; + if (msg.tx_status & CEC_TX_STATUS_ARB_LOST) + pending_tx_arb_lost_msgs += msg.tx_arb_lost_cnt; + if (msg.tx_status & CEC_TX_STATUS_LOW_DRIVE) + pending_tx_low_drive_msgs += msg.tx_low_drive_cnt; + if (msg.tx_status & CEC_TX_STATUS_ERROR) + pending_tx_error_msgs += msg.tx_error_cnt; } + // Go back to blocking mode after draining the receive queue. fcntl(node->fd, F_SETFL, fcntl(node->fd, F_GETFL) & ~O_NONBLOCK); if (!i && show_info) printf("\n\t\tDrained receive queue\n\n"); @@ -1175,7 +1248,7 @@ static int testLostMsgs(struct node *node) */ bool fail_msg = pending_tx_error_msgs || pending_tx_timed_out_msgs || pending_tx_aborted_msgs || - pending_tx_rx_aborted_msgs || pending_quick_msgs < 18 * 3 || + pending_tx_rx_msgs || pending_quick_msgs < CEC_MAX_MSG_RX_QUEUE_SZ || pending_rx_cec_version_msgs > xfer_cnt; bool warn_msg = pending_rx_cec_version_msgs < xfer_cnt - 2; @@ -1184,10 +1257,8 @@ static int testLostMsgs(struct node *node) printf("\n"); if (pending_tx_ok_msgs) { printf("\t\tSuccessful transmits: %d\n", pending_tx_ok_msgs); - printf("\t\t\tReply OK: %d No replies: %d Feature Aborted: %d Timed out: %d Aborted: %d\n", - pending_tx_rx_ok_msgs, - pending_tx_rx_no_reply_msgs, pending_tx_rx_feat_abort_msgs, - pending_tx_rx_timed_out_msgs, pending_tx_rx_aborted_msgs); + if (pending_tx_rx_msgs) + printf("\t\t\tUnexpected replies: %d\n", pending_tx_rx_msgs); } if (pending_tx_nack_msgs) printf("\t\tNACKed transmits: %d\n", pending_tx_nack_msgs); @@ -1204,21 +1275,27 @@ static int testLostMsgs(struct node *node) if (pending_rx_msgs) printf("\t\tReceived messages: %d of which %d were CEC_MSG_CEC_VERSION\n", pending_rx_msgs, pending_rx_cec_version_msgs); - print_sfts(sft[1][1], "SFTs for repeating messages (>= 7)"); - print_sfts(sft[0][1], "SFTs for newly transmitted messages (>= 5)"); - print_sfts(sft[0][0], "SFTs for repeating remote messages (>= 7)"); - print_sfts(sft[1][0], "SFTs for newly transmitted remote messages (>= 5)"); if (pending_quick_msgs < pending_msgs) printf("\t\tReceived %d messages immediately, and %d over %ld seconds\n", pending_quick_msgs, pending_msgs - pending_quick_msgs, time(nullptr) - start); } + print_sfts(sft[1][1], "SFTs for repeating messages (>= 7)"); + print_sfts(sft[1][0], "SFTs for repeating remote messages (>= 7)"); + print_sfts(sft[0][1], "SFTs for newly transmitted messages (>= 5)"); + print_sfts(sft[0][0], "SFTs for newly transmitted remote messages (>= 5)"); if (fail_msg) return fail("There were %d messages in the receive queue for %d transmits\n", pending_msgs, xfer_cnt); if (warn_msg) warn("There were %d CEC_GET_VERSION transmits but only %d CEC_VERSION receives\n", xfer_cnt, pending_rx_cec_version_msgs); + + // Final check if everything else is OK: check that only the oldest + // message (the result of the first transmit) was dropped in the + // receive queue. + if (!fail_msg && !warn_msg) + warn_on_test(rx_first_seq != tx_first_seq + 1); return 0; } _______________________________________________ linuxtv-commits mailing list linuxtv-commits@linuxtv.org https://www.linuxtv.org/cgi-bin/mailman/listinfo/linuxtv-commits
