trace_region on Android and Windows

Source/Android/arcana/tracing/trace_region.h

@@ -2,8 +2,42 @@
 // Copyright (C) Microsoft Corporation. All rights reserved.
 //
 
+//
+// Android trace_region implementation using the NDK ATrace API.
+//
+// This uses ATrace_beginAsyncSection/ATrace_endAsyncSection (API 29+) which pair
+// begin/end events by name + cookie, allowing trace regions to be moved across
+// threads (e.g. when an RAII trace_region is captured into an async continuation).
+// The sync API (ATrace_beginSection/ATrace_endSection) uses a per-thread stack,
+// which breaks when begin and end occur on different threads.
+//
+// When targeting minSdkVersion < 29, the async functions are resolved at runtime
+// via dlsym. If unavailable (device below API 29), ATrace is silently skipped
+// (logcat output at trace_level::log still works).
+//
+// NOTE: Async trace sections may not be visible in Android Studio's Profiler UI.
+// To view them, capture a trace with Perfetto:
+//
+//   adb shell atrace --async_start -a <your.package.name> -c
+//   # ... interact with the app ...
+//   adb shell atrace --async_stop -o /data/local/tmp/trace.txt
+//   adb pull /data/local/tmp/trace.txt
+//
+// Then open the trace file at https://ui.perfetto.dev
+//
+
 #pragma once
 
+#include <atomic>
+#include <string>
+#include <android/trace.h>
+#include <android/log.h>
+#if __ANDROID_MIN_SDK_VERSION__ < 29
+#include <dlfcn.h>
+#endif
+
+#define TRACE_TAG "trace_region"
+
 namespace arcana
 {
     enum class trace_level
@@ -12,33 +46,119 @@ namespace arcana
         log,
     };
 
-    // TODO: https://developer.android.com/topic/performance/tracing/custom-events-native
-    //       https://developer.android.com/ndk/reference/group/tracing
     class trace_region final
     {
     public:
         trace_region() = delete;
         trace_region(const trace_region&) = delete;
         trace_region& operator=(const trace_region&) = delete;
 
-        trace_region(const char*)
+        trace_region(const char* name) :
+            m_cookie{s_enabled ? s_nextCookie.fetch_add(1, std::memory_order_relaxed) : 0},
+            m_name{m_cookie != 0 ? name : ""}
         {
+            if (m_cookie != 0)
+            {
+                if (s_logEnabled)
+                {
+                    __android_log_print(ANDROID_LOG_DEBUG, TRACE_TAG, "[trace_region] BEGIN %s (cookie=%d, this=%p)", m_name.c_str(), m_cookie, static_cast<const void*>(this));
+                }
+                traceBegin(m_name.c_str(), m_cookie);
+            }
         }
 
-        trace_region(trace_region&&) = default;
+        // Move constructor transfers ownership; the moved-from region becomes inactive
+        // (cookie set to 0) so its destructor won't emit a spurious end event.
+        trace_region(trace_region&& other) :
+            m_cookie{other.m_cookie},
+            m_name{std::move(other.m_name)}
+        {
+            other.m_cookie = 0;
+        }
 
         ~trace_region()
         {
+            if (m_cookie != 0)
+            {
+                if (s_logEnabled)
+                {
+                    __android_log_print(ANDROID_LOG_DEBUG, TRACE_TAG, "[trace_region] END (cookie=%d, this=%p)", m_cookie, static_cast<const void*>(this));
+                }
+                traceEnd(m_name.c_str(), m_cookie);
+            }
         }
 
-        trace_region& operator=(trace_region&&) = default;
+        trace_region& operator=(trace_region&& other)
+        {
+            if (m_cookie != 0)
+            {
+                if (s_logEnabled)
+                {
+                    __android_log_print(ANDROID_LOG_DEBUG, TRACE_TAG, "[trace_region] END (move) (cookie=%d, this=%p)", m_cookie, static_cast<const void*>(this));
+                }
+                traceEnd(m_name.c_str(), m_cookie);
+            }
 
-        static void enable(trace_level = trace_level::mark)
+            m_cookie = other.m_cookie;
+            m_name = std::move(other.m_name);
+            other.m_cookie = 0;
+
+            return *this;
+        }
+
+        static void enable(trace_level level = trace_level::mark)
         {
+            s_enabled = true;
+            s_logEnabled = level == trace_level::log;
         }
 
         static void disable()
         {
+            s_enabled = false;
+            s_logEnabled = false;
+        }
+
+    private:
+        static void traceBegin(const char* name, int32_t cookie)
+        {
+#if __ANDROID_MIN_SDK_VERSION__ >= 29
+            ATrace_beginAsyncSection(name, cookie);
+#else
+            if (s_beginAsync)
+                s_beginAsync(name, cookie);
+#endif
         }
+
+        static void traceEnd(const char* name, int32_t cookie)
+        {
+#if __ANDROID_MIN_SDK_VERSION__ >= 29
+            ATrace_endAsyncSection(name, cookie);
+#else
+            if (s_endAsync)
+                s_endAsync(name, cookie);
+#endif
+        }
+
+        static inline std::atomic<bool> s_enabled{false};
+        static inline std::atomic<bool> s_logEnabled{false};
+        static inline std::atomic<int32_t> s_nextCookie{1};
+
+#if __ANDROID_MIN_SDK_VERSION__ < 29
+        // Resolve async trace functions at load time. These are available on
+        // devices running API 29+, even when the app targets a lower minSdkVersion.
+        using AsyncTraceFunc = void (*)(const char*, int32_t);
+        static inline const AsyncTraceFunc s_beginAsync{
+            reinterpret_cast<AsyncTraceFunc>(dlsym(RTLD_DEFAULT, "ATrace_beginAsyncSection"))};
+        static inline const AsyncTraceFunc s_endAsync{
+            reinterpret_cast<AsyncTraceFunc>(dlsym(RTLD_DEFAULT, "ATrace_endAsyncSection"))};
+#endif
+
+        // Cookie uniquely identifies this trace interval for the async API, analogous
+        // to os_signpost_id_t on Apple. A cookie of 0 means the region is inactive.
+        int32_t m_cookie;
+        // Name is stored as std::string (not const char*) because callers may pass
+        // c_str() from a temporary std::string, and ATrace_endAsyncSection needs the
+        // name to match the corresponding begin call.
+        std::string m_name;
     };
 }

