[mesh-forwarder] add time-in-queue statistics collection feature (#9170)

This commit adds the ability to collect statistics on the time
messages spend in the TX queue.

When enabled, a histogram of the time-in-queue is collected. The
time-in-queue is tracked for direct transmissions only, and is
measured as the duration from when a message is added to the TX queue
until it is passed to the MAC layer for transmission or dropped.

The histogram data consists of a number of bins, each representing a
range of time-in-queue values. The bin interval length and maximum
tracked interval can be configured using newly added configuration
options.

This commit also adds a new public OT API and a related CLI command
(`timeinqueue`) to get the collected statistics or reset the data.
This commit is contained in:
Abtin Keshavarzian
2023-07-10 13:34:35 -07:00
committed by GitHub
parent 1839f15417
commit e6df00dd66
9 changed files with 460 additions and 1 deletions
+1
View File
@@ -150,6 +150,7 @@ ot_option(OT_TCP OPENTHREAD_CONFIG_TCP_ENABLE "TCP")
ot_option(OT_TIME_SYNC OPENTHREAD_CONFIG_TIME_SYNC_ENABLE "time synchronization service")
ot_option(OT_TREL OPENTHREAD_CONFIG_RADIO_LINK_TREL_ENABLE "TREL radio link for Thread over Infrastructure feature")
ot_option(OT_TX_BEACON_PAYLOAD OPENTHREAD_CONFIG_MAC_OUTGOING_BEACON_PAYLOAD_ENABLE "tx beacon payload")
ot_option(OT_TX_QUEUE_STATS OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_ENABLE "tx queue statistics")
ot_option(OT_UDP_FORWARD OPENTHREAD_CONFIG_UDP_FORWARD_ENABLE "UDP forward")
ot_option(OT_UPTIME OPENTHREAD_CONFIG_UPTIME_ENABLE "uptime")
+1 -1
View File
@@ -53,7 +53,7 @@ extern "C" {
* @note This number versions both OpenThread platform and user APIs.
*
*/
#define OPENTHREAD_API_VERSION (341)
#define OPENTHREAD_API_VERSION (342)
/**
* @addtogroup api-instance
+57
View File
@@ -902,6 +902,63 @@ const otIpCounters *otThreadGetIp6Counters(otInstance *aInstance);
*/
void otThreadResetIp6Counters(otInstance *aInstance);
/**
* Gets the time-in-queue histogram for messages in the TX queue.
*
* Requires `OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_ENABLE`.
*
* Histogram of the time-in-queue of messages in the transmit queue is collected. The time-in-queue is tracked for
* direct transmissions only and is measured as the duration from when a message is added to the transmit queue until
* it is passed to the MAC layer for transmission or dropped.
*
* The histogram is returned as an array of `uint32_t` values with `aNumBins` entries. The first entry in the array
* (at index 0) represents the number of messages with a time-in-queue less than `aBinInterval`. The second entry
* represents the number of messages with a time-in-queue greater than or equal to `aBinInterval`, but less than
* `2 * aBinInterval`. And so on. The last entry represents the number of messages with time-in-queue greater than or
* equal to `(aNumBins - 1) * aBinInterval`.
*
* The collected statistics can be reset by calling `otThreadResetTimeInQueueStat()`. The histogram information is
* collected since the OpenThread instance was initialized or since the last time statistics collection was reset by
* calling the `otThreadResetTimeInQueueStat()`.
*
* Pointers @p aNumBins and @p aBinInterval MUST NOT be NULL.
*
* @param[in] aInstance A pointer to an OpenThread instance.
* @param[out] aNumBins Pointer to return the number of bins in histogram (array length).
* @param[out] aBinInterval Pointer to return the histogram bin interval length in milliseconds.
*
* @returns A pointer to an array of @p aNumBins entries representing the collected histogram info.
*
*/
const uint32_t *otThreadGetTimeInQueueHistogram(otInstance *aInstance, uint16_t *aNumBins, uint32_t *aBinInterval);
/**
* Gets the maximum time-in-queue for messages in the TX queue.
*
* Requires `OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_ENABLE`.
*
* The time-in-queue is tracked for direct transmissions only and is measured as the duration from when a message is
* added to the transmit queue until it is passed to the MAC layer for transmission or dropped.
*
* The collected statistics can be reset by calling `otThreadResetTimeInQueueStat()`.
*
* @param[in] aInstance A pointer to an OpenThread instance.
*
* @returns The maximum time-in-queue in milliseconds for all messages in the TX queue (so far).
*
*/
uint32_t otThreadGetMaxTimeInQueue(otInstance *aInstance);
/**
* Resets the TX queue time-in-queue statistics.
*
* Requires `OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_ENABLE`.
*
* @param[in] aInstance A pointer to an OpenThread instance.
*
*/
void otThreadResetTimeInQueueStat(otInstance *aInstance);
/**
* Gets the Thread MLE counters.
*
+92
View File
@@ -117,6 +117,7 @@ Done
- [srp](README_SRP.md)
- [tcp](README_TCP.md)
- [thread](#thread-start)
- [timeinqueue](#timeinqueue)
- [trel](#trel)
- [tvcheck](#tvcheck-enable)
- [txpower](#txpower)
@@ -3362,6 +3363,97 @@ Get the Thread Version number.
Done
```
### timeinqueue
Print the tx queue time-in-queue histogram.
Requires `OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_ENABLE`.
The time-in-queue is tracked for direct transmissions only and is measured as the duration from when a message is added to the transmit queue until it is passed to the MAC layer for transmission or dropped.
Each table row shows min and max time-in-queue (in milliseconds) followed by number of messages with time-in-queue within the specified min-max range. The histogram information is collected since the OpenThread instance was initialized or since the last time statistics collection was reset by the `timeinqueue reset` command.
The collected statistics can be reset by `timeinqueue reset`.
```bash
> timeinqueue
| Min | Max |Msg Count|
+------+------+---------+
| 0 | 9 | 1537 |
| 10 | 19 | 156 |
| 20 | 29 | 57 |
| 30 | 39 | 108 |
| 40 | 49 | 60 |
| 50 | 59 | 76 |
| 60 | 69 | 88 |
| 70 | 79 | 51 |
| 80 | 89 | 86 |
| 90 | 99 | 45 |
| 100 | 109 | 43 |
| 110 | 119 | 44 |
| 120 | 129 | 38 |
| 130 | 139 | 44 |
| 140 | 149 | 35 |
| 150 | 159 | 41 |
| 160 | 169 | 34 |
| 170 | 179 | 13 |
| 180 | 189 | 24 |
| 190 | 199 | 3 |
| 200 | 209 | 0 |
| 210 | 219 | 0 |
| 220 | 229 | 2 |
| 230 | 239 | 0 |
| 240 | 249 | 0 |
| 250 | 259 | 0 |
| 260 | 269 | 0 |
| 270 | 279 | 0 |
| 280 | 289 | 0 |
| 290 | 299 | 1 |
| 300 | 309 | 0 |
| 310 | 319 | 0 |
| 320 | 329 | 0 |
| 330 | 339 | 0 |
| 340 | 349 | 0 |
| 350 | 359 | 0 |
| 360 | 369 | 0 |
| 370 | 379 | 0 |
| 380 | 389 | 0 |
| 390 | 399 | 0 |
| 400 | 409 | 0 |
| 410 | 419 | 0 |
| 420 | 429 | 0 |
| 430 | 439 | 0 |
| 440 | 449 | 0 |
| 450 | 459 | 0 |
| 460 | 469 | 0 |
| 470 | 479 | 0 |
| 480 | 489 | 0 |
| 490 | inf | 0 |
Done
```
### timeinqueue max
Print the maximum observed time-in-queue in milliseconds.
Requires `OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_ENABLE`.
The time-in-queue is tracked for direct transmissions only and is measured as the duration from when a message is added to the transmit queue until it is passed to the MAC layer for transmission or dropped.
```bash
> timeinqueue max
291
```
### timeinqueue reset
Reset the TX queue time-in-queue statistics.
```bash
> timeinqueue reset
Done
```
### trel
Indicate whether TREL radio operation is enabled or not.
+136
View File
@@ -6948,6 +6948,139 @@ template <> otError Interpreter::Process<Cmd("thread")>(Arg aArgs[])
return error;
}
#if OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_ENABLE
template <> otError Interpreter::Process<Cmd("timeinqueue")>(Arg aArgs[])
{
otError error = OT_ERROR_NONE;
/**
* @cli timeinqueue
* @code
* timeinqueue
* | Min | Max |Msg Count|
* +------+------+---------+
* | 0 | 9 | 1537 |
* | 10 | 19 | 156 |
* | 20 | 29 | 57 |
* | 30 | 39 | 108 |
* | 40 | 49 | 60 |
* | 50 | 59 | 76 |
* | 60 | 69 | 88 |
* | 70 | 79 | 51 |
* | 80 | 89 | 86 |
* | 90 | 99 | 45 |
* | 100 | 109 | 43 |
* | 110 | 119 | 44 |
* | 120 | 129 | 38 |
* | 130 | 139 | 44 |
* | 140 | 149 | 35 |
* | 150 | 159 | 41 |
* | 160 | 169 | 34 |
* | 170 | 179 | 13 |
* | 180 | 189 | 24 |
* | 190 | 199 | 3 |
* | 200 | 209 | 0 |
* | 210 | 219 | 0 |
* | 220 | 229 | 2 |
* | 230 | 239 | 0 |
* | 240 | 249 | 0 |
* | 250 | 259 | 0 |
* | 260 | 269 | 0 |
* | 270 | 279 | 0 |
* | 280 | 289 | 0 |
* | 290 | 299 | 1 |
* | 300 | 309 | 0 |
* | 310 | 319 | 0 |
* | 320 | 329 | 0 |
* | 330 | 339 | 0 |
* | 340 | 349 | 0 |
* | 350 | 359 | 0 |
* | 360 | 369 | 0 |
* | 370 | 379 | 0 |
* | 380 | 389 | 0 |
* | 390 | 399 | 0 |
* | 400 | 409 | 0 |
* | 410 | 419 | 0 |
* | 420 | 429 | 0 |
* | 430 | 439 | 0 |
* | 440 | 449 | 0 |
* | 450 | 459 | 0 |
* | 460 | 469 | 0 |
* | 470 | 479 | 0 |
* | 480 | 489 | 0 |
* | 490 | inf | 0 |
* Done
* @endcode
* @par api_copy
* #otThreadGetTimeInQueueHistogram
* @csa{timeinqueue reset}
*/
if (aArgs[0].IsEmpty())
{
static const char *const kTimeInQueueTableTitles[] = {"Min", "Max", "Msg Count"};
static const uint8_t kTimeInQueueTableColumnWidths[] = {6, 6, 9};
uint16_t numBins;
uint32_t binInterval;
const uint32_t *histogram;
OutputTableHeader(kTimeInQueueTableTitles, kTimeInQueueTableColumnWidths);
histogram = otThreadGetTimeInQueueHistogram(GetInstancePtr(), &numBins, &binInterval);
for (uint16_t index = 0; index < numBins; index++)
{
OutputFormat("| %4lu | ", ToUlong(index * binInterval));
if (index < numBins - 1)
{
OutputFormat("%4lu", ToUlong((index + 1) * binInterval - 1));
}
else
{
OutputFormat("%4s", "inf");
}
OutputLine(" | %7lu |", ToUlong(histogram[index]));
}
}
/**
* @cli timeinqueue max
* @code
* timeinqueue max
* 281
* Done
* @endcode
* @par api_copy
* #otThreadGetMaxTimeInQueue
* @csa{timeinqueue reset}
*/
else if (aArgs[0] == "max")
{
OutputLine("%lu", ToUlong(otThreadGetMaxTimeInQueue(GetInstancePtr())));
}
/**
* @cli timeinqueue reset
* @code
* timeinqueue reset
* Done
* @endcode
* @par api_copy
* #otThreadResetTimeInQueueStat
*/
else if (aArgs[0] == "reset")
{
otThreadResetTimeInQueueStat(GetInstancePtr());
}
else
{
error = OT_ERROR_INVALID_ARGS;
}
return error;
}
#endif // OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_ENABLE
template <> otError Interpreter::Process<Cmd("dataset")>(Arg aArgs[]) { return mDataset.Process(aArgs); }
template <> otError Interpreter::Process<Cmd("txpower")>(Arg aArgs[])
@@ -7988,6 +8121,9 @@ otError Interpreter::ProcessCommand(Arg aArgs[])
CmdEntry("tcp"),
#endif
CmdEntry("thread"),
#if OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_ENABLE
CmdEntry("timeinqueue"),
#endif
#if OPENTHREAD_CONFIG_RADIO_LINK_TREL_ENABLE
CmdEntry("trel"),
#endif
+20
View File
@@ -430,6 +430,26 @@ const otIpCounters *otThreadGetIp6Counters(otInstance *aInstance)
void otThreadResetIp6Counters(otInstance *aInstance) { AsCoreType(aInstance).Get<MeshForwarder>().ResetCounters(); }
#if OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_ENABLE
const uint32_t *otThreadGetTimeInQueueHistogram(otInstance *aInstance, uint16_t *aNumBins, uint32_t *aBinInterval)
{
AssertPointerIsNotNull(aNumBins);
AssertPointerIsNotNull(aBinInterval);
return AsCoreType(aInstance).Get<MeshForwarder>().GetTimeInQueueHistogram(*aNumBins, *aBinInterval);
}
uint32_t otThreadGetMaxTimeInQueue(otInstance *aInstance)
{
return AsCoreType(aInstance).Get<MeshForwarder>().GetMaxTimeInQueue();
}
void otThreadResetTimeInQueueStat(otInstance *aInstance)
{
return AsCoreType(aInstance).Get<MeshForwarder>().ResetTimeInQueueStat();
}
#endif
const otMleCounters *otThreadGetMleCounters(otInstance *aInstance)
{
return &AsCoreType(aInstance).Get<Mle::MleRouter>().GetCounters();
+52
View File
@@ -34,6 +34,8 @@
#ifndef CONFIG_MESH_FORWARDER_H_
#define CONFIG_MESH_FORWARDER_H_
#include "config/border_router.h"
/**
* @def OPENTHREAD_CONFIG_DROP_MESSAGE_ON_FRAGMENT_TX_FAILURE
*
@@ -148,4 +150,54 @@
#endif
#endif
/**
* @def OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_ENABLE
*
* Define as 1 to enable TX queue time-in-queue statistics collection feature.
*
* When enabled, histogram of the time-in-queue of messages in the transmit queue is collected. The time-in-queue is
* tracked for direct transmissions only and is measured as the duration from when a message is added to the transmit
* queue until it is passed to the MAC layer for transmission or dropped.
*
* The histogram data consists of number of bins, each representing a range of time-in-queue values. The bin interval
* length is specified by the `OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_HISTOGRAM_BIN_INTERVAL` configuration, and the
* maximum tracked interval is given by the `OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_HISTOGRAM_MAX_INTERVAL`.
*
* Along with histogram, the maximum observed time-in-queue is also tracked.
*
*/
#ifndef OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_ENABLE
#define OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_ENABLE (OPENTHREAD_CONFIG_BORDER_ROUTER_ENABLE && OPENTHREAD_FTD)
#endif
/**
* @def OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_HISTOGRAM_MAX_INTERVAL
*
* Specifies the maximum time-in-queue interval in milliseconds tracked by the histogram when the TX queue time-in-queue
* statistics collection feature is enabled.
*
* By default the `OPENTHREAD_CONFIG_DELAY_AWARE_QUEUE_MANAGEMENT_MARK_ECN_INTERVAL` is used which defines the
* maximum time-in-queue interval after which a non-ECN capable message is dropped by delay-aware queue management
* feature.
*
*/
#ifndef OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_HISTOGRAM_MAX_INTERVAL
#define OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_HISTOGRAM_MAX_INTERVAL \
OPENTHREAD_CONFIG_DELAY_AWARE_QUEUE_MANAGEMENT_MARK_ECN_INTERVAL
#endif
/**
* @def OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_HISTOGRAM_BIN_INTERVAL
*
* Specifies the time-in-queue histogram bin interval in milliseconds when the TX queue time-in-queue statistics
* collection feature is enabled.
*
* The number of bins is calculated by dividing `OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_HISTOGRAM_MAX_INTERVAL` by
* `OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_HISTOGRAM_BIN_INTERVAL` and rounding up to the nearest integer.
*
*/
#ifndef OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_HISTOGRAM_BIN_INTERVAL
#define OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_HISTOGRAM_BIN_INTERVAL 10
#endif
#endif // CONFIG_MESH_FORWARDER_H_
+30
View File
@@ -132,6 +132,10 @@ MeshForwarder::MeshForwarder(Instance &aInstance)
#if OPENTHREAD_FTD
mFragmentPriorityList.Clear();
#endif
#if OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_ENABLE
mTxQueueStats.Clear();
#endif
}
void MeshForwarder::Start(void)
@@ -380,6 +384,9 @@ Error MeshForwarder::UpdateEcnOrDrop(Message &aMessage, bool aPreparingToSend)
exit:
if (error == kErrorDrop)
{
#if OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_ENABLE
mTxQueueStats.UpdateFor(aMessage);
#endif
LogMessage(kMessageQueueMgmtDrop, aMessage);
aMessage.ClearDirectTransmission();
RemoveMessageIfNoPendingTx(aMessage);
@@ -503,6 +510,23 @@ exit:
#endif // (OPENTHREAD_CONFIG_MAX_FRAMES_IN_DIRECT_TX_QUEUE > 0)
#if OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_ENABLE
const uint32_t *MeshForwarder::TxQueueStats::GetHistogram(uint16_t &aNumBins, uint32_t &aBinInterval) const
{
aNumBins = kNumHistBins;
aBinInterval = kHistBinInterval;
return mHistogram;
}
void MeshForwarder::TxQueueStats::UpdateFor(const Message &aMessage)
{
uint32_t timeInQueue = TimerMilli::GetNow() - aMessage.GetTimestamp();
mHistogram[Min<uint32_t>(timeInQueue / kHistBinInterval, kNumHistBins - 1)]++;
mMaxInterval = Max(mMaxInterval, timeInQueue);
}
#endif
void MeshForwarder::ScheduleTransmissionTask(void)
{
VerifyOrExit(!mSendBusy && !mTxPaused);
@@ -585,6 +609,9 @@ Message *MeshForwarder::PrepareNextDirectTransmission(void)
switch (error)
{
case kErrorNone:
#if OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_ENABLE
mTxQueueStats.UpdateFor(*curMessage);
#endif
ExitNow();
#if OPENTHREAD_FTD
@@ -594,6 +621,9 @@ Message *MeshForwarder::PrepareNextDirectTransmission(void)
#endif
default:
#if OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_ENABLE
mTxQueueStats.UpdateFor(*curMessage);
#endif
LogMessage(kMessageDrop, *curMessage, error);
mSendQueue.DequeueAndFree(*curMessage);
continue;
+71
View File
@@ -311,6 +311,55 @@ public:
*/
void ResetCounters(void) { memset(&mIpCounters, 0, sizeof(mIpCounters)); }
#if OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_ENABLE
/**
* Gets the time-in-queue histogram for messages in the TX queue.
*
* Histogram of the time-in-queue of messages in the transmit queue is collected. The time-in-queue is tracked for
* direct transmissions only and is measured as the duration from when a message is added to the transmit queue
* until it is passed to the MAC layer for transmission or dropped.
*
* The histogram is returned as an array of `uint32_t` values with `aNumBins` entries. The first entry in the array
* (at index 0) represents the number of messages with a time-in-queue less than `aBinInterval`. The second entry
* represents the number of messages with a time-in-queue greater than or equal to `aBinInterval`, but less than
* `2 * aBinInterval`. And so on. The last entry represents the number of messages with time-in-queue greater than
* or * equal to `(aNumBins - 1) * aBinInterval`.
*
* The collected statistics can be reset by calling `ResetTimeInQueueStat()`. The histogram information is
* collected since the OpenThread instance was initialized or since the last time statistics collection was reset
* by calling the `ResetTimeInQueueStat()`.
*
* @param[out] aNumBins Reference to return the number of bins in histogram (array length).
* @param[out] aBinInterval Reference to return the histogram bin interval length in milliseconds.
*
* @returns A pointer to an array of @p aNumBins entries representing the collected histogram info.
*
*/
const uint32_t *GetTimeInQueueHistogram(uint16_t &aNumBins, uint32_t &aBinInterval) const
{
return mTxQueueStats.GetHistogram(aNumBins, aBinInterval);
}
/**
* Gets the maximum time-in-queue for messages in the TX queue.
*
* The time-in-queue is tracked for direct transmissions only and is measured as the duration from when a message
* is added to the transmit queue until it is passed to the MAC layer for transmission or dropped.
*
* The collected statistics can be reset by calling `ResetTimeInQueueStat()`.
*
* @returns The maximum time-in-queue in milliseconds for all messages in the TX queue (so far).
*
*/
uint32_t GetMaxTimeInQueue(void) const { return mTxQueueStats.GetMaxInterval(); }
/**
* Resets the TX queue time-in-queue statistics.
*
*/
void ResetTimeInQueueStat(void) { mTxQueueStats.Clear(); }
#endif
#if OPENTHREAD_CONFIG_RADIO_LINK_TREL_ENABLE
/**
* Handles a deferred ack.
@@ -432,6 +481,24 @@ private:
};
#endif // OPENTHREAD_FTD
#if OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_ENABLE
class TxQueueStats : public Clearable<TxQueueStats>
{
public:
const uint32_t *GetHistogram(uint16_t &aNumBins, uint32_t &aBinInterval) const;
uint32_t GetMaxInterval(void) const { return mMaxInterval; }
void UpdateFor(const Message &aMessage);
private:
static constexpr uint32_t kHistMaxInterval = OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_HISTOGRAM_MAX_INTERVAL;
static constexpr uint32_t kHistBinInterval = OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_HISTOGRAM_BIN_INTERVAL;
static constexpr uint16_t kNumHistBins = (kHistMaxInterval + kHistBinInterval - 1) / kHistBinInterval;
uint32_t mMaxInterval;
uint32_t mHistogram[kNumHistBins];
};
#endif
void SendIcmpErrorIfDstUnreach(const Message &aMessage, const Mac::Addresses &aMacAddrs);
Error CheckReachability(const FrameData &aFrameData, const Mac::Addresses &aMeshAddrs);
void UpdateRoutes(const FrameData &aFrameData, const Mac::Addresses &aMeshAddrs);
@@ -603,6 +670,10 @@ private:
#endif
DataPollSender mDataPollSender;
#if OPENTHREAD_CONFIG_TX_QUEUE_STATISTICS_ENABLE
TxQueueStats mTxQueueStats;
#endif
};
/**