Measure duration

scripts/tools/check_includes_config.py

@@ -117,6 +117,7 @@
 
     # Only uses <chrono> for zero-cost types.
     'src/system/SystemClock.h': {'chrono'},
+    'src/system/DurationTimer.h': {'string'},
     'src/platform/mbed/MbedEventTimeout.h': {'chrono'},
 
     'src/app/app-platform/ContentApp.h': {'list', 'string'},

src/app/CASESessionManager.cpp

@@ -18,6 +18,7 @@
 
 #include <app/CASESessionManager.h>
 #include <lib/address_resolve/AddressResolve.h>
+#include <system/DurationTimer.h>
 
 namespace chip {
 
@@ -37,6 +38,10 @@ void CASESessionManager::FindOrEstablishSession(const ScopedNodeId & peerId, Cal
 #endif // CHIP_DEVICE_CONFIG_ENABLE_AUTOMATIC_CASE_RETRIES
 )
 {
+
+    chip::timing::DurationTimer timer = chip::timing::GetDefaultTimingInstance( "CASESessionManager: FindOrEstablishSession" );
+    timer.start();
+
     ChipLogDetail(CASESessionManager, "FindOrEstablishSession: PeerId = [%d:" ChipLogFormatX64 "]", peerId.GetFabricIndex(),
                   ChipLogValueX64(peerId.GetNodeId()));
 
@@ -67,6 +72,8 @@ void CASESessionManager::FindOrEstablishSession(const ScopedNodeId & peerId, Cal
 #endif // CHIP_DEVICE_CONFIG_ENABLE_AUTOMATIC_CASE_RETRIES
 
     session->Connect(onConnection, onFailure);
+
+    timer.stop();
 }
 
 void CASESessionManager::ReleaseSessionsForFabric(FabricIndex fabricIndex)

src/app/clusters/network-commissioning/network-commissioning.cpp

@@ -32,6 +32,7 @@
 #include <platform/PlatformManager.h>
 #include <platform/internal/DeviceNetworkInfo.h>
 #include <tracing/macros.h>
+#include <system/DurationTimer.h>
 
 using namespace chip;
 using namespace chip::app;
@@ -79,6 +80,7 @@ void Instance::Shutdown()
 
 void Instance::InvokeCommand(HandlerContext & ctxt)
 {
+
     if (mAsyncCommandHandle.Get() != nullptr)
     {
         // We have a command processing in the backend, reject all incoming commands.
@@ -129,6 +131,8 @@ void Instance::InvokeCommand(HandlerContext & ctxt)
             ctxt, [this](HandlerContext & ctx, const auto & req) { HandleReorderNetwork(ctx, req); });
         return;
     }
+
+
 }
 
 CHIP_ERROR Instance::Read(const ConcreteReadAttributePath & aPath, AttributeValueEncoder & aEncoder)
@@ -216,6 +220,8 @@ CHIP_ERROR Instance::Write(const ConcreteDataAttributePath & aPath, AttributeVal
 void Instance::OnNetworkingStatusChange(NetworkCommissioning::Status aCommissioningError, Optional<ByteSpan> aNetworkId,
                                         Optional<int32_t> aConnectStatus)
 {
+    chip::timing::DurationTimer timer = chip::timing::GetDefaultTimingInstance( "NetworkCommissioning: OnNetworkingStatusChange ");
+    timer.start();
     if (aNetworkId.HasValue() && aNetworkId.Value().size() > kMaxNetworkIDLen)
     {
         ChipLogError(DeviceLayer, "Invalid network id received when calling OnNetworkingStatusChange");
@@ -239,10 +245,13 @@ void Instance::OnNetworkingStatusChange(NetworkCommissioning::Status aCommission
     {
         mLastConnectErrorValue.SetNull();
     }
+    timer.stop();
 }
 
 void Instance::HandleScanNetworks(HandlerContext & ctx, const Commands::ScanNetworks::DecodableType & req)
 {
+    chip::timing::DurationTimer timer = chip::timing::GetDefaultTimingInstance( "NetworkCommissioning: HandleScanNetwork ");
+    timer.start();
     MATTER_TRACE_SCOPE("HandleScanNetwork", "NetworkCommissioning");
     if (mFeatureFlags.Has(Feature::kWiFiNetworkInterface))
     {
@@ -282,6 +291,7 @@ void Instance::HandleScanNetworks(HandlerContext & ctx, const Commands::ScanNetw
     {
         ctx.mCommandHandler.AddStatus(ctx.mRequestPath, Protocols::InteractionModel::Status::UnsupportedCommand);
     }
+    timer.stop();
 }
 
 namespace {
@@ -315,6 +325,9 @@ bool CheckFailSafeArmed(CommandHandlerInterface::HandlerContext & ctx)
 
 void Instance::HandleAddOrUpdateWiFiNetwork(HandlerContext & ctx, const Commands::AddOrUpdateWiFiNetwork::DecodableType & req)
 {
+    chip::timing::DurationTimer timer = chip::timing::GetDefaultTimingInstance( "NetworkCommissioning: HandleAddOrUpdateWiFiNetwork ");
+    timer.start();
+
     MATTER_TRACE_SCOPE("HandleAddOrUpdateWiFiNetwork", "NetworkCommissioning");
 
     VerifyOrReturn(CheckFailSafeArmed(ctx));
@@ -369,10 +382,13 @@ void Instance::HandleAddOrUpdateWiFiNetwork(HandlerContext & ctx, const Commands
     {
         UpdateBreadcrumb(req.breadcrumb);
     }
+    timer.stop();
 }
 
 void Instance::HandleAddOrUpdateThreadNetwork(HandlerContext & ctx, const Commands::AddOrUpdateThreadNetwork::DecodableType & req)
 {
+    chip::timing::DurationTimer timer = chip::timing::GetDefaultTimingInstance( "NetworkCommissioning: HandleAddOrUpdateThreadNetwork ");
+    timer.start();
     MATTER_TRACE_SCOPE("HandleAddOrUpdateThreadNetwork", "NetworkCommissioning");
 
     VerifyOrReturn(CheckFailSafeArmed(ctx));
@@ -392,6 +408,7 @@ void Instance::HandleAddOrUpdateThreadNetwork(HandlerContext & ctx, const Comman
     {
         UpdateBreadcrumb(req.breadcrumb);
     }
+    timer.stop();
 }
 
 void Instance::UpdateBreadcrumb(const Optional<uint64_t> & breadcrumb)
@@ -410,6 +427,9 @@ void Instance::CommitSavedBreadcrumb()
 
 void Instance::HandleRemoveNetwork(HandlerContext & ctx, const Commands::RemoveNetwork::DecodableType & req)
 {
+    chip::timing::DurationTimer timer = chip::timing::GetDefaultTimingInstance( "NetworkCommissioning: HandleRemoveNetwork ");
+    timer.start();
+
     MATTER_TRACE_SCOPE("HandleRemoveNetwork", "NetworkCommissioning");
 
     VerifyOrReturn(CheckFailSafeArmed(ctx));
@@ -428,10 +448,15 @@ void Instance::HandleRemoveNetwork(HandlerContext & ctx, const Commands::RemoveN
     {
         UpdateBreadcrumb(req.breadcrumb);
     }
+
+    timer.stop();
 }
 
 void Instance::HandleConnectNetwork(HandlerContext & ctx, const Commands::ConnectNetwork::DecodableType & req)
 {
+    chip::timing::DurationTimer timer = chip::timing::GetDefaultTimingInstance( "NetworkCommissioning: HandleConnectNetwork ");
+    timer.start();
+
     MATTER_TRACE_SCOPE("HandleConnectNetwork", "NetworkCommissioning");
     if (req.networkID.size() > DeviceLayer::NetworkCommissioning::kMaxNetworkIDLen)
     {
@@ -446,10 +471,15 @@ void Instance::HandleConnectNetwork(HandlerContext & ctx, const Commands::Connec
     mAsyncCommandHandle         = CommandHandler::Handle(&ctx.mCommandHandler);
     mCurrentOperationBreadcrumb = req.breadcrumb;
     mpWirelessDriver->ConnectNetwork(req.networkID, this);
+
+    timer.stop();
 }
 
 void Instance::HandleReorderNetwork(HandlerContext & ctx, const Commands::ReorderNetwork::DecodableType & req)
 {
+    chip::timing::DurationTimer timer = chip::timing::GetDefaultTimingInstance( "NetworkCommissioning: HandleReorderNetwork ");
+    timer.start();
+
     MATTER_TRACE_SCOPE("HandleReorderNetwork", "NetworkCommissioning");
     Commands::NetworkConfigResponse::Type response;
     MutableCharSpan debugText;
@@ -464,6 +494,7 @@ void Instance::HandleReorderNetwork(HandlerContext & ctx, const Commands::Reorde
     {
         UpdateBreadcrumb(req.breadcrumb);
     }
+    timer.stop();
 }
 
 void Instance::OnResult(Status commissioningError, CharSpan debugText, int32_t interfaceStatus)

src/app/clusters/operational-credentials-server/operational-credentials-server.cpp

@@ -49,6 +49,7 @@
 #include <platform/CHIPDeviceLayer.h>
 #include <string.h>
 #include <tracing/macros.h>
+#include <system/DurationTimer.h>
 
 using namespace chip;
 using namespace ::chip::Transport;
@@ -413,6 +414,9 @@ bool emberAfOperationalCredentialsClusterRemoveFabricCallback(app::CommandHandle
     ChipLogProgress(Zcl, "OpCreds: Received a RemoveFabric Command for FabricIndex 0x%x",
                     static_cast<unsigned>(fabricBeingRemoved));
 
+    chip::timing::DurationTimer timer = chip::timing::GetDefaultTimingInstance( "OpCreds: RemoveFabric" );
+    timer.start();
+
     if (!IsValidFabricIndex(fabricBeingRemoved))
     {
         ChipLogError(Zcl, "OpCreds: Failed RemoveFabric due to invalid FabricIndex");
@@ -460,6 +464,9 @@ bool emberAfOperationalCredentialsClusterRemoveFabricCallback(app::CommandHandle
             CleanupSessionsForFabric(*sessionManager, fabricBeingRemoved);
         }
     }
+
+    timer.stop();
+
     return true;
 }
 
@@ -475,6 +482,9 @@ bool emberAfOperationalCredentialsClusterUpdateFabricLabelCallback(app::CommandH
 
     ChipLogProgress(Zcl, "OpCreds: Received an UpdateFabricLabel command");
 
+    chip::timing::DurationTimer timer = chip::timing::GetDefaultTimingInstance( "OpCreds: UpdateFabricLabel" );
+    timer.start();
+
     if (label.size() > 32)
     {
         ChipLogError(Zcl, "OpCreds: Failed UpdateFabricLabel due to invalid label size %u", static_cast<unsigned>(label.size()));
@@ -513,6 +523,9 @@ bool emberAfOperationalCredentialsClusterUpdateFabricLabelCallback(app::CommandH
     {
         commandObj->AddStatus(commandPath, finalStatus);
     }
+
+    timer.stop();
+
     return true;
 }
 
@@ -616,6 +629,9 @@ bool emberAfOperationalCredentialsClusterAddNOCCallback(app::CommandHandler * co
 
     ChipLogProgress(Zcl, "OpCreds: Received an AddNOC command");
 
+    chip::timing::DurationTimer timer = chip::timing::GetDefaultTimingInstance( "OpCreds: AddNOC" );
+    timer.start();
+
     VerifyOrExit(NOCValue.size() <= Credentials::kMaxCHIPCertLength, nonDefaultStatus = Status::InvalidCommand);
     VerifyOrExit(!ICACValue.HasValue() || ICACValue.Value().size() <= Credentials::kMaxCHIPCertLength,
                  nonDefaultStatus = Status::InvalidCommand);
@@ -756,6 +772,8 @@ bool emberAfOperationalCredentialsClusterAddNOCCallback(app::CommandHandler * co
         ChipLogError(Zcl, "OpCreds: Failed AddNOC request with IM error 0x%02x", to_underlying(nonDefaultStatus));
     }
 
+    timer.stop();
+
     return true;
 }
 
@@ -775,6 +793,9 @@ bool emberAfOperationalCredentialsClusterUpdateNOCCallback(app::CommandHandler *
 
     ChipLogProgress(Zcl, "OpCreds: Received an UpdateNOC command");
 
+    chip::timing::DurationTimer timer = chip::timing::GetDefaultTimingInstance( "OpCreds: UpdateNOC" );
+    timer.start();
+
     auto & fabricTable            = Server::GetInstance().GetFabricTable();
     auto & failSafeContext        = Server::GetInstance().GetFailSafeContext();
     const FabricInfo * fabricInfo = RetrieveCurrentFabric(commandObj);
@@ -848,13 +869,19 @@ bool emberAfOperationalCredentialsClusterUpdateNOCCallback(app::CommandHandler *
         ChipLogError(Zcl, "OpCreds: Failed UpdateNOC request with IM error 0x%02x", to_underlying(nonDefaultStatus));
     }
 
+    timer.stop();
+
     return true;
 }
 
 bool emberAfOperationalCredentialsClusterCertificateChainRequestCallback(
     app::CommandHandler * commandObj, const app::ConcreteCommandPath & commandPath,
     const Commands::CertificateChainRequest::DecodableType & commandData)
 {
+
+    chip::timing::DurationTimer timer = chip::timing::GetDefaultTimingInstance( "OpCreds: Certificate Chain" );
+    timer.start();
+
     MATTER_TRACE_SCOPE("CertificateChainRequest", "OperationalCredentials");
     auto & certificateType = commandData.certificateType;
 
@@ -896,13 +923,19 @@ bool emberAfOperationalCredentialsClusterCertificateChainRequestCallback(
         commandObj->AddStatus(commandPath, Status::Failure);
     }
 
+    timer.stop();
+
     return true;
 }
 
 bool emberAfOperationalCredentialsClusterAttestationRequestCallback(app::CommandHandler * commandObj,
                                                                     const app::ConcreteCommandPath & commandPath,
                                                                     const Commands::AttestationRequest::DecodableType & commandData)
 {
+
+    chip::timing::DurationTimer timer = chip::timing::GetDefaultTimingInstance( "OpCreds: AttestationRequest" );
+    timer.start();
+
     MATTER_TRACE_SCOPE("AttestationRequest", "OperationalCredentials");
     auto & attestationNonce = commandData.attestationNonce;
 
@@ -992,13 +1025,19 @@ bool emberAfOperationalCredentialsClusterAttestationRequestCallback(app::Command
                      to_underlying(finalStatus), err.Format());
     }
 
+    timer.stop();
+
     return true;
 }
 
 bool emberAfOperationalCredentialsClusterCSRRequestCallback(app::CommandHandler * commandObj,
                                                             const app::ConcreteCommandPath & commandPath,
                                                             const Commands::CSRRequest::DecodableType & commandData)
 {
+
+    chip::timing::DurationTimer timer = chip::timing::GetDefaultTimingInstance( "OpCreds: CSRRequest" );
+    timer.start();
+
     MATTER_TRACE_SCOPE("CSRRequest", "OperationalCredentials");
     ChipLogProgress(Zcl, "OpCreds: Received a CSRRequest command");
 
@@ -1127,13 +1166,19 @@ bool emberAfOperationalCredentialsClusterCSRRequestCallback(app::CommandHandler
                      to_underlying(finalStatus), err.Format());
     }
 
+    timer.stop();
+
     return true;
 }
 
 bool emberAfOperationalCredentialsClusterAddTrustedRootCertificateCallback(
     app::CommandHandler * commandObj, const app::ConcreteCommandPath & commandPath,
     const Commands::AddTrustedRootCertificate::DecodableType & commandData)
 {
+
+    chip::timing::DurationTimer timer = chip::timing::GetDefaultTimingInstance( "OpCreds: AddTrustedRootCertificate" );
+    timer.start();
+
     MATTER_TRACE_SCOPE("AddTrustedRootCertificate", "OperationalCredentials");
 
     auto & fabricTable = Server::GetInstance().GetFabricTable();
@@ -1185,5 +1230,7 @@ bool emberAfOperationalCredentialsClusterAddTrustedRootCertificateCallback(
     }
 
     commandObj->AddStatus(commandPath, finalStatus);
+    timer.stop();
+
     return true;
 }

src/app/server/CommissioningWindowManager.cpp

@@ -25,6 +25,7 @@
 #include <platform/CHIPDeviceLayer.h>
 #include <platform/CommissionableDataProvider.h>
 #include <platform/DeviceControlServer.h>
+#include <system/DurationTimer.h>
 
 using namespace chip::app::Clusters;
 using namespace chip::System::Clock;
@@ -234,6 +235,9 @@ CHIP_ERROR CommissioningWindowManager::OpenCommissioningWindow(Seconds16 commiss
 
 CHIP_ERROR CommissioningWindowManager::AdvertiseAndListenForPASE()
 {
+    chip::timing::DurationTimer timer = chip::timing::GetDefaultTimingInstance( "AppServer: AdvertiseAndListenForPASE" );
+    timer.start();
+
     VerifyOrReturnError(mCommissioningTimeoutTimerArmed, CHIP_ERROR_INCORRECT_STATE);
 
     mPairingSession.Clear();
@@ -273,6 +277,7 @@ CHIP_ERROR CommissioningWindowManager::AdvertiseAndListenForPASE()
 
     ReturnErrorOnFailure(StartAdvertisement());
 
+    timer.stop();
     return CHIP_NO_ERROR;
 }
 

src/app/server/Dnssd.cpp

@@ -39,6 +39,7 @@
 #include <system/TimeSource.h>
 
 #include <app/server/Server.h>
+#include <system/DurationTimer.h>
 
 namespace chip {
 namespace app {
@@ -378,6 +379,9 @@ void DnssdServer::StopServer()
 void DnssdServer::StartServer(Dnssd::CommissioningMode mode)
 {
     ChipLogProgress(Discovery, "Updating services using commissioning mode %d", static_cast<int>(mode));
+
+    chip::timing::DurationTimer timer = chip::timing::GetDefaultTimingInstance( "Discover: StartServer " );
+    timer.start();
 
     DeviceLayer::PlatformMgr().AddEventHandler(OnPlatformEventWrapper, 0);
 
@@ -447,6 +451,8 @@ void DnssdServer::StartServer(Dnssd::CommissioningMode mode)
     {
         ChipLogError(Discovery, "Failed to finalize service update: %" CHIP_ERROR_FORMAT, err.Format());
     }
+
+    timer.stop();
 }
 
 #if CHIP_ENABLE_ROTATING_DEVICE_ID && defined(CHIP_DEVICE_CONFIG_ROTATING_DEVICE_ID_UNIQUE_ID)