From 8c73c9747b36e56a7ea1d83ed17c55f45b3c9332 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tob=C3=ADas=20Lifschitz?= Date: Sat, 22 Oct 2022 01:26:41 -0300 Subject: [PATCH] [mle] add time tracking to mle roles (#8312) A useful metric for a device is the amount of time it spends in each mle role. This could help to identify connectivity issues on SED with weak signal and frequent detaches by checking the time spent in detached mode. It would also be useful to know the time spent in leader state when having multiple FTDs frequently joining and splitting in different partitions. This information is not available from the role counters, since time spent in each state is not related to the number of entries to that state. This commit adds mle counters to track time spent in each role, when uptime feature is enabled (`OPENTHREAD_CONFIG_UPTIME_ENABLE=1`). --- include/openthread/instance.h | 2 +- include/openthread/thread.h | 13 +++++++++++++ src/cli/README.md | 8 ++++++++ src/cli/cli.cpp | 21 +++++++++++++++++++++ src/core/thread/mle.cpp | 35 +++++++++++++++++++++++++++++++++++ src/core/thread/mle.hpp | 16 ++++++++++++++-- tools/otci/tests/test_otci.py | 2 +- 7 files changed, 93 insertions(+), 4 deletions(-) diff --git a/include/openthread/instance.h b/include/openthread/instance.h index fac04a1b3..f7953179a 100644 --- a/include/openthread/instance.h +++ b/include/openthread/instance.h @@ -53,7 +53,7 @@ extern "C" { * @note This number versions both OpenThread platform and user APIs. * */ -#define OPENTHREAD_API_VERSION (253) +#define OPENTHREAD_API_VERSION (254) /** * @addtogroup api-instance diff --git a/include/openthread/thread.h b/include/openthread/thread.h index 1a61fdd2a..15ae8377c 100644 --- a/include/openthread/thread.h +++ b/include/openthread/thread.h @@ -175,6 +175,19 @@ typedef struct otMleCounters uint16_t mPartitionIdChanges; ///< Number of changes to partition ID. uint16_t mBetterPartitionAttachAttempts; ///< Number of attempts to attach to a better partition. + /** + * Role time tracking. + * + * When uptime feature is enabled (OPENTHREAD_CONFIG_UPTIME_ENABLE = 1) time spent in each MLE role is tracked. + * + */ + uint64_t mDisabledTime; ///< Number of milliseconds device has been in OT_DEVICE_ROLE_DISABLED role. + uint64_t mDetachedTime; ///< Number of milliseconds device has been in OT_DEVICE_ROLE_DETACHED role. + uint64_t mChildTime; ///< Number of milliseconds device has been in OT_DEVICE_ROLE_CHILD role. + uint64_t mRouterTime; ///< Number of milliseconds device has been in OT_DEVICE_ROLE_ROUTER role. + uint64_t mLeaderTime; ///< Number of milliseconds device has been in OT_DEVICE_ROLE_LEADER role. + uint64_t mTrackedTime; ///< Number of milliseconds tracked by previous counters. + /** * Number of times device changed its parent. * diff --git a/src/cli/README.md b/src/cli/README.md index 500326689..241705ef5 100644 --- a/src/cli/README.md +++ b/src/cli/README.md @@ -844,6 +844,8 @@ Done Get the counter value. +Note: `OPENTHREAD_CONFIG_UPTIME_ENABLE` is required for MLE role time tracking in `counters mle` + ```bash > counters mac TxTotal: 10 @@ -888,6 +890,12 @@ Attach Attempts: 1 Partition Id Changes: 1 Better Partition Attach Attempts: 0 Parent Changes: 0 +Time Disabled Milli: 10026 +Time Detached Milli: 6852 +Time Child Milli: 0 +Time Router Milli: 0 +Time Leader Milli: 16195 +Time Tracked Milli: 33073 Done > counters ip TxSuccess: 10 diff --git a/src/cli/cli.cpp b/src/cli/cli.cpp index f09866b7d..4d0054b62 100644 --- a/src/cli/cli.cpp +++ b/src/cli/cli.cpp @@ -2635,6 +2635,27 @@ template <> otError Interpreter::Process(Arg aArgs[]) { OutputLine("%s: %d", counter.mName, mleCounters->*counter.mValuePtr); } +#if OPENTHREAD_CONFIG_UPTIME_ENABLE + { + struct MleTimeCounterName + { + const uint64_t otMleCounters::*mValuePtr; + const char * mName; + }; + + static const MleTimeCounterName kTimeCounterNames[] = { + {&otMleCounters::mDisabledTime, "Disabled"}, {&otMleCounters::mDetachedTime, "Detached"}, + {&otMleCounters::mChildTime, "Child"}, {&otMleCounters::mRouterTime, "Router"}, + {&otMleCounters::mLeaderTime, "Leader"}, + }; + + for (const MleTimeCounterName &counter : kTimeCounterNames) + { + OutputLine("Time %s Milli: %lu", counter.mName, mleCounters->*counter.mValuePtr); + } + OutputLine("Time Tracked Milli: %lu", mleCounters->mTrackedTime); + } +#endif } /** * @cli counters mle reset diff --git a/src/core/thread/mle.cpp b/src/core/thread/mle.cpp index ad3edf291..61530d826 100644 --- a/src/core/thread/mle.cpp +++ b/src/core/thread/mle.cpp @@ -264,6 +264,37 @@ exit: } } +#if OPENTHREAD_CONFIG_UPTIME_ENABLE +void Mle::UpdateRoleTimeCounters(DeviceRole aRole) +{ + uint64_t currentUptimeMsec = Get().GetUptime(); + uint64_t durationMsec = currentUptimeMsec - mLastUpdatedTimestamp; + + mLastUpdatedTimestamp = currentUptimeMsec; + + mCounters.mTrackedTime += durationMsec; + + switch (aRole) + { + case kRoleDisabled: + mCounters.mDisabledTime += durationMsec; + break; + case kRoleDetached: + mCounters.mDetachedTime += durationMsec; + break; + case kRoleChild: + mCounters.mChildTime += durationMsec; + break; + case kRoleRouter: + mCounters.mRouterTime += durationMsec; + break; + case kRoleLeader: + mCounters.mLeaderTime += durationMsec; + break; + } +} +#endif + void Mle::SetRole(DeviceRole aRole) { DeviceRole oldRole = mRole; @@ -272,6 +303,10 @@ void Mle::SetRole(DeviceRole aRole) LogNote("Role %s -> %s", RoleToString(oldRole), RoleToString(mRole)); +#if OPENTHREAD_CONFIG_UPTIME_ENABLE + UpdateRoleTimeCounters(oldRole); +#endif + switch (mRole) { case kRoleDisabled: diff --git a/src/core/thread/mle.hpp b/src/core/thread/mle.hpp index 3e42a1bf5..b84cfed75 100644 --- a/src/core/thread/mle.hpp +++ b/src/core/thread/mle.hpp @@ -598,7 +598,13 @@ public: * @returns A reference to the MLE counters. * */ - const otMleCounters &GetCounters(void) const { return mCounters; } + const otMleCounters &GetCounters(void) + { +#if OPENTHREAD_CONFIG_UPTIME_ENABLE + UpdateRoleTimeCounters(mRole); +#endif + return mCounters; + } /** * This method resets the MLE counters. @@ -1983,6 +1989,10 @@ private: static const char *MessageTypeActionToSuffixString(MessageType aType, MessageAction aAction); #endif +#if OPENTHREAD_CONFIG_UPTIME_ENABLE + void UpdateRoleTimeCounters(DeviceRole aRole); +#endif + using DetachGracefullyTimer = TimerMilliIn; MessageQueue mDelayedResponses; @@ -2024,7 +2034,9 @@ private: #endif otMleCounters mCounters; - +#if OPENTHREAD_CONFIG_UPTIME_ENABLE + uint64_t mLastUpdatedTimestamp; +#endif static const otMeshLocalPrefix sMeshLocalPrefixInit; Ip6::Netif::UnicastAddress mLinkLocal64; diff --git a/tools/otci/tests/test_otci.py b/tools/otci/tests/test_otci.py index b252cb496..ad4b25f52 100644 --- a/tools/otci/tests/test_otci.py +++ b/tools/otci/tests/test_otci.py @@ -243,7 +243,7 @@ class TestOTCI(unittest.TestCase): for counter_name in leader.counter_names: logging.info('counter %s: %r', counter_name, leader.get_counter(counter_name)) leader.reset_counter(counter_name) - self.assertTrue(all(x == 0 for x in leader.get_counter(counter_name).values())) + self.assertTrue(all(x == 0 for name, x in leader.get_counter(counter_name).items() if "Time" not in name)) logging.info("CSL config: %r", leader.get_csl_config()) leader.config_csl(channel=13, period=100, timeout=200)