Skip to content

Improve Windows ETW callback registration and fix issues #24877

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 6 commits into
base: main
Choose a base branch
from
+368 −294
Open

Improve Windows ETW callback registration and fix issues #24877

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
6d6aa47
Address the following problems:
yuslepukhin May 22, 2025
b8bb316
Reinstate LazyInitialization
yuslepukhin May 27, 2025
eaeffa8
Refactor QNN
yuslepukhin May 27, 2025
6ab0185
Address review comments
yuslepukhin May 28, 2025
0a14578
This commit contains the following:
yuslepukhin May 29, 2025
e62225b
Restore atomic update of provider changes
yuslepukhin May 30, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
98 changes: 98 additions & 0 deletions onnxruntime/core/framework/execution_provider.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
// Copyright (c) Microsoft Corporation. All rights reserved.
// Licensed under the MIT License.
#include "core/framework/execution_provider.h"
#include "core/framework/execution_providers.h"

#include "core/graph/graph_viewer.h"
#include "core/framework/compute_capability.h"
Expand All @@ -9,6 +10,8 @@
#include "core/framework/murmurhash3.h"
#include "core/framework/op_kernel.h"

#include <stdint.h>

Check warning on line 13 in onnxruntime/core/framework/execution_provider.cc

View workflow job for this annotation

GitHub Actions / Optional Lint C++ 

[cpplint] reported by reviewdog 🐶
 Found C system header after other header. Should be: execution_provider.h, c system, c++ system, other.  [build/include_order] [4]

Raw Output:
onnxruntime/core/framework/execution_provider.cc:13:  Found C system header after other header. Should be: execution_provider.h, c system, c++ system, other.  [build/include_order] [4]

namespace onnxruntime {

std::vector<std::unique_ptr<ComputeCapability>>
Expand Down Expand Up @@ -37,4 +40,99 @@
}

#endif

ExecutionProviders::ExecutionProviders() {
#ifdef _WIN32
// Register callback for ETW capture state (rundown)
etw_callback_key_ = "ExecutionProviders_rundown_";
etw_callback_key_.append(std::to_string(reinterpret_cast<uintptr_t>(this)));
WindowsTelemetry::RegisterInternalCallback(
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So each session will register a callback.
And each callback will be invoked for each session.
This is O(N^2)!

Copy link
Member Author

@yuslepukhin yuslepukhin May 30, 2025 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Each instance of ExecutionProviders would register a callback, this has not changed.
It would log all EPs that were added to the instance.
In theory, each instance can have different set of EPs.
Question is, what should this be? @ivberg

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It should be that each EP logs it's options. Taking a trace with captureState rundown is an unusual diagnostic event so happens quite rarely

etw_callback_key_,
[this](LPCGUID SourceId,
ULONG IsEnabled,
UCHAR Level,
ULONGLONG MatchAnyKeyword,
ULONGLONG MatchAllKeyword,
PEVENT_FILTER_DESCRIPTOR FilterData,
PVOID CallbackContext) { this->EtwProvidersCallback(SourceId, IsEnabled, Level,
MatchAnyKeyword, MatchAllKeyword,
FilterData, CallbackContext); });
#endif
}

ExecutionProviders::~ExecutionProviders() {
#ifdef _WIN32
WindowsTelemetry::UnregisterInternalCallback(etw_callback_key_);
#endif
}

common::Status ExecutionProviders::Add(const std::string& provider_id,
const std::shared_ptr<IExecutionProvider>& p_exec_provider) {

Check warning on line 70 in onnxruntime/core/framework/execution_provider.cc

View workflow job for this annotation

GitHub Actions / Optional Lint C++ 

[cpplint] reported by reviewdog 🐶
 Add #include <memory> for shared_ptr<>  [build/include_what_you_use] [4]

Raw Output:
onnxruntime/core/framework/execution_provider.cc:70:  Add #include <memory> for shared_ptr<>  [build/include_what_you_use] [4]
// 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);
exec_providers_.push_back(p_exec_provider);
return Status::OK();
}

