Fully dynamic ETW controlled logging for ORT and QNN logs (#20537)

### Description
Windows - Fully dynamic ETW controlled logging for ORT and QNN logs

The logging support is documented here 
-
https://onnxruntime.ai/docs/performance/tune-performance/logging_tracing.html#tracing---windows
-
https://onnxruntime.ai/docs/performance/tune-performance/profiling-tools.html#tracelogging-etw-windows-profiling

Also add support for logging ORT SessionCreation on ETW CaptureState

### Motivation and Context
The previous ETW support only worked if you enabled ETW before the
session started. There can commonly be long-lived AI inference processes
that need to be traced & debugged. This enables logging fully on the
fly.

Without this support a dev would have to end up killing a process or
stopping a service in order to get tracing. We had to do this for a
recent issue with QNN, and it was a bit painful to get the logs and it
ruined the repro.

### Testing
I tested with the following cases
- Leaving default ORT run
- Enabling ETW prior to start and leaving running for entire session +
inferences, then stopping
- Starting ORT session + inf, then enabling and stopping ETW
  - Start ORT session /w long running Inferences 
- wpr -start
[ort.wprp](e6228575e4/ort.wprp (L4))
-start
[etw_provider.wprp](e6228575e4/onnxruntime/test/platform/windows/logging/etw_provider.wprp)
  - Wait a few seconds
  - wpr -stop ort.etl
  - Inferences are still running
- Verify ONNXRuntimeLogEvent provider events are present and new
SessionCreation_CaptureState event under Microsoft.ML.ONNXRuntime
provider

Related:
#18882
#19428
This commit is contained in:
ivberg 2024-06-06 21:11:14 -07:00 committed by GitHub
parent f8b5c2805e
commit 74028e4bdc
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
19 changed files with 507 additions and 102 deletions

View file

@ -6,12 +6,15 @@
#include <string>
#include "core/common/logging/logging.h"
#include "core/common/logging/sink_types.h"
namespace onnxruntime {
namespace logging {
class ISink {
public:
ISink() = default;
explicit ISink(SinkType type = SinkType::BaseSink) : type_(type) {}
SinkType GetType() const { return type_; }
/**
Sends the message to the sink.
@ -32,6 +35,8 @@ class ISink {
virtual ~ISink() = default;
private:
SinkType type_;
// Make Code Analysis happy by disabling all for now. Enable as needed.
ORT_DISALLOW_COPY_ASSIGNMENT_AND_MOVE(ISink);

View file

@ -14,10 +14,10 @@
#include "core/common/common.h"
#include "core/common/profiler_common.h"
#include "core/common/logging/capture.h"
#include "core/common/logging/severity.h"
#include "core/common/logging/macros.h"
#include "core/common/logging/severity.h"
#include "core/common/logging/sink_types.h"
#include "core/platform/ort_mutex.h"
#include "date/date.h"
/*
@ -167,6 +167,23 @@ class LoggingManager final {
*/
static bool HasDefaultLogger() { return nullptr != s_default_logger_; }
/**
Gets the default instance of the LoggingManager.
*/
static LoggingManager* GetDefaultInstance();
/**
Removes a Sink if one is present
*/
void RemoveSink(SinkType sinkType);
/**
Adds a Sink to the current sink creating a CompositeSink if necessary
Sinks types must be unique
@param severity The severity level for the new Sink
*/
bool AddSinkOfType(SinkType sinkType, std::function<std::unique_ptr<ISink>()> sinkFactory, logging::Severity severity);
/**
Change the minimum severity level for log messages to be output by the default logger.
@param severity The severity.
@ -214,7 +231,10 @@ class LoggingManager final {
void CreateDefaultLogger(const std::string& logger_id);
std::unique_ptr<ISink> sink_;
const Severity default_min_severity_;
#ifdef _WIN32
mutable OrtMutex sink_mutex_;
#endif
Severity default_min_severity_;
const bool default_filter_user_data_;
const int default_max_vlog_level_;
bool owns_default_logger_;
@ -362,8 +382,8 @@ unsigned int GetProcessId();
/**
If the ONNXRuntimeTraceLoggingProvider ETW Provider is enabled, then adds to the existing logger.
*/
std::unique_ptr<ISink> EnhanceLoggerWithEtw(std::unique_ptr<ISink> existingLogger, logging::Severity originalSeverity,
logging::Severity etwSeverity);
std::unique_ptr<ISink> EnhanceSinkWithEtw(std::unique_ptr<ISink> existingSink, logging::Severity originalSeverity,
logging::Severity etwSeverity);
/**
If the ONNXRuntimeTraceLoggingProvider ETW Provider is enabled, then can override the logging level.

View file

@ -0,0 +1,11 @@
#pragma once
namespace onnxruntime {
namespace logging {
enum class SinkType {
BaseSink,
CompositeSink,
EtwSink
};
} // namespace logging
} // namespace onnxruntime

View file

@ -9,11 +9,11 @@
#include "core/common/exceptions.h"
#include "core/common/logging/isink.h"
#include "core/common/logging/logging.h"
#include "core/common/logging/sinks/composite_sink.h"
#ifdef _WIN32
#include <Windows.h>
#include "core/platform/windows/logging/etw_sink.h"
#include "core/common/logging/sinks/composite_sink.h"
#else
#include <unistd.h>
#if defined(__MACH__) || defined(__wasm__) || defined(_AIX)
@ -22,10 +22,10 @@
#include <sys/syscall.h>
#endif
#endif
#include "core/platform/ort_mutex.h"
#if __FreeBSD__
#include <sys/thr.h> // Use thr_self() syscall under FreeBSD to get thread id
#include "logging.h"
#endif
namespace onnxruntime {
@ -52,6 +52,10 @@ static std::atomic<void*>& DefaultLoggerManagerInstance() noexcept {
return default_instance;
}
LoggingManager* LoggingManager::GetDefaultInstance() {
return static_cast<LoggingManager*>(DefaultLoggerManagerInstance().load());
}
// GSL_SUPRESS(i.22) is broken. Ignore the warnings for the static local variables that are trivial
// and should not have any destruction order issues via pragmas instead.
// https://developercommunity.visualstudio.com/content/problem/249706/gslsuppress-does-not-work-for-i22-c-core-guideline.html
@ -66,6 +70,7 @@ static OrtMutex& DefaultLoggerMutex() noexcept {
}
Logger* LoggingManager::s_default_logger_ = nullptr;
OrtMutex sink_mutex_;
#ifdef _MSC_VER
#pragma warning(pop)
@ -245,27 +250,27 @@ unsigned int GetProcessId() {
#endif
}
std::unique_ptr<ISink> EnhanceLoggerWithEtw(std::unique_ptr<ISink> existingLogger, logging::Severity originalSeverity,
logging::Severity etwSeverity) {
std::unique_ptr<ISink> EnhanceSinkWithEtw(std::unique_ptr<ISink> existing_sink, logging::Severity original_severity,
logging::Severity etw_severity) {
#ifdef _WIN32
auto& manager = EtwRegistrationManager::Instance();
if (manager.IsEnabled()) {
auto compositeSink = std::make_unique<CompositeSink>();
compositeSink->AddSink(std::move(existingLogger), originalSeverity);
compositeSink->AddSink(std::make_unique<EtwSink>(), etwSeverity);
compositeSink->AddSink(std::move(existing_sink), original_severity);
compositeSink->AddSink(std::make_unique<EtwSink>(), etw_severity);
return compositeSink;
} else {
return existingLogger;
return existing_sink;
}
#else
// On non-Windows platforms, just return the existing logger
(void)originalSeverity;
(void)etwSeverity;
return existingLogger;
(void)original_severity;
(void)etw_severity;
return existing_sink;
#endif // _WIN32
}
Severity OverrideLevelWithEtw(Severity originalSeverity) {
Severity OverrideLevelWithEtw(Severity original_severity) {
#ifdef _WIN32
auto& manager = logging::EtwRegistrationManager::Instance();
if (manager.IsEnabled() &&
@ -273,7 +278,50 @@ Severity OverrideLevelWithEtw(Severity originalSeverity) {
return manager.MapLevelToSeverity();
}
#endif // _WIN32
return originalSeverity;
return original_severity;
}
bool LoggingManager::AddSinkOfType(SinkType sink_type, std::function<std::unique_ptr<ISink>()> sinkFactory,
logging::Severity severity) {
std::lock_guard<OrtMutex> guard(sink_mutex_);
if (sink_->GetType() != SinkType::CompositeSink) {
// Current sink is not a composite, create a new composite sink and add the current sink to it
auto new_composite = std::make_unique<CompositeSink>();
new_composite->AddSink(std::move(sink_), default_min_severity_); // Move the current sink into the new composite
sink_ = std::move(new_composite); // Now sink_ is pointing to the new composite
}
// Adjust the default minimum severity level to accommodate new sink needs
default_min_severity_ = std::min(default_min_severity_, severity);
if (s_default_logger_ != nullptr) {
s_default_logger_->SetSeverity(default_min_severity_);
}
CompositeSink* current_composite = static_cast<CompositeSink*>(sink_.get());
if (current_composite->HasType(sink_type)) {
return false; // Sink of this type already exists, do not add another
}
current_composite->AddSink(sinkFactory(), severity);
return true;
}
void LoggingManager::RemoveSink(SinkType sink_type) {
std::lock_guard<OrtMutex> guard(sink_mutex_);
if (sink_->GetType() == SinkType::CompositeSink) {
auto composite_sink = static_cast<CompositeSink*>(sink_.get());
Severity newSeverity = composite_sink->RemoveSink(sink_type);
if (composite_sink->HasOnlyOneSink()) {
// If only one sink remains, replace the CompositeSink with this single sink
sink_ = composite_sink->GetRemoveSingleSink();
}
default_min_severity_ = newSeverity;
if (s_default_logger_ != nullptr) {
s_default_logger_->SetSeverity(default_min_severity_);
}
}
}
} // namespace logging

View file

@ -23,7 +23,17 @@ class CompositeSink : public ISink {
/// Initializes a new instance of the <see cref="CompositeSink"/> class.
/// Use AddSink to add sinks.
/// </summary>
CompositeSink() {}
CompositeSink() : ISink(SinkType::CompositeSink) {}
/// <summary>
/// Check if the composite sink contains a sink of the specified type.
/// </summary>
bool HasType(SinkType sink_type) const {
return std::any_of(sinks_with_severity_.begin(), sinks_with_severity_.end(),
[&](const auto& sink_pair) {
return sink_pair.first->GetType() == sink_type;
});
}
/// <summary>
/// Adds a sink. Takes ownership of the sink (so pass unique_ptr by value).
@ -37,11 +47,48 @@ class CompositeSink : public ISink {
}
/// <summary>
/// Gets a const reference to the collection of sinks and min severity for that sink
/// Remove a sink of the specified type.
/// </summary>
/// <returns>A const reference to the vector pair of unique_ptr to ISink and severity.</returns>
const std::vector<std::pair<std::unique_ptr<ISink>, logging::Severity>>& GetSinks() const {
return sinks_with_severity_;
/// <param name="sink_type">Sink type to remove</param>
/// <returns>Minimum severity of the remaining sinks</returns>
logging::Severity RemoveSink(SinkType sink_type) {
logging::Severity severity = Severity::kFATAL; // default if we end up with no sinks
// find entries to remove and the minimum severity of the remaining sinks
auto entries_to_remove = std::remove_if(sinks_with_severity_.begin(), sinks_with_severity_.end(),
[&](const auto& entry) {
if (entry.first->GetType() == sink_type) {
return true;
} else {
severity = std::min(severity, entry.second);
return false;
}
});
sinks_with_severity_.erase(entries_to_remove, sinks_with_severity_.end());
return severity;
}
/// <summary>
/// Check if there's only one sink left
/// </summary>
/// <returns> True if only 1 sink remaining </returns>
bool HasOnlyOneSink() const {
return sinks_with_severity_.size() == 1;
}
/// <summary>
/// If one sink is remaining then returns it and empties the composite sink
/// </summary>
/// <returns> If one sink remains then returns the sink, otherwise nullptr </returns>
std::unique_ptr<ISink> GetRemoveSingleSink() {
if (HasOnlyOneSink()) {
auto single_sink = std::move(sinks_with_severity_.begin()->first);
sinks_with_severity_.clear();
return single_sink;
}
return nullptr;
}
private:

View file

@ -55,7 +55,7 @@ void Telemetry::LogSessionCreation(uint32_t session_id, int64_t ir_version, cons
const std::string& model_graph_name,
const std::unordered_map<std::string, std::string>& model_metadata,
const std::string& loadedFrom, const std::vector<std::string>& execution_provider_ids,
bool use_fp16) const {
bool use_fp16, bool captureState) const {
ORT_UNUSED_PARAMETER(session_id);
ORT_UNUSED_PARAMETER(ir_version);
ORT_UNUSED_PARAMETER(model_producer_name);
@ -67,6 +67,7 @@ void Telemetry::LogSessionCreation(uint32_t session_id, int64_t ir_version, cons
ORT_UNUSED_PARAMETER(loadedFrom);
ORT_UNUSED_PARAMETER(execution_provider_ids);
ORT_UNUSED_PARAMETER(use_fp16);
ORT_UNUSED_PARAMETER(captureState);
}
void Telemetry::LogRuntimeError(uint32_t session_id, const common::Status& status, const char* file,

View file

@ -60,7 +60,7 @@ class Telemetry {
const std::string& model_graph_name,
const std::unordered_map<std::string, std::string>& model_metadata,
const std::string& loadedFrom, const std::vector<std::string>& execution_provider_ids,
bool use_fp16) const;
bool use_fp16, bool captureState) const;
virtual void LogRuntimeError(uint32_t session_id, const common::Status& status, const char* file,
const char* function, uint32_t line) const;

View file

@ -31,7 +31,7 @@ namespace logging {
class EtwSink : public ISink {
public:
EtwSink() = default;
EtwSink() : ISink(SinkType::EtwSink) {}
~EtwSink() = default;
constexpr static const char* kEventName = "ONNXRuntimeLogEvent";

View file

@ -210,23 +210,23 @@ void WindowsTelemetry::LogSessionCreation(uint32_t session_id, int64_t ir_versio
const std::string& model_graph_name,
const std::unordered_map<std::string, std::string>& model_metadata,
const std::string& loaded_from, const std::vector<std::string>& execution_provider_ids,
bool use_fp16) const {
bool use_fp16, bool captureState) const {
if (global_register_count_ == 0 || enabled_ == false)
return;
// build the strings we need
std::string domain_to_verison_string;
std::string domain_to_version_string;
bool first = true;
for (auto& i : domain_to_version_map) {
if (first) {
first = false;
} else {
domain_to_verison_string += ',';
domain_to_version_string += ',';
}
domain_to_verison_string += i.first;
domain_to_verison_string += '=';
domain_to_verison_string += std::to_string(i.second);
domain_to_version_string += i.first;
domain_to_version_string += '=';
domain_to_version_string += std::to_string(i.second);
}
std::string model_metadata_string;
@ -253,27 +253,52 @@ void WindowsTelemetry::LogSessionCreation(uint32_t session_id, int64_t ir_versio
execution_provider_string += i;
}
TraceLoggingWrite(telemetry_provider_handle,
"SessionCreation",
TraceLoggingBool(true, "UTCReplace_AppSessionGuid"),
TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage),
TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES),
TraceLoggingKeyword(static_cast<uint64_t>(onnxruntime::logging::ORTTraceLoggingKeyword::Session)),
TraceLoggingLevel(WINEVENT_LEVEL_INFO),
// Telemetry info
TraceLoggingUInt8(0, "schemaVersion"),
TraceLoggingUInt32(session_id, "sessionId"),
TraceLoggingInt64(ir_version, "irVersion"),
TraceLoggingUInt32(projection_, "OrtProgrammingProjection"),
TraceLoggingString(model_producer_name.c_str(), "modelProducerName"),
TraceLoggingString(model_producer_version.c_str(), "modelProducerVersion"),
TraceLoggingString(model_domain.c_str(), "modelDomain"),
TraceLoggingBool(use_fp16, "usefp16"),
TraceLoggingString(domain_to_verison_string.c_str(), "domainToVersionMap"),
TraceLoggingString(model_graph_name.c_str(), "modelGraphName"),
TraceLoggingString(model_metadata_string.c_str(), "modelMetaData"),
TraceLoggingString(loaded_from.c_str(), "loadedFrom"),
TraceLoggingString(execution_provider_string.c_str(), "executionProviderIds"));
// Difference is MeasureEvent & isCaptureState, but keep in sync otherwise
if (!captureState) {
TraceLoggingWrite(telemetry_provider_handle,
"SessionCreation",
TraceLoggingBool(true, "UTCReplace_AppSessionGuid"),
TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage),
TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES),
TraceLoggingKeyword(static_cast<uint64_t>(onnxruntime::logging::ORTTraceLoggingKeyword::Session)),
TraceLoggingLevel(WINEVENT_LEVEL_INFO),
// Telemetry info
TraceLoggingUInt8(0, "schemaVersion"),
TraceLoggingUInt32(session_id, "sessionId"),
TraceLoggingInt64(ir_version, "irVersion"),
TraceLoggingUInt32(projection_, "OrtProgrammingProjection"),
TraceLoggingString(model_producer_name.c_str(), "modelProducerName"),
TraceLoggingString(model_producer_version.c_str(), "modelProducerVersion"),
TraceLoggingString(model_domain.c_str(), "modelDomain"),
TraceLoggingBool(use_fp16, "usefp16"),
TraceLoggingString(domain_to_version_string.c_str(), "domainToVersionMap"),
TraceLoggingString(model_graph_name.c_str(), "modelGraphName"),
TraceLoggingString(model_metadata_string.c_str(), "modelMetaData"),
TraceLoggingString(loaded_from.c_str(), "loadedFrom"),
TraceLoggingString(execution_provider_string.c_str(), "executionProviderIds"));
} else {
TraceLoggingWrite(telemetry_provider_handle,
"SessionCreation_CaptureState",
TraceLoggingBool(true, "UTCReplace_AppSessionGuid"),
TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage),
// Not a measure event
TraceLoggingKeyword(static_cast<uint64_t>(onnxruntime::logging::ORTTraceLoggingKeyword::Session)),
TraceLoggingLevel(WINEVENT_LEVEL_INFO),
// Telemetry info
TraceLoggingUInt8(0, "schemaVersion"),
TraceLoggingUInt32(session_id, "sessionId"),
TraceLoggingInt64(ir_version, "irVersion"),
TraceLoggingUInt32(projection_, "OrtProgrammingProjection"),
TraceLoggingString(model_producer_name.c_str(), "modelProducerName"),
TraceLoggingString(model_producer_version.c_str(), "modelProducerVersion"),
TraceLoggingString(model_domain.c_str(), "modelDomain"),
TraceLoggingBool(use_fp16, "usefp16"),
TraceLoggingString(domain_to_version_string.c_str(), "domainToVersionMap"),
TraceLoggingString(model_graph_name.c_str(), "modelGraphName"),
TraceLoggingString(model_metadata_string.c_str(), "modelMetaData"),
TraceLoggingString(loaded_from.c_str(), "loadedFrom"),
TraceLoggingString(execution_provider_string.c_str(), "executionProviderIds"));
}
}
void WindowsTelemetry::LogRuntimeError(uint32_t session_id, const common::Status& status, const char* file,

View file

@ -51,7 +51,7 @@ class WindowsTelemetry : public Telemetry {
const std::string& model_graph_name,
const std::unordered_map<std::string, std::string>& model_metadata,
const std::string& loadedFrom, const std::vector<std::string>& execution_provider_ids,
bool use_fp16) const override;
bool use_fp16, bool captureState) const override;
void LogRuntimeError(uint32_t session_id, const common::Status& status, const char* file,
const char* function, uint32_t line) const override;

View file

@ -237,10 +237,10 @@ void QnnLogging(const char* format,
ORT_UNUSED_PARAMETER(level);
ORT_UNUSED_PARAMETER(timestamp);
// Always output Qnn log as Ort verbose log
const auto& logger = ::onnxruntime::logging::LoggingManager::DefaultLogger();
const auto severity = ::onnxruntime::logging::Severity::kVERBOSE;
const auto data_type = ::onnxruntime::logging::DataType::SYSTEM;
if (logger.OutputIsEnabled(severity, data_type)) {
::onnxruntime::logging::Capture(logger,
severity,
@ -251,31 +251,77 @@ void QnnLogging(const char* format,
}
}
void QnnBackendManager::InitializeQnnLog() {
Status QnnBackendManager::InitializeQnnLog() {
// Set Qnn log level align with Ort log level
QnnLog_Level_t qnn_log_level = QNN_LOG_LEVEL_WARN;
auto ort_log_level = logger_->GetSeverity();
switch (ort_log_level) {
case logging::Severity::kVERBOSE:
qnn_log_level = QNN_LOG_LEVEL_DEBUG;
break;
case logging::Severity::kINFO:
qnn_log_level = QNN_LOG_LEVEL_INFO;
break;
case logging::Severity::kWARNING:
qnn_log_level = QNN_LOG_LEVEL_WARN;
break;
case logging::Severity::kERROR:
qnn_log_level = QNN_LOG_LEVEL_ERROR;
break;
default:
break;
}
QnnLog_Level_t qnn_log_level = MapOrtSeverityToQNNLogLevel(ort_log_level);
LOGS(*logger_, VERBOSE) << "Set Qnn log level: " << qnn_log_level;
if (QNN_SUCCESS != qnn_interface_.logCreate(QnnLogging, qnn_log_level, &log_handle_)) {
LOGS(*logger_, WARNING) << "Unable to initialize logging in the QNN backend.";
Qnn_ErrorHandle_t result = qnn_interface_.logCreate(QnnLogging, qnn_log_level, &log_handle_);
if (result != QNN_SUCCESS) {
switch (result) {
case QNN_COMMON_ERROR_NOT_SUPPORTED:
LOGS(*logger_, ERROR) << "Logging not supported in the QNN backend.";
break;
case QNN_LOG_ERROR_INVALID_ARGUMENT:
LOGS(*logger_, ERROR) << "Invalid argument provided to QnnLog_create.";
break;
case QNN_LOG_ERROR_MEM_ALLOC:
LOGS(*logger_, ERROR) << "Memory allocation error during QNN logging initialization.";
break;
case QNN_LOG_ERROR_INITIALIZATION:
LOGS(*logger_, ERROR) << "Initialization of logging failed in the QNN backend.";
break;
default:
LOGS(*logger_, WARNING) << "Unknown error occurred while initializing logging in the QNN backend.";
break;
}
}
ORT_RETURN_IF(QNN_BACKEND_NO_ERROR != result, "Failed to initialize logging in the QNN backend");
return Status::OK();
}
QnnLog_Level_t QnnBackendManager::MapOrtSeverityToQNNLogLevel(logging::Severity ort_log_level) {
// Map ORT log severity to Qnn log level
switch (ort_log_level) {
case logging::Severity::kVERBOSE:
return QNN_LOG_LEVEL_DEBUG;
case logging::Severity::kINFO:
return QNN_LOG_LEVEL_INFO;
case logging::Severity::kWARNING:
return QNN_LOG_LEVEL_WARN;
case logging::Severity::kERROR:
case logging::Severity::kFATAL:
default:
return QNN_LOG_LEVEL_ERROR;
}
}
Status QnnBackendManager::ResetQnnLogLevel() {
auto ort_log_level = logger_->GetSeverity();
LOGS(*logger_, INFO) << "Reset Qnn log level to ORT Logger level: " << (unsigned int)ort_log_level;
return UpdateQnnLogLevel(ort_log_level);
}
Status QnnBackendManager::UpdateQnnLogLevel(logging::Severity ort_log_level) {
ORT_RETURN_IF(nullptr == log_handle_, "Unable to update QNN Log Level. Invalid QNN log handle.");
QnnLog_Level_t qnn_log_level = MapOrtSeverityToQNNLogLevel(ort_log_level);
LOGS(*logger_, INFO) << "Updating Qnn log level to: " << qnn_log_level;
// Use the QnnLog_setLogLevel API to set the new log level
Qnn_ErrorHandle_t result = qnn_interface_.logSetLogLevel(log_handle_, qnn_log_level);
if (QNN_SUCCESS != result) {
if (result == QNN_LOG_ERROR_INVALID_ARGUMENT) {
LOGS(*logger_, ERROR) << "Invalid log level argument provided to QnnLog_setLogLevel.";
} else if (result == QNN_LOG_ERROR_INVALID_HANDLE) {
LOGS(*logger_, ERROR) << "Invalid log handle provided to QnnLog_setLogLevel.";
}
}
ORT_RETURN_IF(QNN_BACKEND_NO_ERROR != result, "Failed to set log level in Qnn backend");
return Status::OK();
}
Status QnnBackendManager::InitializeBackend() {
@ -422,6 +468,23 @@ Status QnnBackendManager::ReleaseProfilehandle() {
return Status::OK();
}
Status QnnBackendManager::SetProfilingLevelETW(ProfilingLevel profiling_level_etw_param) {
if (profiling_level_etw_ != profiling_level_etw_param) {
profiling_level_etw_ = profiling_level_etw_param;
auto result = ReleaseProfilehandle();
if (Status::OK() != result) {
ORT_THROW("Failed to ReleaseProfilehandle for previous QNN profiling");
}
result = InitializeProfiling();
if (Status::OK() != result) {
ORT_THROW("Failed to Re-InitializeProfiling for QNN ETW profiling");
}
}
return Status::OK();
}
Status SetQnnContextConfig(ContextPriority context_priority, QnnContext_Config_t& qnn_context_config) {
qnn_context_config.option = QNN_CONTEXT_CONFIG_OPTION_PRIORITY;
switch (context_priority) {

View file

@ -115,11 +115,15 @@ class QnnBackendManager {
void SetLogger(const logging::Logger* logger) {
if (logger_ == nullptr) {
logger_ = logger;
InitializeQnnLog();
(void)InitializeQnnLog();
}
}
void InitializeQnnLog();
Status InitializeQnnLog();
Status UpdateQnnLogLevel(logging::Severity ort_log_level);
Status ResetQnnLogLevel();
// Terminate logging in the backend
Status TerminateQnnLog() {
@ -146,6 +150,8 @@ class QnnBackendManager {
std::ofstream& outfile, bool backendSupportsExtendedEventData,
bool tracelogging_provider_ep_enabled);
Status SetProfilingLevelETW(ProfilingLevel profiling_level_etw_param);
void SetQnnBackendType(uint32_t backend_id);
QnnBackendType GetQnnBackendType() { return qnn_backend_type_; }
@ -210,6 +216,7 @@ class QnnBackendManager {
static const std::string GetEventTypeString(QnnProfile_EventType_t eventType);
static const std::string ExtractQnnScalarValue(const Qnn_Scalar_t& scalar);
const char* QnnProfileErrorToString(QnnProfile_Error_t error);
QnnLog_Level_t MapOrtSeverityToQNNLogLevel(logging::Severity ort_log_level);
#ifdef _WIN32
void LogQnnProfileEventAsTraceLogging(
uint64_t timestamp,

View file

@ -24,6 +24,11 @@
#include "core/providers/qnn/builder/onnx_ctx_model_helper.h"
#include "core/framework/run_options.h"
#ifdef _WIN32
#include <Windows.h>
#include "core/platform/windows/logging/etw_sink.h"
#endif
namespace onnxruntime {
constexpr const char* QNN = "QNN";
@ -156,6 +161,20 @@ static void ParseHtpArchitecture(const std::string& htp_arch_string, QnnHtpDevic
}
}
qnn::ProfilingLevel QNNExecutionProvider::GetProfilingLevelFromETWLevel(unsigned char level) {
if (level == 5) {
LOGS_DEFAULT(INFO) << "Overriding profiling to basic based on ETW level: " << static_cast<int>(level);
return qnn::ProfilingLevel::BASIC;
} else if (level < 5) {
LOGS_DEFAULT(INFO) << "QNN Profiler ETW level not supported below level 5. Level: "
<< static_cast<int>(level);
return qnn::ProfilingLevel::OFF;
} else {
LOGS_DEFAULT(INFO) << "Overriding profiling to detailed based on ETW level: " << static_cast<int>(level);
return qnn::ProfilingLevel::DETAILED;
}
}
QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_options_map,
const SessionOptions* session_options)
: IExecutionProvider{onnxruntime::kQnnExecutionProvider} {
@ -206,21 +225,53 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio
auto keyword = provider.Keyword();
if ((keyword & static_cast<uint64_t>(onnxruntime::logging::ORTTraceLoggingKeyword::Profiling)) != 0) {
if (level != 0) {
if (level == 5) {
LOGS_DEFAULT(INFO) << "Overriding profiling to basic based on ETW level: " << static_cast<int>(level);
profiling_level_etw = qnn::ProfilingLevel::BASIC;
} else if (level < 5) {
LOGS_DEFAULT(INFO) << "QNN Profiler ETW level not supported below level 5. Level: "
<< static_cast<int>(level);
profiling_level_etw = qnn::ProfilingLevel::OFF;
} else {
LOGS_DEFAULT(INFO) << "Overriding profiling to detailed based on ETW level: " << static_cast<int>(level);
profiling_level_etw = qnn::ProfilingLevel::DETAILED;
}
profiling_level_etw = GetProfilingLevelFromETWLevel(level);
}
}
}
#ifdef _WIN32
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) {
ORT_UNUSED_PARAMETER(SourceId);
ORT_UNUSED_PARAMETER(MatchAnyKeyword);
ORT_UNUSED_PARAMETER(MatchAllKeyword);
ORT_UNUSED_PARAMETER(FilterData);
ORT_UNUSED_PARAMETER(CallbackContext);
if (IsEnabled == EVENT_CONTROL_CODE_ENABLE_PROVIDER) {
if ((MatchAnyKeyword & static_cast<ULONGLONG>(onnxruntime::logging::ORTTraceLoggingKeyword::Logs)) != 0) {
auto ortETWSeverity = etwRegistrationManager.MapLevelToSeverity();
(void)qnn_backend_manager_->UpdateQnnLogLevel(ortETWSeverity);
}
if ((MatchAnyKeyword & static_cast<ULONGLONG>(onnxruntime::logging::ORTTraceLoggingKeyword::Profiling)) != 0) {
if (Level != 0) {
// Commenting out Dynamic QNN Profiling for now
// There seems to be a crash in 3rd party QC QnnHtp.dll with this.
// Repro Scenario - start ETW tracing prior to session creation.
// Then disable/enable ETW Tracing with the code below uncommented a few times
// auto profiling_level_etw = GetProfilingLevelFromETWLevel(Level);
// (void)qnn_backend_manager_->SetProfilingLevelETW(profiling_level_etw);
}
}
}
if (IsEnabled == EVENT_CONTROL_CODE_DISABLE_PROVIDER) {
// (void)qnn_backend_manager_->SetProfilingLevelETW(qnn::ProfilingLevel::INVALID);
(void)qnn_backend_manager_->ResetQnnLogLevel();
}
});
#endif
// In case ETW gets disabled later
auto profiling_level_pos = provider_options_map.find(PROFILING_LEVEL);
if (profiling_level_pos != provider_options_map.end()) {

View file

@ -69,6 +69,8 @@ class QNNExecutionProvider : public IExecutionProvider {
void InitQnnGraphConfigs(qnn::QnnConfigsBuilder<QnnGraph_Config_t, QnnHtpGraph_CustomConfig_t>& configs_builder) const;
qnn::ProfilingLevel GetProfilingLevelFromETWLevel(unsigned char level);
private:
qnn::HtpGraphFinalizationOptimizationMode htp_graph_finalization_opt_mode_ = qnn::HtpGraphFinalizationOptimizationMode::kDefault;
std::unique_ptr<qnn::QnnBackendManager> qnn_backend_manager_;

View file

@ -12,6 +12,7 @@
#include <queue>
#include "core/common/denormal.h"
#include "core/common/logging/isink.h"
#include "core/common/logging/logging.h"
#include "core/common/parse_string.h"
#include "core/common/path_string.h"
@ -52,6 +53,7 @@
#include "core/platform/tracing.h"
#include <Windows.h>
#include "core/platform/windows/telemetry.h"
#include "core/platform/windows/logging/etw_sink.h"
#endif
#include "core/providers/cpu/controlflow/utils.h"
#include "core/providers/cpu/cpu_execution_provider.h"
@ -345,7 +347,9 @@ void InferenceSession::SetLoggingManager(const SessionOptions& session_options,
session_options.user_logging_param);
auto sessionSeverity = GetSeverity(session_options);
auto etwOverrideSeverity = logging::OverrideLevelWithEtw(sessionSeverity);
sink = EnhanceLoggerWithEtw(std::move(sink), sessionSeverity, etwOverrideSeverity);
#ifdef _WIN32
sink = EnhanceSinkWithEtw(std::move(sink), sessionSeverity, etwOverrideSeverity);
#endif
user_logging_manager_ = std::make_unique<logging::LoggingManager>(std::move(sink),
std::min(sessionSeverity, etwOverrideSeverity),
@ -369,7 +373,7 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options,
std::lock_guard<OrtMutex> lock(active_sessions_mutex_);
active_sessions_[global_session_id_++] = this;
// Register callback for ETW capture state (rundown)
// Register callback for ETW capture state (rundown) for Microsoft.ML.ONNXRuntime provider
WindowsTelemetry::RegisterInternalCallback(
[this](
LPCGUID SourceId,
@ -392,6 +396,49 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options,
LogAllSessions();
}
});
// 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) {
(void)SourceId;
(void)Level;
(void)MatchAnyKeyword;
(void)MatchAllKeyword;
(void)FilterData;
(void)CallbackContext;
if (logging_manager_ != nullptr) {
auto ortETWSeverity = etwRegistrationManager.MapLevelToSeverity();
if ((MatchAnyKeyword & static_cast<ULONGLONG>(onnxruntime::logging::ORTTraceLoggingKeyword::Logs)) != 0 &&
IsEnabled == EVENT_CONTROL_CODE_ENABLE_PROVIDER) {
LOGS(*session_logger_, VERBOSE) << "Adding ETW Sink to logger with severity level: " << (ULONG)ortETWSeverity;
logging_manager_->AddSinkOfType(
onnxruntime::logging::SinkType::EtwSink,
[]() -> std::unique_ptr<onnxruntime::logging::ISink> { return std::make_unique<onnxruntime::logging::EtwSink>(); },
ortETWSeverity);
onnxruntime::logging::LoggingManager::GetDefaultInstance()->AddSinkOfType(
onnxruntime::logging::SinkType::EtwSink,
[]() -> std::unique_ptr<onnxruntime::logging::ISink> { return std::make_unique<onnxruntime::logging::EtwSink>(); },
ortETWSeverity);
LOGS(*session_logger_, INFO) << "Done Adding ETW Sink to logger with severity level: " << (ULONG)ortETWSeverity;
}
if (IsEnabled == EVENT_CONTROL_CODE_DISABLE_PROVIDER) {
LOGS(*session_logger_, INFO) << "Removing ETW Sink from logger";
logging_manager_->RemoveSink(onnxruntime::logging::SinkType::EtwSink);
LOGS(*session_logger_, VERBOSE) << "Done Removing ETW Sink from logger";
}
}
});
#endif
SetLoggingManager(session_options, session_env);
@ -528,7 +575,7 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options,
}
void InferenceSession::TraceSessionOptions(const SessionOptions& session_options, bool captureState) {
(void)captureState; // Otherwise Linux build error
ORT_UNUSED_PARAMETER(captureState); // Otherwise Linux build error
LOGS(*session_logger_, INFO) << session_options;
@ -2030,8 +2077,8 @@ common::Status InferenceSession::Initialize() {
bool model_has_fp16_inputs = ModelHasFP16Inputs(graph);
env.GetTelemetryProvider().LogSessionCreation(
session_id_, model_->IrVersion(), model_->ProducerName(), model_->ProducerVersion(), model_->Domain(),
model_->MainGraph().DomainToVersionMap(), model_->MainGraph().Name(), model_->MetaData(),
telemetry_.event_name_, execution_providers_.GetIds(), model_has_fp16_inputs);
graph.DomainToVersionMap(), graph.Name(), model_->MetaData(),
telemetry_.event_name_, execution_providers_.GetIds(), model_has_fp16_inputs, false);
LOGS(*session_logger_, INFO) << "Session successfully initialized.";
}
@ -3172,9 +3219,19 @@ IOBinding* SessionIOBinding::Get() {
#ifdef _WIN32
void InferenceSession::LogAllSessions() {
const Env& env = Env::Default();
std::lock_guard<OrtMutex> lock(active_sessions_mutex_);
for (const auto& session_pair : active_sessions_) {
InferenceSession* session = session_pair.second;
onnxruntime::Graph& graph = model_->MainGraph();
bool model_has_fp16_inputs = ModelHasFP16Inputs(graph);
env.GetTelemetryProvider().LogSessionCreation(
session_id_, model_->IrVersion(), model_->ProducerName(), model_->ProducerVersion(), model_->Domain(),
graph.DomainToVersionMap(), graph.Name(), model_->MetaData(),
telemetry_.event_name_, execution_providers_.GetIds(), model_has_fp16_inputs, true);
TraceSessionOptions(session->session_options_, true);
}
}

View file

@ -48,8 +48,8 @@ OrtEnv* OrtEnv::GetInstance(const OrtEnv::LoggingManagerConstructionInfo& lm_inf
sink = MakePlatformDefaultLogSink();
}
auto etwOverrideSeverity = logging::OverrideLevelWithEtw(static_cast<Severity>(lm_info.default_warning_level));
sink = EnhanceLoggerWithEtw(std::move(sink), static_cast<Severity>(lm_info.default_warning_level),
etwOverrideSeverity);
sink = EnhanceSinkWithEtw(std::move(sink), static_cast<Severity>(lm_info.default_warning_level),
etwOverrideSeverity);
lmgr = std::make_unique<LoggingManager>(std::move(sink),
std::min(static_cast<Severity>(lm_info.default_warning_level), etwOverrideSeverity),
false,

View file

@ -18,6 +18,16 @@ class MockSink : public ::onnxruntime::logging::ISink {
const ::onnxruntime::logging::Capture& message));
};
class MockEtwSink : public ::onnxruntime::logging::ISink {
public:
MockEtwSink() : ISink(onnxruntime::logging::SinkType::EtwSink) {}
~MockEtwSink() = default;
MOCK_METHOD3(SendImpl, void(const ::onnxruntime::logging::Timestamp& timestamp,
const std::string& logger_id,
const ::onnxruntime::logging::Capture& message));
};
// The ACTION*() macros trigger warning C4100 (unreferenced formal
// parameter) in MSVC with -W4. Unfortunately they cannot be fixed in
// the macro definition, as the warnings are generated when the macro

View file

@ -144,8 +144,8 @@ TEST(LoggingTests, TestFileSink) {
/// <summary>
/// Tests that a composite_sink works correctly.
/// </summary>
TEST(LoggingTests, TestCompositeSink) {
const std::string logid{"TestCompositeSink"};
TEST(LoggingTests, TestCompositeSinkBasic) {
const std::string logid{"TestCompositeSinkBasic"};
const Severity min_log_level = Severity::kWARNING;
MockSink* sink_ptr1 = new MockSink();
@ -163,3 +163,58 @@ TEST(LoggingTests, TestCompositeSink) {
LOGS_CATEGORY(*logger, WARNING, "ArbitraryCategory") << "Warning";
}
/// <summary>
/// Tests that removing a sink of a specific type correctly updates the composite sink.
/// </summary>
TEST(LoggingTests, TestRemoveSink) {
CompositeSink sink;
MockSink* mock_sink1 = new MockSink();
MockEtwSink* mock_sink2 = new MockEtwSink();
sink.AddSink(std::unique_ptr<ISink>(mock_sink1), Severity::kWARNING);
sink.AddSink(std::unique_ptr<ISink>(mock_sink2), Severity::kERROR);
// Set expectations that no SendImpl will be called on the removed sink
EXPECT_CALL(*mock_sink1, SendImpl(testing::_, testing::_, testing::_)).Times(0);
// Remove the sink and check severity update
auto new_severity = sink.RemoveSink(SinkType::EtwSink);
EXPECT_EQ(new_severity, Severity::kWARNING); // assuming mock_sink2 had SpecificType and was removed
// Verify that sink2 is still in the composite
EXPECT_TRUE(sink.HasType(SinkType::BaseSink));
}
/// <summary>
/// Tests the HasOnlyOneSink method to ensure it correctly identifies when one sink is left.
/// </summary>
TEST(LoggingTests, TestHasOnlyOneSink) {
CompositeSink sink;
sink.AddSink(std::unique_ptr<ISink>(new MockEtwSink()), Severity::kWARNING);
sink.AddSink(std::unique_ptr<ISink>(new MockSink()), Severity::kERROR);
EXPECT_FALSE(sink.HasOnlyOneSink());
sink.RemoveSink(SinkType::EtwSink);
EXPECT_TRUE(sink.HasOnlyOneSink());
sink.RemoveSink(SinkType::BaseSink); // Remove the last one
EXPECT_FALSE(sink.HasOnlyOneSink());
}
/// <summary>
/// Tests the GetRemoveSingleSink method to ensure it returns the last sink and empties the composite sink.
/// </summary>
TEST(LoggingTests, TestGetRemoveSingleSink) {
CompositeSink sink;
auto* single_mock_sink = new MockSink();
sink.AddSink(std::unique_ptr<ISink>(single_mock_sink), Severity::kWARNING);
// Check we have one sink
EXPECT_TRUE(sink.HasOnlyOneSink());
// Get and remove the single sink
auto removed_sink = sink.GetRemoveSingleSink();
EXPECT_EQ(removed_sink.get(), single_mock_sink); // Check it's the same sink
EXPECT_FALSE(sink.HasOnlyOneSink()); // Should be empty now
}

View file

@ -1,5 +1,5 @@
<?xml version="1.0" encoding="utf-8"?>
<!-- TODO:
<!-- TODO:
1. Find and replace "OrtTraceLoggingProvider" with your component name.
2. See TODO below to update GUID for your event provider
-->
@ -12,8 +12,11 @@
<Buffers Value="10" PercentageOfTotalMemory="true"/>
</EventCollector>
<EventProvider Id="EventProvider_OrtTraceLoggingProvider"
Name="3a26b1ff-7484-7484-7484-15261f42614d" Level="5" />
<EventProvider Id="EventProvider_OrtTraceLoggingProvider" Name="3a26b1ff-7484-7484-7484-15261f42614d" Level="5" >
<CaptureStateOnSave>
<Keyword Value="0x1"/> <!-- Session rundown -->
</CaptureStateOnSave>
</EventProvider>
<Profile Id="OrtTraceLoggingProvider.Verbose.File"
Name="OrtTraceLoggingProvider" Description="OrtTraceLoggingProvider"
LoggingMode="File" DetailLevel="Verbose">
@ -48,4 +51,4 @@
DetailLevel="Light" />
</Profiles>
</WindowsPerformanceRecorder>
</WindowsPerformanceRecorder>