Source/Apple/arcana/tracing/trace_region.h

@@ -2,6 +2,24 @@
 // Copyright (C) Microsoft Corporation. All rights reserved.
 //
 
+//
+// Apple trace_region implementation using os_signpost.
+//
+// Signpost intervals are logged to the OS_LOG_CATEGORY_POINTS_OF_INTEREST category,
+// which makes them appear on the "Points of Interest" timeline in Instruments.
+// Each interval is identified by a unique os_signpost_id_t, allowing begin/end
+// pairs to be matched even across threads or when multiple regions overlap.
+//
+// To capture and view traces in Instruments:
+//   1. Open Instruments (Xcode → Open Developer Tool → Instruments, or ⌘I from Xcode)
+//   2. Choose the "Blank" template, then add the "os_signpost" instrument
+//      (click "+", search for "os_signpost", and add it)
+//   3. Select your app as the target and click Record
+//   4. Interact with the app, then stop recording
+//   5. Trace regions appear on the "Points of Interest" timeline as labeled intervals
+//   6. Click on an interval to see its name and duration in the detail pane
+//
+
 #pragma once
 
 #include <atomic>

Source/Windows/arcana/tracing/trace_region.h

@@ -2,42 +2,189 @@
 // Copyright (C) Microsoft Corporation. All rights reserved.
 //
 
+//
+// Windows trace_region implementation using ETW TraceLogging.
+//
+// Events are emitted as ETW activity start/stop pairs via TraceLoggingWriteActivity
+// under the "Arcana.TraceRegion" provider. Each trace region gets a unique activity
+// GUID (derived from an integer cookie), allowing WPA to correlate begin/end events
+// into duration spans — even across threads.
+//
+// TRACELOGGING_DEFINE_PROVIDER_STORAGE creates static (TU-local) provider
+// storage with no external symbols, avoiding linker conflicts when included
+// from multiple translation units. The handle is defined as a C++17 inline
+// variable so all TUs share a single provider pointer.
+//
+// To capture and view traces (from an elevated command prompt):
+//   1. Start an ETW trace session:
+//      logman create trace ArcanaTrace -p "{B2A07E6E-A49F-4C4F-B9D2-8D3E5C7F1A2B}" -o arcana.etl -ets
+//   2. Run the application
+//   3. Stop the trace:
+//      logman stop ArcanaTrace -ets
+//   4. Open arcana.etl in Windows Performance Analyzer (WPA) or PerfView.
+//      In WPA, trace regions appear as duration spans in the Regions of Interest
+//      activity view under "Arcana.TraceRegion".
+//
+// Debug log output (at trace_level::log) goes to OutputDebugStringA,
+// visible in the Visual Studio Output window or DebugView (SysInternals).
+//
+
 #pragma once
 