#ifdef _WIN32
void ExecutionProviders::EtwProvidersCallback(LPCGUID /* SourceId */,
ULONG IsEnabled,
UCHAR /* Level */,
ULONGLONG MatchAnyKeyword,
ULONGLONG /* MatchAllKeyword */,
PEVENT_FILTER_DESCRIPTOR /* FilterData */,
PVOID /* CallbackContext */) {
// Check if this callback is for capturing state
if ((IsEnabled == EVENT_CONTROL_CODE_CAPTURE_STATE) &&
((MatchAnyKeyword & static_cast<ULONGLONG>(onnxruntime::logging::ORTTraceLoggingKeyword::Session)) != 0)) {
for (size_t i = 0; i < exec_providers_.size(); ++i) {
const auto& provider_id = exec_provider_ids_[i];

auto it = exec_provider_options_.find(provider_id);
if (it != exec_provider_options_.end()) {
const auto& options = it->second;

LogProviderOptions(provider_id, options, true);
}
}
}
}

void ExecutionProviders::LogProviderOptions(const std::string& provider_id,

Check warning on line 120 in onnxruntime/core/framework/execution_provider.cc

View workflow job for this annotation

GitHub Actions / Optional Lint C++ 

[cpplint] reported by reviewdog 🐶
 Add #include <string> for string  [build/include_what_you_use] [4]

Raw Output:
onnxruntime/core/framework/execution_provider.cc:120:  Add #include <string> for string  [build/include_what_you_use] [4]
const ProviderOptions& providerOptions,
bool captureState) {
for (const auto& config_pair : providerOptions) {
TraceLoggingWrite(
telemetry_provider_handle,
"ProviderOptions",
TraceLoggingKeyword(static_cast<uint64_t>(onnxruntime::logging::ORTTraceLoggingKeyword::Session)),
TraceLoggingLevel(WINEVENT_LEVEL_INFO),
TraceLoggingString(provider_id.c_str(), "ProviderId"),
TraceLoggingString(config_pair.first.c_str(), "Key"),
TraceLoggingString(config_pair.second.c_str(), "Value"),
TraceLoggingBool(captureState, "isCaptureState"));
}
}

#endif

} // namespace onnxruntime
93 changes: 13 additions & 80 deletions onnxruntime/core/framework/execution_providers.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -26,91 +26,24 @@ Class for managing lookup of the execution providers in a session.
*/
class ExecutionProviders {
public:
ExecutionProviders() {
#ifdef _WIN32
// Register callback for ETW capture state (rundown)
etw_callback_ = 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;
(void)MatchAllKeyword;
(void)FilterData;
(void)CallbackContext;

// Check if this callback is for capturing state
if ((IsEnabled == EVENT_CONTROL_CODE_CAPTURE_STATE) &&
((MatchAnyKeyword & static_cast<ULONGLONG>(onnxruntime::logging::ORTTraceLoggingKeyword::Session)) != 0)) {
for (size_t i = 0; i < exec_providers_.size(); ++i) {
const auto& provider_id = exec_provider_ids_[i];

auto it = exec_provider_options_.find(provider_id);
if (it != exec_provider_options_.end()) {
const auto& options = it->second;

LogProviderOptions(provider_id, options, true);
}
}
}
});
WindowsTelemetry::RegisterInternalCallback(etw_callback_);
#endif
}

~ExecutionProviders() {
#ifdef _WIN32
WindowsTelemetry ::UnregisterInternalCallback(etw_callback_);
#endif
}
ExecutionProviders();

common::Status
Add(const std::string& provider_id, const std::shared_ptr<IExecutionProvider>& 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;
}
~ExecutionProviders();

// 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;
common::Status Add(const std::string& provider_id, const std::shared_ptr<IExecutionProvider>& p_exec_provider);

#ifdef _WIN32
LogProviderOptions(provider_id, providerOptions, false);
#endif

exec_provider_ids_.push_back(provider_id);
exec_providers_.push_back(p_exec_provider);
return Status::OK();
}
void EtwProvidersCallback(LPCGUID SourceId,
ULONG IsEnabled,
UCHAR Level,
ULONGLONG MatchAnyKeyword,
ULONGLONG MatchAllKeyword,
PEVENT_FILTER_DESCRIPTOR FilterData,
PVOID CallbackContext);

