trace_region on Android and Windows

Source/Android/arcana/tracing/trace_region.h

@@ -2,8 +2,40 @@
 // 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
+
 namespace arcana
 {
     enum class trace_level
@@ -12,33 +44,134 @@ 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_region", "[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_region", "[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 (this == &other)
+            {
+                return *this;
+            }
+
+            if (m_cookie != 0)
+            {
+                if (s_logEnabled)
+                {
+                    __android_log_print(ANDROID_LOG_DEBUG, "trace_region", "[trace_region] END (move) (cookie=%d, this=%p)", m_cookie, static_cast<const void*>(this));
+                }
+                traceEnd(m_name.c_str(), m_cookie);
+            }
+
+            m_cookie = other.m_cookie;
+            m_name = std::move(other.m_name);
+            other.m_cookie = 0;
 
-        static void enable(trace_level = trace_level::mark)
+            return *this;
+        }
+
+        static void enable(trace_level level = trace_level::mark)
         {
+            if (s_enabled)
+            {
+                return;
+            }
+
+            s_enabled = true;
+            s_logEnabled = level == trace_level::log;
         }
 
         static void disable()
         {
+            if (!s_enabled)
+            {
+                return;
+            }
+
+            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,14 +2,30 @@
 // 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>
 #include <os/signpost.h>
 #include <os/log.h>
 
-#define SIGNPOST_NAME "trace_region"
-
 namespace arcana
 {
     enum class trace_level
@@ -34,7 +50,7 @@ namespace arcana
                 {
                     os_log_debug(s_log, "[trace_region] BEGIN %s (id=%llu, this=%p)", name, m_id, this);
                 }
-                os_signpost_interval_begin(s_log, m_id, SIGNPOST_NAME, "%s", name);
+                os_signpost_interval_begin(s_log, m_id, "trace_region", "%s", name);
             }
         }
 
@@ -52,19 +68,24 @@ namespace arcana
                 {
                     os_log_debug(s_log, "[trace_region] END (id=%llu, this=%p)", m_id, this);
                 }
-                os_signpost_interval_end(s_log, m_id, SIGNPOST_NAME);
+                os_signpost_interval_end(s_log, m_id, "trace_region");
             }
         }
 
         trace_region& operator=(trace_region&& other)
         {
+            if (this == &other)
+            {
+                return *this;
+            }
+
             if (m_id != OS_SIGNPOST_ID_NULL)
             {
                 if (s_logEnabled)
                 {
                     os_log_debug(s_log, "[trace_region] END (move) (id=%llu, this=%p)", m_id, this);
                 }
-                os_signpost_interval_end(s_log, m_id, SIGNPOST_NAME);
+                os_signpost_interval_end(s_log, m_id, "trace_region");
             }
 
             m_id = other.m_id;
@@ -75,12 +96,22 @@ namespace arcana
 
         static void enable(trace_level level = trace_level::mark)
         {
+            if (s_enabled)
+            {
+                return;
+            }
+
             s_enabled = true;
             s_logEnabled = level == trace_level::log;
         }
 
         static void disable()
         {
+            if (!s_enabled)
+            {
+                return;
+            }
+
             s_enabled = false;
             s_logEnabled = false;
         }