diff --git a/Source/Android/arcana/tracing/trace_region.h b/Source/Android/arcana/tracing/trace_region.h index cd3b650..c75ad1e 100644 --- a/Source/Android/arcana/tracing/trace_region.h +++ b/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 -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 +#include +#include +#include +#if __ANDROID_MIN_SDK_VERSION__ < 29 +#include +#endif + namespace arcana { enum class trace_level @@ -12,8 +44,6 @@ 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: @@ -21,24 +51,127 @@ namespace arcana 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(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(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(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 s_enabled{false}; + static inline std::atomic s_logEnabled{false}; + static inline std::atomic 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(dlsym(RTLD_DEFAULT, "ATrace_beginAsyncSection"))}; + static inline const AsyncTraceFunc s_endAsync{ + reinterpret_cast(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; }; } diff --git a/Source/Apple/arcana/tracing/trace_region.h b/Source/Apple/arcana/tracing/trace_region.h index ad66cc3..8f734aa 100644 --- a/Source/Apple/arcana/tracing/trace_region.h +++ b/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 #include #include -#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; } diff --git a/Source/Windows/arcana/tracing/trace_region.h b/Source/Windows/arcana/tracing/trace_region.h index b728a65..940c316 100644 --- a/Source/Windows/arcana/tracing/trace_region.h +++ b/Source/Windows/arcana/tracing/trace_region.h @@ -2,17 +2,66 @@ // 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 +#include +#include +#include +#include +#include +#include + +#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: @@ -20,24 +69,164 @@ namespace arcana 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)}, + m_registration{m_cookie != 0 ? s_registration : nullptr} { + 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}, + m_registration{std::move(other.m_registration)} + { + 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 (this == &other) + { + return *this; + } + + 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")); + } - static void enable(trace_level = trace_level::mark) + m_cookie = other.m_cookie; + m_name = std::move(other.m_name); + m_activityId = other.m_activityId; + m_registration = std::move(other.m_registration); + other.m_cookie = 0; + + return *this; + } + + static void enable(trace_level level = trace_level::mark) { + if (s_enabled) + { + return; + } + + TraceLoggingRegister(detail::g_traceRegionProvider); + // Create a shared_ptr whose custom deleter calls TraceLoggingUnregister. + // Each active trace_region holds a copy, so the provider stays registered + // until disable() is called AND all outstanding regions are destroyed. + s_registration = std::make_shared(); + s_enabled = true; + s_logEnabled = level == trace_level::log; } static void disable() { + if (!s_enabled) + { + return; + } + + s_enabled = false; + s_logEnabled = false; + // Release our ref. If active trace_regions still hold copies, + // the provider stays registered until their destructors run. + s_registration.reset(); + } + + private: + // RAII guard for provider registration. When the last shared_ptr to this + // object is released, the provider is unregistered. This ensures the + // provider stays registered as long as any trace_region is alive. + struct ProviderRegistration + { + ~ProviderRegistration() + { + TraceLoggingUnregister(detail::g_traceRegionProvider); + } + }; + + // Derives a deterministic GUID from the cookie for ETW activity correlation. + // Only needs to be unique within a single trace session. + // Fixed bytes are intentionally different from the provider GUID to avoid + // collisions when the cookie happens to match the provider's Data1. + static GUID cookieToGuid(int32_t cookie) + { + return {static_cast(cookie), 0x1E3A, 0x4B5C, + {0xA7, 0xD0, 0x6F, 0x2E, 0x9C, 0x8B, 0x3D, 0x14}}; } + + static inline std::atomic s_enabled{false}; + static inline std::atomic s_logEnabled{false}; + static inline std::atomic s_nextCookie{1}; + static inline std::shared_ptr s_registration; + + // 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; + // Ref-counted handle to the provider registration. Ensures the provider + // stays registered until this region emits its stop event, even if + // disable() is called while regions are still alive. + std::shared_ptr m_registration; }; }