diff --git a/examples/platform/silabs/MatterConfig.cpp b/examples/platform/silabs/MatterConfig.cpp index 3bdac99034..5b29a0af18 100644 --- a/examples/platform/silabs/MatterConfig.cpp +++ b/examples/platform/silabs/MatterConfig.cpp @@ -91,6 +91,13 @@ static chip::DeviceLayer::Internal::Efr32PsaOperationalKeystore gOperationalKeys #include "sl_power_manager.h" #endif +#include +#if MATTER_TRACING_ENABLED +#include +#include +#include +#endif // MATTER_TRACING_ENABLED + /********************************************************** * Defines *********************************************************/ @@ -101,6 +108,11 @@ using namespace ::chip::DeviceLayer; using namespace ::chip::Credentials; using namespace chip::DeviceLayer::Silabs; +#if MATTER_TRACING_ENABLED +using TimeTraceOperation = chip::Tracing::Silabs::TimeTraceOperation; +using SilabsTracer = chip::Tracing::Silabs::SilabsTracer; +#endif // MATTER_TRACING_ENABLED + #if CHIP_ENABLE_OPENTHREAD #include #include @@ -205,6 +217,13 @@ void SilabsMatterConfig::AppInit() sMainTaskHandle = osThreadNew(ApplicationStart, nullptr, &kMainTaskAttr); ChipLogProgress(DeviceLayer, "Starting scheduler"); VerifyOrDie(sMainTaskHandle); // We can't proceed if the Main Task creation failed. + +#if MATTER_TRACING_ENABLED + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kMatterInit); +#endif // MATTER_TRACING_ENABLED +#if MATTER_TRACING_ENABLED + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kBootup); +#endif // MATTER_TRACING_ENABLED GetPlatform().StartScheduler(); // Should never get here. @@ -312,6 +331,11 @@ CHIP_ERROR SilabsMatterConfig::InitMatter(const char * appName) // Init Matter Server and Start Event Loop err = chip::Server::GetInstance().Init(initParams); +#if MATTER_TRACING_ENABLED + static Tracing::Silabs::BackendImpl backend; + Tracing::Register(backend); +#endif // MATTER_TRACING_ENABLED + chip::DeviceLayer::PlatformMgr().UnlockChipStack(); ReturnErrorOnFailure(err); diff --git a/examples/platform/silabs/MatterShell.cpp b/examples/platform/silabs/MatterShell.cpp index 714b579a96..b88a0a21f8 100644 --- a/examples/platform/silabs/MatterShell.cpp +++ b/examples/platform/silabs/MatterShell.cpp @@ -22,6 +22,7 @@ #include #include #include +#include #include #ifdef SL_CATALOG_CLI_PRESENT #include "sl_cli.h" @@ -29,6 +30,10 @@ #include "sli_cli_io.h" #endif +#if MATTER_TRACING_ENABLED +#include +#endif // MATTER_TRACING_ENABLED + using namespace ::chip; using chip::Shell::Engine; @@ -112,6 +117,154 @@ void cmdSilabsInit() #endif // SL_CATALOG_CLI_PRESENT +#if MATTER_TRACING_ENABLED +using TimeTraceOperation = Tracing::Silabs::TimeTraceOperation; + +TimeTraceOperation StringToTimeTraceOperation(const char * str) +{ + if (strcmp(str, "Spake2p") == 0) + { + return TimeTraceOperation::kSpake2p; + } + else if (strcmp(str, "Pake1") == 0) + { + return TimeTraceOperation::kPake1; + } + else if (strcmp(str, "Pake2") == 0) + { + return TimeTraceOperation::kPake2; + } + else if (strcmp(str, "Pake3") == 0) + { + return TimeTraceOperation::kPake3; + } + else if (strcmp(str, "OperationalCredentials") == 0) + { + return TimeTraceOperation::kOperationalCredentials; + } + else if (strcmp(str, "AttestationVerification") == 0) + { + return TimeTraceOperation::kAttestationVerification; + } + else if (strcmp(str, "CSR") == 0) + { + return TimeTraceOperation::kCSR; + } + else if (strcmp(str, "NOC") == 0) + { + return TimeTraceOperation::kNOC; + } + else if (strcmp(str, "TransportLayer") == 0) + { + return TimeTraceOperation::kTransportLayer; + } + else if (strcmp(str, "TransportSetup") == 0) + { + return TimeTraceOperation::kTransportSetup; + } + else if (strcmp(str, "FindOperational") == 0) + { + return TimeTraceOperation::kFindOperational; + } + else if (strcmp(str, "CaseSession") == 0) + { + return TimeTraceOperation::kCaseSession; + } + else if (strcmp(str, "Sigma1") == 0) + { + return TimeTraceOperation::kSigma1; + } + else if (strcmp(str, "Sigma2") == 0) + { + return TimeTraceOperation::kSigma2; + } + else if (strcmp(str, "Sigma3") == 0) + { + return TimeTraceOperation::kSigma3; + } + else if (strcmp(str, "OTA") == 0) + { + return TimeTraceOperation::kOTA; + } + else if (strcmp(str, "ImageUpload") == 0) + { + return TimeTraceOperation::kImageUpload; + } + else if (strcmp(str, "ImageVerification") == 0) + { + return TimeTraceOperation::kImageVerification; + } + else if (strcmp(str, "AppApplyTime") == 0) + { + return TimeTraceOperation::kAppApplyTime; + } + else if (strcmp(str, "Bootup") == 0) + { + return TimeTraceOperation::kBootup; + } + else if (strcmp(str, "SilabsInit") == 0) + { + return TimeTraceOperation::kSilabsInit; + } + else if (strcmp(str, "MatterInit") == 0) + { + return TimeTraceOperation::kMatterInit; + } + else if (strcmp(str, "BufferFull") == 0) + { + return TimeTraceOperation::kBufferFull; + } + else + { + return TimeTraceOperation::kNumTraces; + } +} + +CHIP_ERROR CmdTracingDispatch(int argc, char ** argv) +{ + CHIP_ERROR error = CHIP_NO_ERROR; + + VerifyOrReturnError(argc > 1, error = CHIP_ERROR_INVALID_ARGUMENT); + + if (strcmp(argv[0], "flush") == 0) + { + if (strcmp(argv[1], "all") == 0) + { + error = Tracing::Silabs::SilabsTracer::Instance().TraceBufferFlushAll(); + } + else + { + TimeTraceOperation operation = StringToTimeTraceOperation(argv[1]); + error = Tracing::Silabs::SilabsTracer::Instance().TraceBufferFlushByOperation(operation); + } + } + else if (strcmp(argv[0], "watermarks") == 0) + { + if (strcmp(argv[1], "all") == 0) + { + error = Tracing::Silabs::SilabsTracer::Instance().OutputAllWaterMarks(); + } + else + { + TimeTraceOperation operation = StringToTimeTraceOperation(argv[1]); + error = Tracing::Silabs::SilabsTracer::Instance().OutputWaterMark(operation); + } + } + else + { + error = CHIP_ERROR_INVALID_ARGUMENT; + } + return error; +} +static const Shell::shell_command_t cmds_silabs_tracing = { &CmdTracingDispatch, "tracing", + "Dispatch Silicon Labs Tracing command" }; +void CmdTracingInit() +{ + // Register tracing commands with the top-level shell. + Engine::Root().RegisterCommands(&cmds_silabs_tracing, 2); +} +#endif // MATTER_TRACING_ENABLED + void startShellTask() { int status = chip::Shell::Engine::Root().Init(); @@ -127,6 +280,9 @@ void startShellTask() #ifdef SL_CATALOG_CLI_PRESENT cmdSilabsInit(); #endif +#if MATTER_TRACING_ENABLED + CmdTracingInit(); +#endif // MATTER_TRACING_ENABLED shellTaskHandle = osThreadNew(MatterShellTask, nullptr, &kShellTaskAttr); VerifyOrDie(shellTaskHandle); diff --git a/examples/platform/silabs/efr32/BUILD.gn b/examples/platform/silabs/efr32/BUILD.gn index e0e7b45070..0f55479575 100644 --- a/examples/platform/silabs/efr32/BUILD.gn +++ b/examples/platform/silabs/efr32/BUILD.gn @@ -18,6 +18,7 @@ import("${chip_root}/examples/common/pigweed/pigweed_rpcs.gni") import("${chip_root}/src/app/icd/icd.gni") import("${chip_root}/src/lib/lib.gni") import("${chip_root}/src/platform/device.gni") +import("${chip_root}/src/tracing/tracing_args.gni") import("${silabs_sdk_build_root}/efr32_sdk.gni") import("${silabs_sdk_build_root}/silabs_board.gni") @@ -110,6 +111,9 @@ source_set("matter-shell") { "${chip_root}/src/lib/shell:shell", "${chip_root}/src/lib/shell:shell_core", ] + if (matter_enable_tracing_support) { + public_deps += [ "${chip_root}/src/platform/silabs/tracing:SilabsTracing" ] + } } config("efr32-common-config") { @@ -141,7 +145,10 @@ config("efr32-common-config") { } source_set("efr32-common") { - deps = [ "${silabs_common_plat_dir}/provision:storage" ] + deps = [ + "${chip_root}/src/tracing", + "${silabs_common_plat_dir}/provision:storage", + ] defines = [] public_deps = [] public_configs = [ @@ -233,4 +240,8 @@ source_set("efr32-common") { if (app_data_model != "") { public_deps += [ app_data_model ] } + + if (matter_enable_tracing_support) { + public_deps += [ "${chip_root}/src/platform/silabs/tracing:SilabsTracing" ] + } } diff --git a/examples/platform/silabs/main.cpp b/examples/platform/silabs/main.cpp index d01e27f178..3ba68782df 100644 --- a/examples/platform/silabs/main.cpp +++ b/examples/platform/silabs/main.cpp @@ -21,10 +21,31 @@ #include "sl_system_kernel.h" #include +#include +#if MATTER_TRACING_ENABLED +#include +#endif // MATTER_TRACING_ENABLED + +#if MATTER_TRACING_ENABLED +using TimeTraceOperation = chip::Tracing::Silabs::TimeTraceOperation; +using SilabsTracer = chip::Tracing::Silabs::SilabsTracer; +#endif // MATTER_TRACING_ENABLED + int main(void) { +#if MATTER_TRACING_ENABLED + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kBootup); +#endif // MATTER_TRACING_ENABLED +#if MATTER_TRACING_ENABLED + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSilabsInit); +#endif // MATTER_TRACING_ENABLED sl_system_init(); - +#if MATTER_TRACING_ENABLED + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kSilabsInit); +#endif // MATTER_TRACING_ENABLED +#if MATTER_TRACING_ENABLED + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kMatterInit); +#endif // MATTER_TRACING_ENABLED // Initialize the application. For example, create periodic timer(s) or // task(s) if the kernel is present. SilabsMatterConfig::AppInit(); diff --git a/src/platform/silabs/efr32/BUILD.gn b/src/platform/silabs/efr32/BUILD.gn index f39628d484..920168ce8a 100644 --- a/src/platform/silabs/efr32/BUILD.gn +++ b/src/platform/silabs/efr32/BUILD.gn @@ -17,6 +17,7 @@ import("//build_overrides/chip.gni") import("${chip_root}/build/chip/buildconfig_header.gni") import("${chip_root}/src/crypto/crypto.gni") import("${chip_root}/src/platform/device.gni") +import("${chip_root}/src/tracing/tracing_args.gni") import("${chip_root}/third_party/silabs/efr32_sdk.gni") import("${chip_root}/third_party/silabs/silabs_board.gni") @@ -114,9 +115,17 @@ static_library("efr32") { "${chip_root}/src/platform:platform_base", "${chip_root}/src/platform/logging:headers", ] - deps = [ "${silabs_platform_dir}/provision:provision-headers" ] + deps = [ + "${chip_root}/src/tracing", + "${silabs_platform_dir}/provision:provision-headers", + ] + public_configs = [] + if (matter_enable_tracing_support) { + public_deps += [ "${chip_root}/src/platform/silabs/tracing:SilabsTracing" ] + } + # Add platform crypto implementation if (chip_crypto == "platform") { sources += [ diff --git a/src/platform/silabs/efr32/OTAImageProcessorImpl.cpp b/src/platform/silabs/efr32/OTAImageProcessorImpl.cpp index a0efd10100..0c9addf4de 100644 --- a/src/platform/silabs/efr32/OTAImageProcessorImpl.cpp +++ b/src/platform/silabs/efr32/OTAImageProcessorImpl.cpp @@ -25,6 +25,11 @@ #include #endif // SL_WIFI +#include +#if MATTER_TRACING_ENABLED +#include +#endif // MATTER_TRACING_ENABLED + extern "C" { #include "btl_interface.h" #include "sl_core.h" @@ -51,6 +56,11 @@ static chip::OTAImageProcessorImpl gImageProcessor; namespace chip { +#if MATTER_TRACING_ENABLED +using TimeTraceOperation = chip::Tracing::Silabs::TimeTraceOperation; +using SilabsTracer = chip::Tracing::Silabs::SilabsTracer; +#endif // MATTER_TRACING_ENABLED + // Define static memebers uint8_t OTAImageProcessorImpl::mSlotId = 0; uint32_t OTAImageProcessorImpl::mWriteOffset = 0; @@ -158,12 +168,19 @@ void OTAImageProcessorImpl::HandlePrepareDownload(intptr_t context) ChipLogProgress(SoftwareUpdate, "HandlePrepareDownload: started"); +#if MATTER_TRACING_ENABLED + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kImageUpload); +#endif // MATTER_TRACING_ENABLED + #ifdef _SILICON_LABS_32B_SERIES_2 // TODO sl-temp: bootloader_init is called previously sl_platform_init(). Recalling it for series3 causes a crash. WRAP_BL_DFU_CALL(err = bootloader_init()) if (err != SL_BOOTLOADER_OK) { ChipLogProgress(SoftwareUpdate, "bootloader_init Failed error: %ld", err); +#if MATTER_TRACING_ENABLED + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kImageUpload, CHIP_ERROR_INTERNAL); +#endif // MATTER_TRACING_ENABLED } #endif @@ -205,6 +222,9 @@ void OTAImageProcessorImpl::HandleFinalize(intptr_t context) if (err != SL_STATUS_OK) { ChipLogError(SoftwareUpdate, "sl_wfx_host_pre_bootloader_spi_transfer() error: %ld", err); +#if MATTER_TRACING_ENABLED + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kImageUpload, CHIP_ERROR_INTERNAL); +#endif // MATTER_TRACING_ENABLED return; } #endif // SL_BTLCTRL_MUX @@ -215,6 +235,9 @@ void OTAImageProcessorImpl::HandleFinalize(intptr_t context) if (err != SL_STATUS_OK) { ChipLogError(SoftwareUpdate, "sl_wfx_host_post_bootloader_spi_transfer() error: %ld", err); +#if MATTER_TRACING_ENABLED + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kImageUpload, CHIP_ERROR_INTERNAL); +#endif // MATTER_TRACING_ENABLED return; } #endif // SL_BTLCTRL_MUX @@ -222,6 +245,9 @@ void OTAImageProcessorImpl::HandleFinalize(intptr_t context) { ChipLogError(SoftwareUpdate, "bootloader_eraseWriteStorage() error: %ld", err); imageProcessor->mDownloader->EndDownload(CHIP_ERROR_WRITE_FAILED); +#if MATTER_TRACING_ENABLED + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kImageUpload, CHIP_ERROR_WRITE_FAILED); +#endif // MATTER_TRACING_ENABLED return; } } @@ -229,6 +255,9 @@ void OTAImageProcessorImpl::HandleFinalize(intptr_t context) imageProcessor->ReleaseBlock(); ChipLogProgress(SoftwareUpdate, "OTA image downloaded successfully"); +#if MATTER_TRACING_ENABLED + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kImageUpload); +#endif // MATTER_TRACING_ENABLED } // TODO: SE access is not thread safe. It assert if other tasks accesses it during bootloader_verifyImage or @@ -252,6 +281,9 @@ void OTAImageProcessorImpl::HandleApply(intptr_t context) uint32_t err = SL_BOOTLOADER_OK; ChipLogProgress(SoftwareUpdate, "HandleApply: verifying image"); +#if MATTER_TRACING_ENABLED + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kImageVerification); +#endif // MATTER_TRACING_ENABLED // Force KVS to store pending keys such as data from StoreCurrentUpdateInfo() chip::DeviceLayer::PersistedStorage::KeyValueStoreMgrImpl().ForceKeyMapSave(); @@ -260,6 +292,9 @@ void OTAImageProcessorImpl::HandleApply(intptr_t context) if (err != SL_STATUS_OK) { ChipLogError(SoftwareUpdate, "sl_wfx_host_pre_bootloader_spi_transfer() error: %ld", err); +#if MATTER_TRACING_ENABLED + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kImageVerification, CHIP_ERROR_INTERNAL); +#endif // MATTER_TRACING_ENABLED return; } #endif // SL_BTLCTRL_MUX @@ -282,6 +317,9 @@ void OTAImageProcessorImpl::HandleApply(intptr_t context) ChipLogError(SoftwareUpdate, "sl_wfx_host_post_bootloader_spi_transfer() error: %ld", err); } #endif // SL_BTLCTRL_MUX +#if MATTER_TRACING_ENABLED + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kImageVerification, err); +#endif // MATTER_TRACING_ENABLED return; } ChipLogProgress(SoftwareUpdate, "Image verified, Set image to bootload"); @@ -300,6 +338,9 @@ void OTAImageProcessorImpl::HandleApply(intptr_t context) ChipLogError(SoftwareUpdate, "sl_wfx_host_post_bootloader_spi_transfer() error: %ld", err); } #endif // SL_BTLCTRL_MUX +#if MATTER_TRACING_ENABLED + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kImageVerification, err); +#endif // MATTER_TRACING_ENABLED return; } @@ -308,11 +349,17 @@ void OTAImageProcessorImpl::HandleApply(intptr_t context) if (err != SL_STATUS_OK) { ChipLogError(SoftwareUpdate, "sl_wfx_host_post_bootloader_spi_transfer() error: %ld", err); +#if MATTER_TRACING_ENABLED + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kImageVerification, err); +#endif // MATTER_TRACING_ENABLED return; } #endif // SL_BTLCTRL_MUX ChipLogProgress(SoftwareUpdate, "Reboot and install new image..."); +#if MATTER_TRACING_ENABLED + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kImageVerification); +#endif // MATTER_TRACING_ENABLED #if defined(_SILICON_LABS_32B_SERIES_3) && CHIP_PROGRESS_LOGGING osDelay(100); // sl-temp: delay for uart print before reboot #endif // _SILICON_LABS_32B_SERIES_3 && CHIP_PROGRESS_LOGGING diff --git a/src/platform/silabs/tracing/BUILD.gn b/src/platform/silabs/tracing/BUILD.gn index 78b339d19c..4aa3a78218 100644 --- a/src/platform/silabs/tracing/BUILD.gn +++ b/src/platform/silabs/tracing/BUILD.gn @@ -18,8 +18,14 @@ import("//build_overrides/build.gni") import("//build_overrides/chip.gni") +config("tracing") { + include_dirs = [ "include" ] +} + static_library("SilabsTracing") { sources = [ + "BackendImpl.cpp", + "BackendImpl.h", "SilabsTracing.cpp", "SilabsTracing.h", ] @@ -27,7 +33,14 @@ static_library("SilabsTracing") { deps = [ "${chip_root}/src/lib/core", "${chip_root}/src/lib/support", - "${chip_root}/src/platform", "${chip_root}/src/system", ] + + public_deps = [ "${chip_root}/src/tracing:tracing" ] +} + +source_set("silabs_tracing") { + public = [ "include/matter/tracing/macros_impl.h" ] + public_configs = [ ":tracing" ] + deps = [ ":SilabsTracing" ] } diff --git a/src/platform/silabs/tracing/BackendImpl.cpp b/src/platform/silabs/tracing/BackendImpl.cpp new file mode 100644 index 0000000000..35836011f2 --- /dev/null +++ b/src/platform/silabs/tracing/BackendImpl.cpp @@ -0,0 +1,90 @@ +#include "BackendImpl.h" +#include "SilabsTracing.h" +#include +#include + +namespace chip { +namespace Tracing { +namespace Silabs { + +TimeTraceOperation MapMetricKeyToOperation(MetricKey metricKey) +{ + if (metricKey == kMetricDeviceCommissionerPASESession) + return TimeTraceOperation::kPake1; + if (metricKey == kMetricDeviceCommissionerCommission) + return TimeTraceOperation::kOperationalCredentials; + if (metricKey == kMetricDeviceCommissionerCommissionStage) + return TimeTraceOperation::kTransportSetup; + if (metricKey == kMetricSetupCodePairerPairDevice) + return TimeTraceOperation::kFindOperational; + if (metricKey == kMetricDeviceCommissioningOperationalSetup) + return TimeTraceOperation::kCaseSession; + if (metricKey == kMetricDeviceOperationalDiscovery) + return TimeTraceOperation::kFindOperational; + if (metricKey == kMetricDeviceOperationalDiscoveryAttemptCount) + return TimeTraceOperation::kFindOperational; + if (metricKey == kMetricDeviceCASESession) + return TimeTraceOperation::kCaseSession; + if (metricKey == kMetricDeviceCASESessionSigma1) + return TimeTraceOperation::kSigma1; + if (metricKey == kMetricDeviceCASESessionSigma1Resume) + return TimeTraceOperation::kSigma1; + if (metricKey == kMetricDeviceCASESessionSigma2) + return TimeTraceOperation::kSigma2; + if (metricKey == kMetricDeviceCASESessionSigma3) + return TimeTraceOperation::kSigma3; + if (metricKey == kMetricDeviceCASESessionSigma2Resume) + return TimeTraceOperation::kSigma2; + if (metricKey == kMetricDeviceCASESessionSigmaFinished) + return TimeTraceOperation::kCaseSession; + if (metricKey == kMetricDeviceRMPRetryCount) + return TimeTraceOperation::kTransportLayer; + + return TimeTraceOperation::kNumTraces; +} + +void BackendImpl::TraceBegin(const char * label, const char * group) +{ + SilabsTracer::Instance().TimeTraceBegin(MapMetricKeyToOperation(label)); +} +void BackendImpl::TraceEnd(const char * label, const char * group) +{ + SilabsTracer::Instance().TimeTraceEnd(MapMetricKeyToOperation(label), CHIP_NO_ERROR); +} +void BackendImpl::TraceInstant(const char * label, const char * group) +{ + SilabsTracer::Instance().TimeTraceInstant(MapMetricKeyToOperation(label), CHIP_NO_ERROR); +} + +void BackendImpl::LogMetricEvent(const MetricEvent & event) +{ + Silabs::TimeTraceOperation operation = MapMetricKeyToOperation(event.key()); + CHIP_ERROR err = CHIP_NO_ERROR; + switch (event.ValueType()) + { + case MetricEvent::Value::Type::kChipErrorCode: + err = ChipError(event.ValueErrorCode()); + break; + default: + break; + } + + switch (event.type()) + { + case MetricEvent::Type::kBeginEvent: + SilabsTracer::Instance().TimeTraceBegin(operation); + break; + case MetricEvent::Type::kEndEvent: + SilabsTracer::Instance().TimeTraceEnd(operation, err); + break; + case MetricEvent::Type::kInstantEvent: + SilabsTracer::Instance().TimeTraceInstant(operation, err); + break; + default: + break; + } +} + +} // namespace Silabs +} // namespace Tracing +} // namespace chip diff --git a/src/platform/silabs/tracing/BackendImpl.h b/src/platform/silabs/tracing/BackendImpl.h new file mode 100644 index 0000000000..9b64825bb8 --- /dev/null +++ b/src/platform/silabs/tracing/BackendImpl.h @@ -0,0 +1,73 @@ +/* + * Copyright (c) 2024 Project CHIP Authors + * All rights reserved. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +#pragma once + +#include +#include +#include + +#define _MATTER_TRACE_DISABLE(...) \ + do \ + { \ + } while (false) + +// This gets forwarded to the multiplexed instance +#define MATTER_TRACE_BEGIN(label, group) ::chip::Tracing::Internal::Begin(label, group) +#define MATTER_TRACE_END(label, group) ::chip::Tracing::Internal::End(label, group) +#define MATTER_TRACE_INSTANT(label, group) ::chip::Tracing::Internal::Instant(label, group) +#define MATTER_TRACE_COUNTER(label) ::chip::Tracing::Internal::Counter(label) + +// We are not using this in our current implementation, so we are disabling it. +#define MATTER_TRACE_SCOPE(...) _MATTER_TRACE_DISABLE(__VA_ARGS__) + +namespace chip { +namespace Tracing { +namespace Silabs { + +/** @brief + * Backend implementation for Silabs platform acting as an interface with SilabsTracer and the matter layer. + */ +class BackendImpl : public ::chip::Tracing::Backend +{ +public: + BackendImpl() = default; + // TraceBegin, TraceEnd and TraceInstant are redundant with LogMetricEvent in the usecases that we are trying to track, + // so we are not implementing them at current to avoid duplication of the same information in the trace. We might implement it + // in the future if we want to add new traces that are not related to our metrics measurements + void TraceBegin(const char * label, const char * group) override; + void TraceEnd(const char * label, const char * group) override; + void TraceInstant(const char * label, const char * group) override; + + // Our tracing counter is embedded in our metrics, so we are not implementing it. + void TraceCounter(const char * label) override {} + + // Not implmented yet, might be implemented in the future. + void LogMessageSend(MessageSendInfo &) override {} + void LogMessageReceived(MessageReceivedInfo &) override {} + void LogNodeLookup(NodeLookupInfo &) override {} + void LogNodeDiscovered(NodeDiscoveredInfo &) override {} + void LogNodeDiscoveryFailed(NodeDiscoveryFailedInfo &) override {} + + /** @brief Log a metric event using SilabsTracer interface + * SilabsTracer.Init() needs to be called before this is called. + */ + void LogMetricEvent(const MetricEvent &) override; +}; + +} // namespace Silabs +} // namespace Tracing +} // namespace chip diff --git a/src/platform/silabs/tracing/SilabsTracing.cpp b/src/platform/silabs/tracing/SilabsTracing.cpp index e9940bac02..3d0d1107f6 100644 --- a/src/platform/silabs/tracing/SilabsTracing.cpp +++ b/src/platform/silabs/tracing/SilabsTracing.cpp @@ -20,7 +20,7 @@ #include #if !CONFIG_BUILD_FOR_HOST_UNIT_TEST -#include // for isLogInitialized +#include // for isLogInitialized #endif // The following functions needs to be implemented by the application to allows logging or storing the traces / @@ -120,18 +120,20 @@ int TimeTracker::ToCharArray(MutableByteSpan & buffer) const { case OperationType::kBegin: return snprintf(reinterpret_cast(buffer.data()), buffer.size(), - "TimeTracker - StartTime: %" PRIu32 ", Operation: %s, Type: %s, Error: 0x%" PRIx32, mStartTime.count(), - TimeTraceOperationToString(mOperation), OperationTypeToString(mType), mError.AsInteger()); + "TimeTracker - Type: %s, Operation: %s, Status: 0x%" PRIx32 ", StartTime: %" PRIu32 "", + OperationTypeToString(mType), TimeTraceOperationToString(mOperation), mError.AsInteger(), + mStartTime.count()); case OperationType::kEnd: return snprintf(reinterpret_cast(buffer.data()), buffer.size(), - "TimeTracker - StartTime: %" PRIu32 ", EndTime: %" PRIu32 ", Duration: %" PRIu32 - " ms, Operation: %s, Type: %s, Error: 0x%" PRIx32, - mStartTime.count(), mEndTime.count(), (mEndTime - mStartTime).count(), - TimeTraceOperationToString(mOperation), OperationTypeToString(mType), mError.AsInteger()); + "TimeTracker - Type: %s, Operation: %s, Status: 0x%" PRIx32 ", StartTime: %" PRIu32 ", EndTime: %" PRIu32 + ", Duration: %" PRIu32 " ms", + OperationTypeToString(mType), TimeTraceOperationToString(mOperation), mError.AsInteger(), + mStartTime.count(), mEndTime.count(), (mEndTime - mStartTime).count()); case OperationType::kInstant: return snprintf(reinterpret_cast(buffer.data()), buffer.size(), - "TimeTracker - EventTime: %" PRIu32 ", Operation: %s, Type: %s, Error: 0x%" PRIx32, mStartTime.count(), - TimeTraceOperationToString(mOperation), OperationTypeToString(mType), mError.AsInteger()); + "TimeTracker - Type: %s, Operation: %s, Status: 0x%" PRIx32 ", EventTime: %" PRIu32 "", + OperationTypeToString(mType), TimeTraceOperationToString(mOperation), mError.AsInteger(), + mStartTime.count()); default: return snprintf(reinterpret_cast(buffer.data()), buffer.size(), "TimeTracker - Unknown operation type"); } @@ -237,6 +239,8 @@ CHIP_ERROR SilabsTracer::TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ER CHIP_ERROR SilabsTracer::OutputTimeTracker(const TimeTracker & tracker) { + VerifyOrReturnError(to_underlying(tracker.mOperation) < kNumTraces, CHIP_ERROR_INVALID_ARGUMENT, + ChipLogError(DeviceLayer, "Invalid tracker")); VerifyOrReturnError(isLogInitialized(), CHIP_ERROR_UNINITIALIZED); // Allocate a buffer to store the trace uint8_t buffer[kMaxTraceSize]; @@ -279,16 +283,17 @@ CHIP_ERROR SilabsTracer::OutputTrace(const TimeTracker & tracker) CHIP_ERROR SilabsTracer::OutputWaterMark(TimeTraceOperation aOperation) { - size_t index = static_cast(aOperation); + VerifyOrReturnError(to_underlying(aOperation) < kNumTraces, CHIP_ERROR_INVALID_ARGUMENT, + ChipLogError(DeviceLayer, "Invalid watermark")); + size_t index = to_underlying(aOperation); auto & watermark = mWatermarks[index]; VerifyOrReturnError(isLogInitialized(), CHIP_ERROR_UNINITIALIZED); ChipLogProgress(DeviceLayer, - "Operation: %s, TotalCount=%" PRIu32 ", SuccessFullCount=%" PRIu32 ", MaxTime=%" PRIu32 ", MinTime=%" PRIu32 - ", AvgTime=%" PRIu32 ", CountAboveAvg=%" PRIu32 "", - TimeTraceOperationToString(aOperation), watermark.mTotalCount, watermark.mSuccessfullCount, - watermark.mMaxTimeMs.count(), watermark.mMinTimeMs.count(), watermark.mMovingAverage.count(), - watermark.mCountAboveAvg); + "| Operation: %-25s| MaxTime:%-5" PRIu32 "| MinTime:%-5" PRIu32 "| AvgTime:%-5" PRIu32 "| TotalCount:%-8" PRIu32 + ", SuccessFullCount:%-8" PRIu32 "| CountAboveAvg:%-8" PRIu32 "|", + TimeTraceOperationToString(aOperation), watermark.mMaxTimeMs.count(), watermark.mMinTimeMs.count(), + watermark.mMovingAverage.count(), watermark.mTotalCount, watermark.mSuccessfullCount, watermark.mCountAboveAvg); return CHIP_NO_ERROR; } diff --git a/src/platform/silabs/tracing/SilabsTracing.h b/src/platform/silabs/tracing/SilabsTracing.h index 5bfc912f8c..80f110ce37 100644 --- a/src/platform/silabs/tracing/SilabsTracing.h +++ b/src/platform/silabs/tracing/SilabsTracing.h @@ -151,6 +151,7 @@ class SilabsTracer * @return CHIP_ERROR, returns CHIP_ERROR_BUFFER_TOO_SMALL if the buffer is full */ CHIP_ERROR TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error = CHIP_NO_ERROR); + CHIP_ERROR TimeTraceEnd(TimeTraceOperation aOperation, uint32_t error) { return TimeTraceEnd(aOperation, ChipError((error))); } /** @brief Trace an instant time operation * This calls the OutputTrace method to log the trace if logs are enabled, and stores the time tracker in the buffer if the @@ -160,6 +161,10 @@ class SilabsTracer * @return CHIP_ERROR, returns CHIP_ERROR_BUFFER_TOO_SMALL if the buffer is full */ CHIP_ERROR TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error = CHIP_NO_ERROR); + CHIP_ERROR TimeTraceInstant(TimeTraceOperation aOperation, uint32_t error) + { + return TimeTraceInstant(aOperation, ChipError((error))); + } /** @brief Output a time tracker * This will output the latest time tracker for a specific operation, without affecting the buffer. diff --git a/src/platform/silabs/tracing/include/matter/tracing/macros_impl.h b/src/platform/silabs/tracing/include/matter/tracing/macros_impl.h new file mode 100644 index 0000000000..6a7fa1d292 --- /dev/null +++ b/src/platform/silabs/tracing/include/matter/tracing/macros_impl.h @@ -0,0 +1,23 @@ +/* + * + * Copyright (c) 2024 Project CHIP Authors + * All rights reserved. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +#pragma once + +/* Ensure we do not have double tracing macros defined */ +#if defined(MATTER_TRACE_BEGIN) +#error "Tracing macros seem to be double defined" +#endif diff --git a/src/platform/tests/TestSilabsTracing.cpp b/src/platform/tests/TestSilabsTracing.cpp index 1634b93191..f4a34985fa 100644 --- a/src/platform/tests/TestSilabsTracing.cpp +++ b/src/platform/tests/TestSilabsTracing.cpp @@ -667,14 +667,14 @@ TEST_F(TestSilabsTracing, TestLogs) // Verify OTA log EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kOTA, span), CHIP_NO_ERROR); const char * expectedOTALogFormat = - "TimeTracker - StartTime: 0, EndTime: 100, Duration: 100 ms, Operation: OTA, Type: End, Error: 0x0"; + "TimeTracker - Type: End, Operation: OTA, Status: 0x0, StartTime: 0, EndTime: 100, Duration: 100 ms"; EXPECT_STREQ(reinterpret_cast(span.data()), expectedOTALogFormat); // Verify Bootup log span = MutableByteSpan(logBuffer); EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kBootup, span), CHIP_NO_ERROR); const char * expectedBootupLogFormat = - "TimeTracker - StartTime: 100, EndTime: 300, Duration: 200 ms, Operation: Bootup, Type: End, Error: 0x0"; + "TimeTracker - Type: End, Operation: Bootup, Status: 0x0, StartTime: 100, EndTime: 300, Duration: 200 ms"; EXPECT_STREQ(reinterpret_cast(span.data()), expectedBootupLogFormat); // Test buffer too small behavior @@ -733,7 +733,7 @@ TEST_F(TestSilabsTracing, TestBufferBusting) uint8_t logBuffer[256]; MutableByteSpan logSpan(logBuffer); EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kBufferFull, logSpan), CHIP_NO_ERROR); - const char * expectedNumLogFormat = "TimeTracker - EventTime: 6200, Operation: BufferFull, Type: Instant, Error: 0x19"; + const char * expectedNumLogFormat = "TimeTracker - Type: Instant, Operation: BufferFull, Status: 0x19, EventTime: 6200"; EXPECT_STREQ(reinterpret_cast(logSpan.data()), expectedNumLogFormat); // Verify the kImageUpload operation was not added diff --git a/src/tracing/silabs/BUILD.gn b/src/tracing/silabs/BUILD.gn new file mode 100644 index 0000000000..0b744d4536 --- /dev/null +++ b/src/tracing/silabs/BUILD.gn @@ -0,0 +1,25 @@ +# Copyright (c) 2024 Project CHIP Authors +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +import("//build_overrides/build.gni") +import("//build_overrides/chip.gni") + +config("tracing") { + include_dirs = [ "include" ] +} + +source_set("silabs_tracing") { + public = [ "include/matter/tracing/macros_impl.h" ] + public_configs = [ ":tracing" ] +} diff --git a/src/tracing/silabs/include/matter/tracing/macros_impl.h b/src/tracing/silabs/include/matter/tracing/macros_impl.h new file mode 100644 index 0000000000..f9ec7e5697 --- /dev/null +++ b/src/tracing/silabs/include/matter/tracing/macros_impl.h @@ -0,0 +1,25 @@ +/* + * + * Copyright (c) 2024 Project CHIP Authors + * All rights reserved. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +#pragma once + +/* Ensure we do not have double tracing macros defined */ +#if defined(MATTER_TRACE_BEGIN) +#error "Tracing macros seem to be double defined" +#endif + +#include diff --git a/src/tracing/tracing_args.gni b/src/tracing/tracing_args.gni index 085844e4a5..376c981282 100644 --- a/src/tracing/tracing_args.gni +++ b/src/tracing/tracing_args.gni @@ -49,6 +49,8 @@ declare_args() { matter_trace_config = "${chip_root}/src/tracing/perfetto:perfetto_tracing" } else if (chip_device_platform == "darwin") { matter_trace_config = "${chip_root}/src/tracing/darwin:darwin_tracing" + } else if (chip_device_platform == "efr32") { + matter_trace_config = "${chip_root}/src/tracing/silabs:silabs_tracing" } else { matter_trace_config = "${chip_root}/src/tracing/none" }