From 55f7f9d7a9b88c4e7f0eb7cf4d7f31004761f5cb Mon Sep 17 00:00:00 2001 From: ivberg Date: Thu, 20 Jun 2024 06:45:45 -0700 Subject: [PATCH] Fix Crash When Enabling and Disabling ETW with Old Callbacks (#21086) ### Description Under certain conditions with enabling & disabling ETW continuously, we got a crash report. Allows ETW callbacks to be de-registered upon class destructor. Related to #20537 ### Motivation and Context Fixes crash ### Callstack We see it crash in [0x0] onnxruntime!::operator()+0x34 0x12941ff570 0x7ffa994f0a04 [0x1] onnxruntime!std::_Func_class::operator()+0x54 0x12941ff7b0 0x7ffa994f0d64 [0x2] onnxruntime!onnxruntime::logging::EtwRegistrationManager::InvokeCallbacks+0xcc 0x12941ff7b0 0x7ffa994f0d64 [0x3] onnxruntime!onnxruntime::logging::EtwRegistrationManager::ORT_TL_EtwEnableCallback+0x94 0x12941ff860 0x7ffa98d19628 and seems to us that the this pointer captured in etwRegistrationManager.RegisterInternalCallback( [&etwRegistrationManager, this]( ... is no longer valid when the callback is called. --- .../core/framework/execution_providers.h | 58 ++++++++++++------- .../core/platform/windows/logging/etw_sink.cc | 15 ++++- .../core/platform/windows/logging/etw_sink.h | 4 +- .../core/platform/windows/telemetry.cc | 22 +++++-- onnxruntime/core/platform/windows/telemetry.h | 4 +- .../providers/qnn/qnn_execution_provider.cc | 8 ++- .../providers/qnn/qnn_execution_provider.h | 6 ++ onnxruntime/core/session/inference_session.cc | 45 +++++++------- onnxruntime/core/session/inference_session.h | 6 ++ 9 files changed, 116 insertions(+), 52 deletions(-) diff --git a/onnxruntime/core/framework/execution_providers.h b/onnxruntime/core/framework/execution_providers.h index dc45cad692..43fe92edc9 100644 --- a/onnxruntime/core/framework/execution_providers.h +++ b/onnxruntime/core/framework/execution_providers.h @@ -25,30 +25,10 @@ Class for managing lookup of the execution providers in a session. */ class ExecutionProviders { public: - ExecutionProviders() = default; - - common::Status Add(const std::string& provider_id, const std::shared_ptr& p_exec_provider) { - // make sure there are no issues before we change any internal data structures - if (provider_idx_map_.find(provider_id) != provider_idx_map_.end()) { - auto status = ORT_MAKE_STATUS(ONNXRUNTIME, FAIL, "Provider ", provider_id, " has already been registered."); - LOGS_DEFAULT(ERROR) << status.ErrorMessage(); - return status; - } - - // index that provider will have after insertion - auto new_provider_idx = exec_providers_.size(); - - ORT_IGNORE_RETURN_VALUE(provider_idx_map_.insert({provider_id, new_provider_idx})); - - // update execution provider options - auto providerOptions = p_exec_provider->GetProviderOptions(); - exec_provider_options_[provider_id] = providerOptions; - + ExecutionProviders() { #ifdef _WIN32 - LogProviderOptions(provider_id, providerOptions, false); - // Register callback for ETW capture state (rundown) - WindowsTelemetry::RegisterInternalCallback( + etw_callback_ = onnxruntime::WindowsTelemetry::EtwInternalCallback( [this]( LPCGUID SourceId, ULONG IsEnabled, @@ -79,6 +59,36 @@ class ExecutionProviders { } } }); + WindowsTelemetry::RegisterInternalCallback(etw_callback_); +#endif + } + + ~ExecutionProviders() { +#ifdef _WIN32 + WindowsTelemetry ::UnregisterInternalCallback(etw_callback_); +#endif + } + + common::Status + Add(const std::string& provider_id, const std::shared_ptr& p_exec_provider) { + // make sure there are no issues before we change any internal data structures + if (provider_idx_map_.find(provider_id) != provider_idx_map_.end()) { + auto status = ORT_MAKE_STATUS(ONNXRUNTIME, FAIL, "Provider ", provider_id, " has already been registered."); + LOGS_DEFAULT(ERROR) << status.ErrorMessage(); + return status; + } + + // index that provider will have after insertion + auto new_provider_idx = exec_providers_.size(); + + ORT_IGNORE_RETURN_VALUE(provider_idx_map_.insert({provider_id, new_provider_idx})); + + // update execution provider options + auto providerOptions = p_exec_provider->GetProviderOptions(); + exec_provider_options_[provider_id] = providerOptions; + +#ifdef _WIN32 + LogProviderOptions(provider_id, providerOptions, false); #endif exec_provider_ids_.push_back(provider_id); @@ -156,5 +166,9 @@ class ExecutionProviders { // Whether the CPU provider was implicitly added to a session for fallback (true), // or whether it was explicitly added by the caller. bool cpu_execution_provider_was_implicitly_added_ = false; + +#ifdef _WIN32 + WindowsTelemetry::EtwInternalCallback etw_callback_; +#endif }; } // namespace onnxruntime diff --git a/onnxruntime/core/platform/windows/logging/etw_sink.cc b/onnxruntime/core/platform/windows/logging/etw_sink.cc index 5fb7f7a651..b0f9eaf4f6 100644 --- a/onnxruntime/core/platform/windows/logging/etw_sink.cc +++ b/onnxruntime/core/platform/windows/logging/etw_sink.cc @@ -104,7 +104,16 @@ HRESULT EtwRegistrationManager::Status() const { void EtwRegistrationManager::RegisterInternalCallback(const EtwInternalCallback& callback) { std::lock_guard lock(callbacks_mutex_); - callbacks_.push_back(callback); + callbacks_.push_back(&callback); +} + +void EtwRegistrationManager::UnregisterInternalCallback(const EtwInternalCallback& callback) { + std::lock_guard lock(callbacks_mutex_); + auto new_end = std::remove_if(callbacks_.begin(), callbacks_.end(), + [&callback](const EtwInternalCallback* ptr) { + return ptr == &callback; + }); + callbacks_.erase(new_end, callbacks_.end()); } void NTAPI EtwRegistrationManager::ORT_TL_EtwEnableCallback( @@ -126,6 +135,8 @@ void NTAPI EtwRegistrationManager::ORT_TL_EtwEnableCallback( } EtwRegistrationManager::~EtwRegistrationManager() { + std::lock_guard lock(callbacks_mutex_); + callbacks_.clear(); ::TraceLoggingUnregister(etw_provider_handle); } @@ -150,7 +161,7 @@ void EtwRegistrationManager::InvokeCallbacks(LPCGUID SourceId, ULONG IsEnabled, PVOID CallbackContext) { std::lock_guard lock(callbacks_mutex_); for (const auto& callback : callbacks_) { - callback(SourceId, IsEnabled, Level, MatchAnyKeyword, MatchAllKeyword, FilterData, CallbackContext); + (*callback)(SourceId, IsEnabled, Level, MatchAnyKeyword, MatchAllKeyword, FilterData, CallbackContext); } } diff --git a/onnxruntime/core/platform/windows/logging/etw_sink.h b/onnxruntime/core/platform/windows/logging/etw_sink.h index 5d35d101f1..3af45b813a 100644 --- a/onnxruntime/core/platform/windows/logging/etw_sink.h +++ b/onnxruntime/core/platform/windows/logging/etw_sink.h @@ -71,6 +71,8 @@ class EtwRegistrationManager { void RegisterInternalCallback(const EtwInternalCallback& callback); + void UnregisterInternalCallback(const EtwInternalCallback& callback); + private: EtwRegistrationManager(); ~EtwRegistrationManager(); @@ -90,7 +92,7 @@ class EtwRegistrationManager { _In_opt_ PEVENT_FILTER_DESCRIPTOR FilterData, _In_opt_ PVOID CallbackContext); - std::vector callbacks_; + std::vector callbacks_; OrtMutex callbacks_mutex_; mutable OrtMutex provider_change_mutex_; OrtMutex init_mutex_; diff --git a/onnxruntime/core/platform/windows/telemetry.cc b/onnxruntime/core/platform/windows/telemetry.cc index 850f40e846..86067d3772 100644 --- a/onnxruntime/core/platform/windows/telemetry.cc +++ b/onnxruntime/core/platform/windows/telemetry.cc @@ -64,7 +64,7 @@ bool WindowsTelemetry::enabled_ = true; uint32_t WindowsTelemetry::projection_ = 0; UCHAR WindowsTelemetry::level_ = 0; UINT64 WindowsTelemetry::keyword_ = 0; -std::vector WindowsTelemetry::callbacks_; +std::vector WindowsTelemetry::callbacks_; OrtMutex WindowsTelemetry::callbacks_mutex_; WindowsTelemetry::WindowsTelemetry() { @@ -86,6 +86,9 @@ WindowsTelemetry::~WindowsTelemetry() { TraceLoggingUnregister(telemetry_provider_handle); } } + + std::lock_guard lock_callbacks(callbacks_mutex_); + callbacks_.clear(); } bool WindowsTelemetry::IsEnabled() const { @@ -108,8 +111,17 @@ UINT64 WindowsTelemetry::Keyword() const { // } void WindowsTelemetry::RegisterInternalCallback(const EtwInternalCallback& callback) { - std::lock_guard lock(callbacks_mutex_); - callbacks_.push_back(callback); + std::lock_guard lock_callbacks(callbacks_mutex_); + callbacks_.push_back(&callback); +} + +void WindowsTelemetry::UnregisterInternalCallback(const EtwInternalCallback& callback) { + std::lock_guard lock_callbacks(callbacks_mutex_); + auto new_end = std::remove_if(callbacks_.begin(), callbacks_.end(), + [&callback](const EtwInternalCallback* ptr) { + return ptr == &callback; + }); + callbacks_.erase(new_end, callbacks_.end()); } void NTAPI WindowsTelemetry::ORT_TL_EtwEnableCallback( @@ -131,9 +143,9 @@ void NTAPI WindowsTelemetry::ORT_TL_EtwEnableCallback( void WindowsTelemetry::InvokeCallbacks(LPCGUID SourceId, ULONG IsEnabled, UCHAR Level, ULONGLONG MatchAnyKeyword, ULONGLONG MatchAllKeyword, PEVENT_FILTER_DESCRIPTOR FilterData, PVOID CallbackContext) { - std::lock_guard lock(callbacks_mutex_); + std::lock_guard lock_callbacks(callbacks_mutex_); for (const auto& callback : callbacks_) { - callback(SourceId, IsEnabled, Level, MatchAnyKeyword, MatchAllKeyword, FilterData, CallbackContext); + (*callback)(SourceId, IsEnabled, Level, MatchAnyKeyword, MatchAllKeyword, FilterData, CallbackContext); } } diff --git a/onnxruntime/core/platform/windows/telemetry.h b/onnxruntime/core/platform/windows/telemetry.h index 27cd20c2d2..ed80f13e63 100644 --- a/onnxruntime/core/platform/windows/telemetry.h +++ b/onnxruntime/core/platform/windows/telemetry.h @@ -66,13 +66,15 @@ class WindowsTelemetry : public Telemetry { static void RegisterInternalCallback(const EtwInternalCallback& callback); + static void UnregisterInternalCallback(const EtwInternalCallback& callback); + private: static OrtMutex mutex_; static uint32_t global_register_count_; static bool enabled_; static uint32_t projection_; - static std::vector callbacks_; + static std::vector callbacks_; static OrtMutex callbacks_mutex_; static OrtMutex provider_change_mutex_; static UCHAR level_; diff --git a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc index d4616e0cef..c159730d46 100644 --- a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc +++ b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc @@ -233,7 +233,7 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio #ifdef _WIN32 auto& etwRegistrationManager = logging::EtwRegistrationManager::Instance(); // Register callback for ETW capture state (rundown) - etwRegistrationManager.RegisterInternalCallback( + callback_ETWSink_provider_ = onnxruntime::logging::EtwRegistrationManager::EtwInternalCallback( [&etwRegistrationManager, this]( LPCGUID SourceId, ULONG IsEnabled, @@ -270,6 +270,7 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio (void)qnn_backend_manager_->ResetQnnLogLevel(); } }); + etwRegistrationManager.RegisterInternalCallback(callback_ETWSink_provider_); #endif // In case ETW gets disabled later @@ -397,6 +398,11 @@ QNNExecutionProvider::~QNNExecutionProvider() { if (!cache) continue; ORT_IGNORE_RETURN_VALUE(cache->erase(this)); } + + // Unregister the ETW callback +#ifdef _WIN32 + logging::EtwRegistrationManager::Instance().UnregisterInternalCallback(callback_ETWSink_provider_); +#endif } bool QNNExecutionProvider::IsNodeSupported(qnn::QnnModelWrapper& qnn_model_wrapper, const NodeUnit& node_unit, diff --git a/onnxruntime/core/providers/qnn/qnn_execution_provider.h b/onnxruntime/core/providers/qnn/qnn_execution_provider.h index c5d3098f87..e7419dabb1 100644 --- a/onnxruntime/core/providers/qnn/qnn_execution_provider.h +++ b/onnxruntime/core/providers/qnn/qnn_execution_provider.h @@ -15,6 +15,9 @@ #include #include #include +#ifdef _WIN32 +#include "core/platform/windows/logging/etw_sink.h" +#endif namespace onnxruntime { @@ -86,6 +89,9 @@ class QNNExecutionProvider : public IExecutionProvider { qnn::HtpPerformanceMode default_htp_performance_mode_ = qnn::HtpPerformanceMode::kHtpDefault; uint32_t default_rpc_control_latency_ = 0; bool enable_HTP_FP16_precision_ = false; +#ifdef _WIN32 + onnxruntime::logging::EtwRegistrationManager::EtwInternalCallback callback_ETWSink_provider_; +#endif class PerThreadContext final { public: diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index e8d33bc154..03049c4b51 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -250,6 +250,7 @@ std::atomic InferenceSession::global_session_id_{1}; std::map InferenceSession::active_sessions_; #ifdef _WIN32 OrtMutex InferenceSession::active_sessions_mutex_; // Protects access to active_sessions_ +onnxruntime::WindowsTelemetry::EtwInternalCallback InferenceSession::callback_ML_ORT_provider_; #endif static Status FinalizeSessionOptions(const SessionOptions& user_provided_session_options, @@ -374,15 +375,14 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options, active_sessions_[global_session_id_++] = this; // Register callback for ETW capture state (rundown) for Microsoft.ML.ONNXRuntime provider - WindowsTelemetry::RegisterInternalCallback( - [this]( - LPCGUID SourceId, - ULONG IsEnabled, - UCHAR Level, - ULONGLONG MatchAnyKeyword, - ULONGLONG MatchAllKeyword, - PEVENT_FILTER_DESCRIPTOR FilterData, - PVOID CallbackContext) { + callback_ML_ORT_provider_ = onnxruntime::WindowsTelemetry::EtwInternalCallback( + [this](LPCGUID SourceId, + ULONG IsEnabled, + UCHAR Level, + ULONGLONG MatchAnyKeyword, + ULONGLONG MatchAllKeyword, + PEVENT_FILTER_DESCRIPTOR FilterData, + PVOID CallbackContext) { (void)SourceId; (void)Level; (void)MatchAnyKeyword; @@ -396,19 +396,18 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options, LogAllSessions(); } }); + WindowsTelemetry::RegisterInternalCallback(callback_ML_ORT_provider_); // Register callback for ETW start / stop so that LOGS tracing can be adjusted dynamically after session start auto& etwRegistrationManager = logging::EtwRegistrationManager::Instance(); - // Register callback for ETW capture state (rundown) - etwRegistrationManager.RegisterInternalCallback( - [&etwRegistrationManager, this]( - LPCGUID SourceId, - ULONG IsEnabled, - UCHAR Level, - ULONGLONG MatchAnyKeyword, - ULONGLONG MatchAllKeyword, - PEVENT_FILTER_DESCRIPTOR FilterData, - PVOID CallbackContext) { + callback_ETWSink_provider_ = onnxruntime::logging::EtwRegistrationManager::EtwInternalCallback( + [&etwRegistrationManager, this](LPCGUID SourceId, + ULONG IsEnabled, + UCHAR Level, + ULONGLONG MatchAnyKeyword, + ULONGLONG MatchAllKeyword, + PEVENT_FILTER_DESCRIPTOR FilterData, + PVOID CallbackContext) { (void)SourceId; (void)Level; (void)MatchAnyKeyword; @@ -439,6 +438,10 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options, } } }); + + // Register callback for ETW capture state (rundown) + etwRegistrationManager.RegisterInternalCallback(callback_ETWSink_provider_); + #endif SetLoggingManager(session_options, session_env); @@ -720,9 +723,11 @@ InferenceSession::~InferenceSession() { } } - // Unregister the session + // Unregister the session and ETW callbacks #ifdef _WIN32 std::lock_guard lock(active_sessions_mutex_); + WindowsTelemetry::UnregisterInternalCallback(callback_ML_ORT_provider_); + logging::EtwRegistrationManager::Instance().UnregisterInternalCallback(callback_ETWSink_provider_); #endif active_sessions_.erase(global_session_id_); diff --git a/onnxruntime/core/session/inference_session.h b/onnxruntime/core/session/inference_session.h index 204b24974f..77fba90b56 100644 --- a/onnxruntime/core/session/inference_session.h +++ b/onnxruntime/core/session/inference_session.h @@ -35,6 +35,10 @@ #include "core/platform/tracing.h" #include #endif +#ifdef _WIN32 +#include "core/platform/windows/logging/etw_sink.h" +#include "core/platform/windows/telemetry.h" +#endif namespace ONNX_NAMESPACE { class ModelProto; @@ -124,6 +128,8 @@ class InferenceSession { static std::map active_sessions_; #ifdef _WIN32 static OrtMutex active_sessions_mutex_; // Protects access to active_sessions_ + static onnxruntime::WindowsTelemetry::EtwInternalCallback callback_ML_ORT_provider_; + onnxruntime::logging::EtwRegistrationManager::EtwInternalCallback callback_ETWSink_provider_; #endif public: