[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

@@ -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

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.
      *

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

src/cli/cli.cpp

@@ -2635,6 +2635,27 @@ template <> otError Interpreter::Process<Cmd("counters")>(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

src/core/thread/mle.cpp

@@ -264,6 +264,37 @@ exit:
     }
 }
 
+#if OPENTHREAD_CONFIG_UPTIME_ENABLE
+void Mle::UpdateRoleTimeCounters(DeviceRole aRole)
+{
+    uint64_t currentUptimeMsec = Get<Uptime>().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:

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<Mle, &Mle::HandleDetachGracefullyTimer>;
 
     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;

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)