+#include <atomic>
+#include <cstdio>
+#include <string>
+#include <windows.h>
+#include <evntrace.h>
+#include <TraceLoggingProvider.h>
+
+#pragma comment(lib, "advapi32.lib")
+
 namespace arcana
 {
+    namespace detail
+    {
+        // Static per-TU storage — no external symbols, no linker conflicts.
+        TRACELOGGING_DEFINE_PROVIDER_STORAGE(
+            s_traceRegionProviderStorage,
+            "Arcana.TraceRegion",
+            // {B2A07E6E-A49F-4C4F-B9D2-8D3E5C7F1A2B}
+            (0xB2A07E6E, 0xA49F, 0x4C4F, 0xB9, 0xD2, 0x8D, 0x3E, 0x5C, 0x7F, 0x1A, 0x2B));
+
+        // C++17 inline — linker picks one definition, all TUs share the same handle.
+        inline TraceLoggingHProvider const g_traceRegionProvider = &s_traceRegionProviderStorage;
+    }
+
     enum class trace_level
     {
         mark,
         log,
     };
 
-    // TODO: https://docs.microsoft.com/en-us/windows/win32/tracelogging/tracelogging-native-quick-start
     class trace_region final
     {
     public:
         trace_region() = delete;
         trace_region(const trace_region&) = delete;
         trace_region& operator=(const trace_region&) = delete;
 
-        trace_region(const char*)
+        trace_region(const char* name) :
+            m_cookie{s_enabled ? s_nextCookie.fetch_add(1, std::memory_order_relaxed) : 0},
+            m_name{m_cookie != 0 ? name : ""},
+            m_activityId{cookieToGuid(m_cookie)}
         {
+            if (m_cookie != 0)
+            {
+                if (s_logEnabled)
+                {
+                    char buf[256];
+                    std::snprintf(buf, sizeof(buf), "[trace_region] BEGIN %s (cookie=%d)\n", m_name.c_str(), m_cookie);
+                    OutputDebugStringA(buf);
+                }
+                TraceLoggingWriteActivity(detail::g_traceRegionProvider,
+                    "TraceRegion",
+                    &m_activityId,
+                    nullptr,
+                    TraceLoggingOpcode(EVENT_TRACE_TYPE_START),
+                    TraceLoggingString(m_name.c_str(), "Name"),
+                    TraceLoggingInt32(m_cookie, "Cookie"));
+            }
         }
 
-        trace_region(trace_region&&) = default;
+        // Move constructor transfers ownership; the moved-from region becomes inactive
+        // (cookie set to 0) so its destructor won't emit a spurious stop event.
+        trace_region(trace_region&& other) :
+            m_cookie{other.m_cookie},
+            m_name{std::move(other.m_name)},
+            m_activityId{other.m_activityId}
+        {
+            other.m_cookie = 0;
+        }
 
         ~trace_region()
         {
+            if (m_cookie != 0)
+            {
+                if (s_logEnabled)
+                {
+                    char buf[256];
+                    std::snprintf(buf, sizeof(buf), "[trace_region] END (cookie=%d)\n", m_cookie);
+                    OutputDebugStringA(buf);
+                }
+                TraceLoggingWriteActivity(detail::g_traceRegionProvider,
+                    "TraceRegion",
+                    &m_activityId,
+                    nullptr,
+                    TraceLoggingOpcode(EVENT_TRACE_TYPE_STOP),
+                    TraceLoggingString(m_name.c_str(), "Name"),
+                    TraceLoggingInt32(m_cookie, "Cookie"));
+            }
         }
 
-        trace_region& operator=(trace_region&&) = default;
+        trace_region& operator=(trace_region&& other)
+        {
+            if (m_cookie != 0)
+            {
+                if (s_logEnabled)
+                {
+                    char buf[256];
+                    std::snprintf(buf, sizeof(buf), "[trace_region] END (move) (cookie=%d)\n", m_cookie);
+                    OutputDebugStringA(buf);
+                }
+                TraceLoggingWriteActivity(detail::g_traceRegionProvider,
+                    "TraceRegion",
+                    &m_activityId,
+                    nullptr,
+                    TraceLoggingOpcode(EVENT_TRACE_TYPE_STOP),
+                    TraceLoggingString(m_name.c_str(), "Name"),
+                    TraceLoggingInt32(m_cookie, "Cookie"));
+            }
+
+            m_cookie = other.m_cookie;
+            m_name = std::move(other.m_name);
+            m_activityId = other.m_activityId;
+            other.m_cookie = 0;
+
+            return *this;
+        }
 
-        static void enable(trace_level = trace_level::mark)
+        static void enable(trace_level level = trace_level::mark)
         {
+            TraceLoggingRegister(detail::g_traceRegionProvider);
+            s_enabled = true;
+            s_logEnabled = level == trace_level::log;
         }
 
         static void disable()
         {
+            s_enabled = false;
+            s_logEnabled = false;
+            TraceLoggingUnregister(detail::g_traceRegionProvider);
         }
+
+    private:
+        // Derives a deterministic GUID from the cookie for ETW activity correlation.
+        // Only needs to be unique within a single trace session.
+        static GUID cookieToGuid(int32_t cookie)
+        {
+            // Use the provider GUID as a base, with the cookie in Data1.
+            return {static_cast<unsigned long>(cookie), 0xA49F, 0x4C4F,
+                    {0xB9, 0xD2, 0x8D, 0x3E, 0x5C, 0x7F, 0x1A, 0x2B}};
+        }
+
+        static inline std::atomic<bool> s_enabled{false};
+        static inline std::atomic<bool> s_logEnabled{false};
+        static inline std::atomic<int32_t> s_nextCookie{1};
+
+        // Cookie uniquely identifies this trace interval, analogous to
+        // os_signpost_id_t on Apple. A cookie of 0 means the region is inactive.
+        int32_t m_cookie;
+        // Name is stored as std::string (not const char*) because callers may pass
+        // c_str() from a temporary std::string, and the stop event needs the name
+        // to match the corresponding start event for correlation.
+        std::string m_name;
+        // Activity GUID derived from cookie, used by ETW to correlate start/stop
+        // events into duration spans in WPA.
+        GUID m_activityId;
     };
 }