#ifdef _WIN32
void LogProviderOptions(const std::string& provider_id, const ProviderOptions& providerOptions, bool captureState) {
for (const auto& config_pair : providerOptions) {
TraceLoggingWrite(
telemetry_provider_handle,
"ProviderOptions",
TraceLoggingKeyword(static_cast<uint64_t>(onnxruntime::logging::ORTTraceLoggingKeyword::Session)),
TraceLoggingLevel(WINEVENT_LEVEL_INFO),
TraceLoggingString(provider_id.c_str(), "ProviderId"),
TraceLoggingString(config_pair.first.c_str(), "Key"),
TraceLoggingString(config_pair.second.c_str(), "Value"),
TraceLoggingBool(captureState, "isCaptureState"));
}
}
void LogProviderOptions(const std::string& provider_id, const ProviderOptions& providerOptions,
bool captureState);
#endif

const IExecutionProvider* Get(const onnxruntime::Node& node) const {
Expand Down Expand Up @@ -169,7 +102,7 @@ class ExecutionProviders {
bool cpu_execution_provider_was_implicitly_added_ = false;

#ifdef _WIN32
WindowsTelemetry::EtwInternalCallback etw_callback_;
std::string etw_callback_key_;
#endif
};
} // namespace onnxruntime
48 changes: 21 additions & 27 deletions onnxruntime/core/platform/windows/logging/etw_sink.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -106,18 +106,15 @@
return etw_status_;
}

void EtwRegistrationManager::RegisterInternalCallback(const EtwInternalCallback& callback) {
void EtwRegistrationManager::RegisterInternalCallback(const std::string& cb_key, EtwInternalCallback callback) {
std::lock_guard<std::mutex> lock(callbacks_mutex_);
callbacks_.push_back(&callback);
[[maybe_unused]] auto result = callbacks_.emplace(cb_key, std::move(callback));

Check warning on line 111 in onnxruntime/core/platform/windows/logging/etw_sink.cc

View workflow job for this annotation

GitHub Actions / Optional Lint C++ 

[cpplint] reported by reviewdog 🐶
 Add #include <utility> for move  [build/include_what_you_use] [4]

Raw Output:
onnxruntime/core/platform/windows/logging/etw_sink.cc:111:  Add #include <utility> for move  [build/include_what_you_use] [4]
assert(result.second);
}

void EtwRegistrationManager::UnregisterInternalCallback(const EtwInternalCallback& callback) {
void EtwRegistrationManager::UnregisterInternalCallback(const std::string& cb_key) {
std::lock_guard<std::mutex> 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());
callbacks_.erase(cb_key);
}

void NTAPI EtwRegistrationManager::ORT_TL_EtwEnableCallback(
Expand All @@ -138,21 +135,12 @@
manager.InvokeCallbacks(SourceId, IsEnabled, Level, MatchAnyKeyword, MatchAllKeyword, FilterData, CallbackContext);
}

EtwRegistrationManager::~EtwRegistrationManager() {
std::lock_guard<std::mutex> lock(callbacks_mutex_);
callbacks_.clear();
if (initialization_status_ == InitializationStatus::Initialized ||
initialization_status_ == InitializationStatus::Initializing) {
std::lock_guard<std::mutex> init_lock(init_mutex_);
assert(initialization_status_ != InitializationStatus::Initializing);
if (initialization_status_ == InitializationStatus::Initialized) {
::TraceLoggingUnregister(etw_provider_handle);
initialization_status_ = InitializationStatus::NotInitialized;
}
}
}

EtwRegistrationManager::EtwRegistrationManager() {
EtwRegistrationManager::EtwRegistrationManager()
: initialization_status_(InitializationStatus::NotInitialized),
is_enabled_(false),
level_(),
keyword_(0),
etw_status_(S_OK) {
}

void EtwRegistrationManager::LazyInitialize() {
Expand All @@ -173,6 +161,13 @@
}
}

EtwRegistrationManager::~EtwRegistrationManager() {
if (initialization_status_ == InitializationStatus::Initialized) {
::TraceLoggingUnregister(etw_provider_handle);
initialization_status_ = InitializationStatus::NotInitialized;
}
}

void EtwRegistrationManager::InvokeCallbacks(LPCGUID SourceId, ULONG IsEnabled, UCHAR Level, ULONGLONG MatchAnyKeyword,
ULONGLONG MatchAllKeyword, PEVENT_FILTER_DESCRIPTOR FilterData,
PVOID CallbackContext) {
Expand All @@ -182,10 +177,9 @@
}

std::lock_guard<std::mutex> lock(callbacks_mutex_);
for (const auto& callback : callbacks_) {
if (callback != nullptr) {
(*callback)(SourceId, IsEnabled, Level, MatchAnyKeyword, MatchAllKeyword, FilterData, CallbackContext);
}
for (const auto& entry : callbacks_) {
const auto& cb = entry.second;
cb(SourceId, IsEnabled, Level, MatchAnyKeyword, MatchAllKeyword, FilterData, CallbackContext);
}
}

Expand Down
15 changes: 8 additions & 7 deletions onnxruntime/core/platform/windows/logging/etw_sink.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@
#include <atomic>
#include <iostream>
#include <string>
#include <unordered_map>
#include <vector>

#include "core/common/logging/capture.h"
Expand Down Expand Up @@ -77,9 +78,9 @@
// Get the ETW registration status
HRESULT Status() const;

void RegisterInternalCallback(const EtwInternalCallback& callback);
void RegisterInternalCallback(const std::string& cb_key, EtwInternalCallback callback);

void UnregisterInternalCallback(const EtwInternalCallback& callback);
void UnregisterInternalCallback(const std::string& cb_key);

private:
EtwRegistrationManager();
Expand All @@ -100,11 +101,11 @@
_In_opt_ PEVENT_FILTER_DESCRIPTOR FilterData,
_In_opt_ PVOID CallbackContext);

std::vector<const EtwInternalCallback*> callbacks_;
std::mutex init_mutex_;
std::atomic<InitializationStatus> initialization_status_ = InitializationStatus::NotInitialized;
std::unordered_map<std::string, EtwInternalCallback> callbacks_;

Check warning on line 106 in onnxruntime/core/platform/windows/logging/etw_sink.h

View workflow job for this annotation

GitHub Actions / Optional Lint C++ 

[cpplint] reported by reviewdog 🐶
 Add #include <unordered_map> for unordered_map<>  [build/include_what_you_use] [4]

Raw Output:
onnxruntime/core/platform/windows/logging/etw_sink.h:106:  Add #include <unordered_map> for unordered_map<>  [build/include_what_you_use] [4]
std::mutex callbacks_mutex_;
mutable std::mutex provider_change_mutex_;
std::mutex init_mutex_;
InitializationStatus initialization_status_ = InitializationStatus::NotInitialized;
bool is_enabled_;
UCHAR level_;
ULONGLONG keyword_;
Expand Down Expand Up @@ -133,8 +134,8 @@
Severity MapLevelToSeverity() { return Severity::kFATAL; }
uint64_t Keyword() const { return 0; }
HRESULT Status() const { return 0; }
void RegisterInternalCallback(const EtwInternalCallback& callback) {}
void UnregisterInternalCallback(const EtwInternalCallback& callback) {}
void RegisterInternalCallback(const std::string& cb_key, EtwInternalCallback callback) {}
void UnregisterInternalCallback(const std::string& cb_key) {}

Check warning on line 138 in onnxruntime/core/platform/windows/logging/etw_sink.h

View workflow job for this annotation

GitHub Actions / Optional Lint C++ 

[cpplint] reported by reviewdog 🐶
 Add #include <string> for string  [build/include_what_you_use] [4]

Raw Output:
onnxruntime/core/platform/windows/logging/etw_sink.h:138:  Add #include <string> for string  [build/include_what_you_use] [4]

private:
EtwRegistrationManager() = default;
Expand Down
Loading
Loading