Implement the tracing macros using a backend for esp32. (#29543)

* Implement the tracing macros using a backend for esp32.

- This PR is aimed at addressing the review comments on PR #29318.
- This is a draft implementation of the backend.

* Move esp32 tracing configs around: better location, integrate in build examples, carry over configurations

* More options removals

* Remove fixme text

* Restrict tracing to light app, fix include paths in main, add ignore for authkey since that should not be checked in

* Move dependencies around even more - esp32 now seems to compile with tracing enabled

* Ensure tracing is actually enabled when insights is on

* Restyle

* Made esp32_trace backend in sync with existing version

* Made the common include on the tracing config for all esp32 examples

* Fixed the CI failure

---------

Co-authored-by: Andrei Litvin <andy314@gmail.com>

config/esp32/BUILD.gn

@@ -19,13 +19,17 @@ import("//build_overrides/build.gni")
 import("//build_overrides/chip.gni")
 
 import("${chip_root}/build/chip/tests.gni")
+import("${chip_root}/src/tracing/tracing_args.gni")
 
 declare_args() {
   chip_build_pw_rpc_lib = false
 }
 
 group("esp32") {
-  deps = [ "${chip_root}/src/lib" ]
+  deps = [
+    "${chip_root}/src/lib",
+    matter_trace_config,
+  ]
 
   if (chip_build_pw_rpc_lib) {
     deps += [ "//lib/pw_rpc" ]

config/esp32/components/chip/CMakeLists.txt

@@ -261,13 +261,18 @@ if (CONFIG_SEC_CERT_DAC_PROVIDER)
 endif()
 
 if (CONFIG_ENABLE_ESP_INSIGHTS_TRACE)
-    chip_gn_arg_append("matter_enable_esp_insights_trace"                    "true")
+  chip_gn_arg_bool("matter_enable_tracing_support"  "true")
+  chip_gn_arg_append("matter_trace_config" "\"${CHIP_ROOT}/src/tracing/esp32_trace:esp32_trace_tracing\"")
 endif()
 
 if (CONFIG_USE_ESP32_ECDSA_PERIPHERAL)
     chip_gn_arg_append("chip_use_esp32_ecdsa_peripheral" "true")
 endif()
 
+if (CONFIG_ENABLE_ESP_INSIGHTS_TRACE)
+   target_include_directories(${COMPONENT_LIB} INTERFACE "${CHIP_ROOT}/src/tracing/esp32_trace/include")
+endif()
+
 set(args_gn_input "${CMAKE_CURRENT_BINARY_DIR}/args.gn.in")
 file(GENERATE OUTPUT "${args_gn_input}" CONTENT "${chip_gn_args}")
 
@@ -318,7 +323,11 @@ set(GN_ROOT_TARGET ${CHIP_ROOT}/config/esp32)
 set(chip_libraries "${CMAKE_CURRENT_BINARY_DIR}/lib/libCHIP.a")
 
 if(CONFIG_ENABLE_PW_RPC)
-    list(APPEND chip_libraries "${CMAKE_CURRENT_BINARY_DIR}/lib/libPwRpc.a")
+  list(APPEND chip_libraries "${CMAKE_CURRENT_BINARY_DIR}/lib/libPwRpc.a")
+endif()
+
+if (CONFIG_ENABLE_ESP_INSIGHTS_TRACE)
+  list(APPEND chip_libraries "${CMAKE_CURRENT_BINARY_DIR}/lib/libEsp32TracingBackend.a")
 endif()
 
 # When using the pregenerated files, there is a edge case where an error appears for
@@ -371,10 +380,6 @@ target_include_directories(${COMPONENT_LIB} INTERFACE
     "${CHIP_ROOT}/config/esp32/${CONFIG_CHIP_EXTERNAL_PLATFORM_DIR}/../../"
 )
 
-if (CONFIG_ENABLE_ESP_INSIGHTS_TRACE)
-    target_include_directories(${COMPONENT_LIB} INTERFACE "${CHIP_ROOT}/src/tracing/esp32_trace/include")
-endif()
-
 idf_component_get_property(mbedtls_lib mbedtls COMPONENT_LIB)
 
 idf_build_get_property(idf_target IDF_TARGET)

examples/lighting-app/esp32/.gitignore

@@ -1,3 +1,4 @@
 /build/
 /sdkconfig
 /sdkconfig.old
+main/insights_auth_key.txt

examples/lighting-app/esp32/main/CMakeLists.txt

@@ -73,6 +73,7 @@ if(${IDF_TARGET} STREQUAL "esp32")
     list(APPEND PRIV_REQUIRES_LIST spidriver screen-framework)
 endif()
 
+
 if (CONFIG_ENABLE_PW_RPC)
 # Append additional directories for RPC build
 set(PRIV_INCLUDE_DIRS_LIST  "${PRIV_INCLUDE_DIRS_LIST}"

examples/lighting-app/esp32/main/main.cpp

@@ -18,11 +18,10 @@
 #include "DeviceCallbacks.h"
 
 #include "AppTask.h"
+#include "esp_log.h"
 #include <common/CHIPDeviceManager.h>
 #include <common/Esp32AppServer.h>
 #include <common/Esp32ThreadInit.h>
-
-#include "esp_log.h"
 #if ESP_IDF_VERSION >= ESP_IDF_VERSION_VAL(5, 0, 0)
 #include "spi_flash_mmap.h"
 #else
@@ -61,6 +60,8 @@
 
 #if CONFIG_ENABLE_ESP_INSIGHTS_TRACE
 #include <esp_insights.h>
+#include <tracing/esp32_trace/esp32_tracing.h>
+#include <tracing/registry.h>
 #endif
 
 using namespace ::chip;
@@ -113,6 +114,22 @@ static void InitServer(intptr_t context)
 
     DeviceCallbacksDelegate::Instance().SetAppDelegate(&sAppDeviceCallbacksDelegate);
     Esp32AppServer::Init(); // Init ZCL Data Model and CHIP App Server AND Initialize device attestation config
+#if CONFIG_ENABLE_ESP_INSIGHTS_TRACE
+    esp_insights_config_t config = {
+        .log_type = ESP_DIAG_LOG_TYPE_ERROR | ESP_DIAG_LOG_TYPE_WARNING | ESP_DIAG_LOG_TYPE_EVENT,
+        .auth_key = insights_auth_key_start,
+    };
+
+    esp_err_t ret = esp_insights_init(&config);
+
+    if (ret != ESP_OK)
+    {
+        ESP_LOGE(TAG, "Failed to initialize ESP Insights, err:0x%x", ret);
+    }
+
+    static Tracing::Insights::ESP32Backend backend;
+    Tracing::Register(backend);
+#endif
 }
 
 extern "C" void app_main()
@@ -134,20 +151,6 @@ extern "C" void app_main()
     chip::rpc::Init();
 #endif
 
-#if CONFIG_ENABLE_ESP_INSIGHTS_TRACE
-    esp_insights_config_t config = {
-        .log_type = ESP_DIAG_LOG_TYPE_ERROR | ESP_DIAG_LOG_TYPE_WARNING | ESP_DIAG_LOG_TYPE_EVENT,
-        .auth_key = insights_auth_key_start,
-    };
-
-    esp_err_t ret = esp_insights_init(&config);
-
-    if (ret != ESP_OK)
-    {
-        ESP_LOGE(TAG, "Failed to initialize ESP Insights, err:0x%x", ret);
-    }
-#endif
-
     ESP_LOGI(TAG, "==================================================");
     ESP_LOGI(TAG, "chip-esp32-light-example starting");
     ESP_LOGI(TAG, "==================================================");

scripts/build/build/targets.py

@@ -206,6 +206,7 @@ def BuildEsp32Target():
 
     target.AppendModifier('rpc', enable_rpcs=True)
     target.AppendModifier('ipv6only', enable_ipv4=False)
+    target.AppendModifier('tracing', enable_insights_trace=True).OnlyIfRe("light")
 
     return target
 

scripts/build/builders/esp32.py

@@ -147,13 +147,15 @@ def __init__(self,
                  board: Esp32Board = Esp32Board.M5Stack,
                  app: Esp32App = Esp32App.ALL_CLUSTERS,
                  enable_rpcs: bool = False,
-                 enable_ipv4: bool = True
+                 enable_ipv4: bool = True,
+                 enable_insights_trace: bool = False
                  ):
         super(Esp32Builder, self).__init__(root, runner)
         self.board = board
         self.app = app
         self.enable_rpcs = enable_rpcs
         self.enable_ipv4 = enable_ipv4
+        self.enable_insights_trace = enable_insights_trace
 
         if not app.IsCompatible(board):
             raise Exception(
@@ -191,6 +193,15 @@ def generate(self):
             self._Execute(
                 ['bash', '-c', 'echo -e "\\nCONFIG_DISABLE_IPV4=y\\n" >>%s' % shlex.quote(defaults_out)])
 
+        if self.enable_insights_trace:
+            insights_flag = 'y'
+        else:
+            insights_flag = 'n'
+
+        # pre-requisite
+        self._Execute(
+            ['bash', '-c', 'echo -e "\\nCONFIG_ESP_INSIGHTS_ENABLED=%s\\nCONFIG_ENABLE_ESP_INSIGHTS_TRACE=%s\\n" >>%s' % (insights_flag, insights_flag, shlex.quote(defaults_out))])
+
         cmake_flags = []
 
         if self.options.pregen_dir:

scripts/build/testdata/all_targets_linux_x64.txt

@@ -7,7 +7,7 @@ ti-cc13x2x7_26x2x7-{lighting,lock,pump,pump-controller}[-mtd]
 ti-cc13x4_26x4-{all-clusters,lighting,lock,pump,pump-controller}[-mtd][-ftd]
 cyw30739-cyw930739m2evb_01-{light,lock,ota-requestor,switch}
 efr32-{brd4161a,brd4187c,brd4186c,brd4163a,brd4164a,brd4166a,brd4170a,brd4186a,brd4187a,brd4304a}-{window-covering,switch,unit-test,light,lock,thermostat,pump}[-rpc][-with-ota-requestor][-icd][-low-power][-shell][-no_logging][-openthread_mtd][-enable_heap_monitoring][-no_openthread_cli][-show_qr_code][-wifi][-rs911x][-wf200][-wifi_ipv4][-additional_data_advertising][-use_ot_lib][-use_ot_coap_lib][-no-version]
-esp32-{m5stack,c3devkit,devkitc,qemu}-{all-clusters,all-clusters-minimal,ota-provider,ota-requestor,shell,light,lock,bridge,temperature-measurement,ota-requestor,tests}[-rpc][-ipv6only]
+esp32-{m5stack,c3devkit,devkitc,qemu}-{all-clusters,all-clusters-minimal,ota-provider,ota-requestor,shell,light,lock,bridge,temperature-measurement,ota-requestor,tests}[-rpc][-ipv6only][-tracing]
 genio-lighting-app
 linux-fake-tests[-mbedtls][-boringssl][-asan][-tsan][-ubsan][-libfuzzer][-ossfuzz][-coverage][-dmalloc][-clang]
 linux-{x64,arm64}-{rpc-console,all-clusters,all-clusters-minimal,chip-tool,thermostat,java-matter-controller,minmdns,light,lock,shell,ota-provider,ota-requestor,simulated-app1,simulated-app2,python-bindings,tv-app,tv-casting-app,bridge,tests,chip-cert,address-resolve-tool,contact-sensor,dishwasher,refrigerator,rvc}[-nodeps][-platform-mdns][-minmdns-verbose][-libnl][-same-event-loop][-no-interactive][-ipv6only][-no-ble][-no-wifi][-no-thread][-mbedtls][-boringssl][-asan][-tsan][-ubsan][-libfuzzer][-ossfuzz][-coverage][-dmalloc][-clang][-test][-rpc][-with-ui]

scripts/build/testdata/dry_run_esp32-devkitc-light-rpc.txt

@@ -8,6 +8,8 @@ cp examples/lighting-app/esp32/sdkconfig_rpc.defaults {out}/esp32-devkitc-light-
 
 rm -f examples/lighting-app/esp32/sdkconfig
 
+bash -c 'echo -e "\nCONFIG_ESP_INSIGHTS_ENABLED=n\nCONFIG_ENABLE_ESP_INSIGHTS_TRACE=n\n" >>{out}/esp32-devkitc-light-rpc/sdkconfig.defaults'
+
 bash -c 'source $IDF_PATH/export.sh; source scripts/activate.sh; 
 export SDKCONFIG_DEFAULTS={out}/esp32-devkitc-light-rpc/sdkconfig.defaults
 idf.py -C examples/lighting-app/esp32 -B {out}/esp32-devkitc-light-rpc reconfigure'

scripts/build/testdata/dry_run_esp32-m5stack-all-clusters-minimal-rpc-ipv6only.txt

@@ -10,6 +10,8 @@ rm -f examples/all-clusters-minimal-app/esp32/sdkconfig
 
 bash -c 'echo -e "\nCONFIG_DISABLE_IPV4=y\n" >>{out}/esp32-m5stack-all-clusters-minimal-rpc-ipv6only/sdkconfig.defaults'
 
+bash -c 'echo -e "\nCONFIG_ESP_INSIGHTS_ENABLED=n\nCONFIG_ENABLE_ESP_INSIGHTS_TRACE=n\n" >>{out}/esp32-m5stack-all-clusters-minimal-rpc-ipv6only/sdkconfig.defaults'
+
 bash -c 'source $IDF_PATH/export.sh; source scripts/activate.sh; 
 export SDKCONFIG_DEFAULTS={out}/esp32-m5stack-all-clusters-minimal-rpc-ipv6only/sdkconfig.defaults
 idf.py -C examples/all-clusters-minimal-app/esp32 -B {out}/esp32-m5stack-all-clusters-minimal-rpc-ipv6only reconfigure'

src/tracing/esp32_trace/BUILD.gn

@@ -20,8 +20,19 @@ config("tracing") {
   include_dirs = [ "include" ]
 }
 
-source_set("esp32_trace") {
+static_library("backend") {
+  output_name = "libEsp32TracingBackend"
+  output_dir = "${root_out_dir}/lib"
+
+  sources = [
+    "esp32_tracing.cpp",
+    "esp32_tracing.h",
+  ]
+  public_deps = [ "${chip_root}/src/tracing" ]
+}
+
+source_set("esp32_trace_tracing") {
   public = [ "include/matter/tracing/macros_impl.h" ]
-  sources = [ "include/matter/tracing/macros_impl.cpp" ]
   public_configs = [ ":tracing" ]
+  deps = [ ":backend" ]
 }

src/tracing/esp32_trace/include/matter/tracing/macros_impl.cpp → src/tracing/esp32_trace/esp32_tracing.cpp

@@ -1,5 +1,7 @@
 /*
+ *
  *    Copyright (c) 2023 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.
@@ -14,9 +16,15 @@
  *    limitations under the License.
  */
 
-#include "macros_impl.h"
+#include "esp32_tracing.h"
 #include <esp_heap_caps.h>
 #include <esp_insights.h>
+#include <esp_log.h>
+#include <memory>
+#include <tracing/backend.h>
+
+namespace chip {
+namespace Tracing {
 namespace Insights {
 
 #define LOG_HEAP_INFO(label, group, entry_exit)                                                                                    \
@@ -28,17 +36,31 @@ namespace Insights {
                        heap_caps_get_free_size(MALLOC_CAP_8BIT));                                                                  \
     } while (0)
 
-ESP32Backend::ESP32Backend(const char * str, ...)
+void ESP32Backend::LogMessageReceived(MessageReceivedInfo & info) {}
+
+void ESP32Backend::LogMessageSend(MessageSendInfo & info) {}
+
+void ESP32Backend::LogNodeLookup(NodeLookupInfo & info) {}
+
+void ESP32Backend::LogNodeDiscovered(NodeDiscoveredInfo & info) {}
+
+void ESP32Backend::LogNodeDiscoveryFailed(NodeDiscoveryFailedInfo & info) {}
+
+void ESP32Backend::TraceBegin(const char * label, const char * group)
+{
+    LOG_HEAP_INFO(label, group, "Entry");
+}
+
+void ESP32Backend::TraceEnd(const char * label, const char * group)
 {
-    va_list args;
-    va_start(args, str);
-    mlabel = str;
-    mgroup = va_arg(args, const char *);
-    LOG_HEAP_INFO(mlabel, mgroup, "Entry");
+    LOG_HEAP_INFO(label, group, "Exit");
 }
 
-ESP32Backend::~ESP32Backend()
+void ESP32Backend::TraceInstant(const char * label, const char * group)
 {
-    LOG_HEAP_INFO(mlabel, mgroup, "Exit");
+    ESP_DIAG_EVENT("MTR_TRC", "Instant : %s -%s", label, group);
 }
 } // namespace Insights
+} // namespace Tracing
+} // namespace chip
+// namespace chip

src/tracing/esp32_trace/esp32_tracing.h

@@ -0,0 +1,34 @@
+#include <tracing/backend.h>
+
+#include <memory>
+
+namespace chip {
+namespace Tracing {
+namespace Insights {
+
+/// A Backend that outputs data to chip logging.
+///
+/// Structured data is formatted as json strings.
+class ESP32Backend : public ::chip::Tracing::Backend
+{
+public:
+    ESP32Backend() = default;
+
+    void TraceBegin(const char * label, const char * group) override;
+
+    void TraceEnd(const char * label, const char * group) override;
+
+    /// Trace a zero-sized event
+    void TraceInstant(const char * label, const char * group) override;
+
+    void LogMessageSend(MessageSendInfo &) override;
+    void LogMessageReceived(MessageReceivedInfo &) override;
+
+    void LogNodeLookup(NodeLookupInfo &) override;
+    void LogNodeDiscovered(NodeDiscoveredInfo &) override;
+    void LogNodeDiscoveryFailed(NodeDiscoveryFailedInfo &) override;
+};
+
+} // namespace Insights
+} // namespace Tracing
+} // namespace chip

src/tracing/esp32_trace/include/matter/tracing/macros_impl.h

@@ -1,4 +1,5 @@
 /*
+ *
  *    Copyright (c) 2023 Project CHIP Authors
  *    All rights reserved.
  *
@@ -21,30 +22,30 @@
 #error "Tracing macros seem to be double defined"
 #endif
 
+#include <tracing/registry.h>
+
+// 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)
+
+namespace chip {
+namespace Tracing {
 namespace Insights {
-class ESP32Backend
+class Scoped
 {
 public:
-    ESP32Backend(const char * str, ...);
-    ~ESP32Backend();
+    inline Scoped(const char * label, const char * group) : mLabel(label), mGroup(group) { MATTER_TRACE_BEGIN(label, group); }
+    inline ~Scoped() { MATTER_TRACE_END(mLabel, mGroup); }
 
 private:
-    const char * mlabel;
-    const char * mgroup;
+    const char * mLabel;
+    const char * mGroup;
 };
 } // namespace Insights
+} // namespace Tracing
+} // namespace chip
+#define _CONCAT_IMPL(a, b) a##b
+#define _MACRO_CONCAT(a, b) _CONCAT_IMPL(a, b)
 
-#define MATTER_TRACE_SCOPE(...)                                                                                                    \
-    do                                                                                                                             \
-    {                                                                                                                              \
-        Insights::ESP32Backend backend(__VA_ARGS__);                                                                               \
-    } while (0)
-
-#define _MATTER_TRACE_DISABLE(...)                                                                                                 \
-    do                                                                                                                             \
-    {                                                                                                                              \
-    } while (false)
-
-#define MATTER_TRACE_BEGIN(...) _MATTER_TRACE_DISABLE(__VA_ARGS__)
-#define MATTER_TRACE_END(...) _MATTER_TRACE_DISABLE(__VA_ARGS__)
-#define MATTER_TRACE_INSTANT(...) _MATTER_TRACE_DISABLE(__VA_ARGS__)
+#define MATTER_TRACE_SCOPE(label, group) ::chip::Tracing::Insights::Scoped _MACRO_CONCAT(_trace_scope, __COUNTER__)(label, group)