mirror of
https://github.com/saymrwulf/onnxruntime.git
synced 2026-07-30 20:18:08 +00:00
ORT ETW dynamic logging that improves ORT diagnosability & performance (#18882)
### Description This PR has several combined ORT ETW changes that improve ORT log diagnosability & performance. - The existing log behavior in the ORT API and Severity behavior remain the same as compiled by the dev using the ORT API - The PR keeps the existing design which has 2 TraceLogging providers defined (although both were not used before this PR) - Keeps great inference (inf) and session load performance even with dynamic logging enabled (see below) - On Windows, when ONNXRuntimeTraceLoggingProvider is enabled, then ORT will dynamically _add_ a new sink reflecting the severity level provided by ETW dynamically. E.G Critical - Verbose per the need at runtime - This allows previous printf style LOGS() statements both for CPU and NPU cases to flow to ETW via a local trace (if enabled) - This DOES NOT add any new Telemetry which can optionally be sent to Microsoft. - Telemetry are ETW events marked with the Measure keyword that _can_ be sampled if a box opts-in - Existing Microsoft.ML.ONNXRuntime events have appropriate keywords and levels added if they were missing - If Execution Providers (EPs) can provide more detailed insight into their HW or component, then this PR allows for those to be dynamically logged instead of just at compile time - In this PR, the QNN EP for QC NPUs can have basic or detailed profiling enabled to give some insight into how the NPU is performing - When the Microsoft.ML.ONNXRuntime ETW provider is enabled with the Profiling keyword and level 5 then QC QNN basic profiling info is output to ETW ### Motivation and Context - This make ORT logging and diagnosability more performant (on Windows) and available in a wider variety of runtime environments. - The performance difference for inf times was ~300x+ drastically better/faster when these logs were output to ETW vs just stdout (Verbose Severity) - This style of ETW dynamic tracing is the widely used standard for Windows components, and even by some 3rd party software since the ETW API is open and part of the Windows API - These ETW based logs can be seamlessly combined with other ETW logs such as an AI component/feature using ORT, OS CPU profiling, scheduling, and more - Before the PR, ORT logging is largely printf style and output to a sink (usually stdout) only if compiled with a certain log Severity. When enabled the previous logging (to stdout) would vastly slow down inference times. Once compiled for release the internal ORT logs were not accessible by anyone except the AI model developer in their dev inner loop. That means logs could not be enabled on a lab machine, or on a production system where the runtime behavior or performance might be different for various reasons on a wide variety of HW. - This change was tested with performance in mind and tested with a mobilenet small AI model with onnxruntime_perf_test - CPU: There was no statistical difference for inf times with the baseline (main) or this PR whether ETW was enabled or not (both ORT providers all keywords level 5). - NPU (QNN on SP9 or Dev Kit 2023 QC SQ3): There was no statistical difference for inf times with this PR whether ETW (both ORT providers all keywords) were enabled or not for Level 5 (Verbose). This is even with QNN Basic profiling turned on and outputting NPU stats to ETW - As expected and designed, there was perf slowdown when Max Level 255 is enabled which translates to QNN Detailed profiling. This mirrors the expected slowdown in the NPU when individual model operations are monitored & recorded as well. This perf is similar to the QNN SDK Detailed profiling performance separate from this PR. This is designed to be above level 5 (verbose) as that is commonly the max level used in many trace profiles and won't affect inf performance. - Other OSes such as Linux & Android are left untouched for now. - Out of scope for this PR but TraceLogging is available for Linux with LTTng tracing. So in the future, this optional tracing could also be made available on other OSes where a TraceLogging API is available
This commit is contained in:
ivberg
GitHub
parent
d0bac8216d
commit
4d1243b4b4
22 changed files with 593 additions and 125 deletions
|
|
@ -75,6 +75,21 @@ struct Category {
|
|||
// TODO: What other high level categories are meaningful? Model? Optimizer? Execution?
|
||||
};
|
||||
|
||||
/// <summary>
|
||||
/// ORT TraceLogging keywords for categories of dynamic logging enablement
|
||||
/// </summary>
|
||||
enum class ORTTraceLoggingKeyword : uint64_t {
|
||||
Session = 0x1, // ORT Session TraceLoggingWrite
|
||||
Logs = 0x2, // LOGS() Macro ORT logs. Pair with an appropriate level depending on detail required
|
||||
Reserved1 = 0x4, // Reserved if we want to add some specific sub-categories instead of just LOGS() or other uses
|
||||
Reserved2 = 0x8,
|
||||
Reserved3 = 0x10,
|
||||
Reserved4 = 0x20,
|
||||
Reserved5 = 0x40,
|
||||
Reserved6 = 0x80,
|
||||
Profiling = 0x100 // Enables profiling. At higher levels >5 can impact inference performance
|
||||
};
|
||||
|
||||
class ISink;
|
||||
class Logger;
|
||||
class Capture;
|
||||
|
|
@ -333,5 +348,17 @@ unsigned int GetThreadId();
|
|||
*/
|
||||
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);
|
||||
|
||||
/**
|
||||
If the ONNXRuntimeTraceLoggingProvider ETW Provider is enabled, then can override the logging level.
|
||||
But this overrided level only applies to the ETW sink. The original logger(s) retain their original logging level
|
||||
*/
|
||||
Severity OverrideLevelWithEtw(Severity originalSeverity);
|
||||
|
||||
} // namespace logging
|
||||
} // namespace onnxruntime
|
||||
|
|
|
|||
|
|
@ -12,6 +12,8 @@
|
|||
|
||||
#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)
|
||||
|
|
@ -243,5 +245,36 @@ unsigned int GetProcessId() {
|
|||
#endif
|
||||
}
|
||||
|
||||
std::unique_ptr<ISink> EnhanceLoggerWithEtw(std::unique_ptr<ISink> existingLogger, logging::Severity originalSeverity,
|
||||
logging::Severity etwSeverity) {
|
||||
#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);
|
||||
return compositeSink;
|
||||
} else {
|
||||
return existingLogger;
|
||||
}
|
||||
#else
|
||||
// On non-Windows platforms, just return the existing logger
|
||||
(void)originalSeverity;
|
||||
(void)etwSeverity;
|
||||
return existingLogger;
|
||||
#endif // _WIN32
|
||||
}
|
||||
|
||||
Severity OverrideLevelWithEtw(Severity originalSeverity) {
|
||||
#ifdef _WIN32
|
||||
auto& manager = logging::EtwRegistrationManager::Instance();
|
||||
if (manager.IsEnabled() &&
|
||||
(manager.Keyword() & static_cast<ULONGLONG>(onnxruntime::logging::ORTTraceLoggingKeyword::Logs)) != 0) {
|
||||
return manager.MapLevelToSeverity();
|
||||
}
|
||||
#endif // _WIN32
|
||||
return originalSeverity;
|
||||
}
|
||||
|
||||
} // namespace logging
|
||||
} // namespace onnxruntime
|
||||
|
|
|
|||
|
|
@ -5,6 +5,8 @@
|
|||
|
||||
#include <string>
|
||||
#include <vector>
|
||||
#include <utility>
|
||||
#include <memory>
|
||||
|
||||
#include "core/common/logging/isink.h"
|
||||
#include "core/common/logging/logging.h"
|
||||
|
|
@ -27,20 +29,31 @@ class CompositeSink : public ISink {
|
|||
/// Adds a sink. Takes ownership of the sink (so pass unique_ptr by value).
|
||||
/// </summary>
|
||||
/// <param name="sink">The sink.</param>
|
||||
/// <param name="severity">The min severity to send a message to that sink</param>
|
||||
/// <returns>This instance to allow chaining.</returns>
|
||||
CompositeSink& AddSink(std::unique_ptr<ISink> sink) {
|
||||
sinks_.push_back(std::move(sink));
|
||||
CompositeSink& AddSink(std::unique_ptr<ISink> sink, logging::Severity severity) {
|
||||
sinks_with_severity_.emplace_back(std::move(sink), severity);
|
||||
return *this;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Gets a const reference to the collection of sinks and min severity for that sink
|
||||
/// </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_;
|
||||
}
|
||||
|
||||
private:
|
||||
void SendImpl(const Timestamp& timestamp, const std::string& logger_id, const Capture& message) override {
|
||||
for (auto& sink : sinks_) {
|
||||
sink->Send(timestamp, logger_id, message);
|
||||
for (auto& sink_pair : sinks_with_severity_) {
|
||||
if (message.Severity() >= sink_pair.second) {
|
||||
sink_pair.first->Send(timestamp, logger_id, message);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
std::vector<std::unique_ptr<ISink>> sinks_;
|
||||
std::vector<std::pair<std::unique_ptr<ISink>, logging::Severity>> sinks_with_severity_;
|
||||
};
|
||||
} // namespace logging
|
||||
} // namespace onnxruntime
|
||||
|
|
|
|||
|
|
@ -13,6 +13,7 @@
|
|||
#include "core/graph/graph_viewer.h"
|
||||
#include "core/common/logging/logging.h"
|
||||
#ifdef _WIN32
|
||||
#include <winmeta.h>
|
||||
#include "core/platform/tracing.h"
|
||||
#endif
|
||||
|
||||
|
|
@ -47,6 +48,8 @@ class ExecutionProviders {
|
|||
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"));
|
||||
|
|
|
|||
|
|
@ -181,7 +181,7 @@ class SessionScope {
|
|||
}
|
||||
|
||||
auto& logger = session_state_.Logger();
|
||||
LOGS(logger, VERBOSE) << "Begin execution";
|
||||
VLOGS(logger, 0) << "Begin execution";
|
||||
const SequentialExecutionPlan& seq_exec_plan = *session_state_.GetExecutionPlan();
|
||||
const auto& exec_plan_vec = seq_exec_plan.execution_plan;
|
||||
VLOGS(logger, 1) << "Size of execution plan vector: " << exec_plan_vec.size();
|
||||
|
|
@ -515,7 +515,7 @@ onnxruntime::Status ExecuteKernel(StreamExecutionContext& ctx,
|
|||
return Status(status.Category(), status.Code(), msg_string);
|
||||
}
|
||||
ctx.RecycleNodeInputs(idx);
|
||||
LOGS(logger, VERBOSE) << "stream " << stream_idx << " launch kernel with idx " << idx;
|
||||
VLOGS(logger, 0) << "stream " << stream_idx << " launch kernel with idx " << idx;
|
||||
return Status::OK();
|
||||
}
|
||||
|
||||
|
|
@ -531,7 +531,7 @@ onnxruntime::Status ExecuteThePlan(const SessionState& session_state, gsl::span<
|
|||
const bool only_execute_path_to_fetches,
|
||||
bool single_thread_mode) {
|
||||
auto* execution_plan = session_state.GetExecutionPlan();
|
||||
LOGS(logger, VERBOSE) << "Number of streams: " << execution_plan->execution_plan.size();
|
||||
VLOGS(logger, 0) << "Number of streams: " << execution_plan->execution_plan.size();
|
||||
int32_t valid_streams = 0;
|
||||
for (auto& stream : execution_plan->execution_plan) {
|
||||
if (stream && stream->steps_.size() > 0)
|
||||
|
|
|
|||
|
|
@ -168,7 +168,7 @@ void StreamExecutionContext::RecycleNodeInputs(onnxruntime::NodeIndex node_index
|
|||
for (auto idx : execution_plan->node_release_list[node_index]) {
|
||||
if (--release_plan_[idx] == 0) {
|
||||
ORT_ENFORCE(frame_.ReleaseMLValue(static_cast<int>(execution_plan->release_actions[idx].value_index)).IsOK());
|
||||
LOGS(*logger_, VERBOSE) << "ort value " << execution_plan->release_actions[idx].value_index << " released";
|
||||
VLOGS(*logger_, 0) << "ort value " << execution_plan->release_actions[idx].value_index << " released";
|
||||
}
|
||||
}
|
||||
}
|
||||
|
|
|
|||
|
|
@ -12,6 +12,21 @@ void LogRuntimeError(uint32_t sessionId, const common::Status& status, const cha
|
|||
env.GetTelemetryProvider().LogRuntimeError(sessionId, status, file, function, line);
|
||||
}
|
||||
|
||||
bool Telemetry::IsEnabled() const {
|
||||
return false;
|
||||
}
|
||||
|
||||
// Get the current logging level
|
||||
// The Level defined as uchar is coming from the ETW Enable callback in TraceLoggingRegisterEx.
|
||||
unsigned char Telemetry::Level() const {
|
||||
return 0;
|
||||
}
|
||||
|
||||
// Get the current keyword
|
||||
uint64_t Telemetry::Keyword() const {
|
||||
return 0;
|
||||
}
|
||||
|
||||
void Telemetry::EnableTelemetryEvents() const {
|
||||
}
|
||||
|
||||
|
|
|
|||
|
|
@ -38,6 +38,14 @@ class Telemetry {
|
|||
virtual void DisableTelemetryEvents() const;
|
||||
virtual void SetLanguageProjection(uint32_t projection) const;
|
||||
|
||||
virtual bool IsEnabled() const;
|
||||
|
||||
// Get the current logging level
|
||||
virtual unsigned char Level() const;
|
||||
|
||||
// Get the current keyword
|
||||
virtual uint64_t Keyword() const;
|
||||
|
||||
virtual void LogProcessInfo() const;
|
||||
|
||||
virtual void LogSessionCreationStart() const;
|
||||
|
|
|
|||
|
|
@ -58,42 +58,107 @@ TRACELOGGING_DEFINE_PROVIDER(etw_provider_handle, "ONNXRuntimeTraceLoggingProvid
|
|||
#pragma warning(pop)
|
||||
#endif
|
||||
|
||||
// Class to unregister ETW provider at shutdown.
|
||||
// We expect one static instance to be created for the lifetime of the program.
|
||||
class EtwRegistrationManager {
|
||||
public:
|
||||
static EtwRegistrationManager& Register() {
|
||||
const HRESULT etw_status = ::TraceLoggingRegister(etw_provider_handle);
|
||||
EtwRegistrationManager& EtwRegistrationManager::Instance() {
|
||||
static EtwRegistrationManager instance;
|
||||
instance.LazyInitialize();
|
||||
return instance;
|
||||
}
|
||||
|
||||
if (FAILED(etw_status)) {
|
||||
ORT_THROW("ETW registration failed. Logging will be broken: " + std::to_string(etw_status));
|
||||
bool EtwRegistrationManager::IsEnabled() const {
|
||||
std::lock_guard<OrtMutex> lock(provider_change_mutex_);
|
||||
return is_enabled_;
|
||||
}
|
||||
|
||||
UCHAR EtwRegistrationManager::Level() const {
|
||||
std::lock_guard<OrtMutex> lock(provider_change_mutex_);
|
||||
return level_;
|
||||
}
|
||||
|
||||
Severity EtwRegistrationManager::MapLevelToSeverity() {
|
||||
switch (level_) {
|
||||
case TRACE_LEVEL_NONE:
|
||||
return Severity::kFATAL; // There is no none severity option
|
||||
case TRACE_LEVEL_VERBOSE:
|
||||
return Severity::kVERBOSE;
|
||||
case TRACE_LEVEL_INFORMATION:
|
||||
return Severity::kINFO;
|
||||
case TRACE_LEVEL_WARNING:
|
||||
return Severity::kWARNING;
|
||||
case TRACE_LEVEL_ERROR:
|
||||
return Severity::kERROR;
|
||||
case TRACE_LEVEL_CRITICAL:
|
||||
return Severity::kFATAL;
|
||||
default:
|
||||
return Severity::kVERBOSE;
|
||||
}
|
||||
}
|
||||
|
||||
ULONGLONG EtwRegistrationManager::Keyword() const {
|
||||
std::lock_guard<OrtMutex> lock(provider_change_mutex_);
|
||||
return keyword_;
|
||||
}
|
||||
|
||||
HRESULT EtwRegistrationManager::Status() const {
|
||||
return etw_status_;
|
||||
}
|
||||
|
||||
void EtwRegistrationManager::RegisterInternalCallback(const EtwInternalCallback& callback) {
|
||||
std::lock_guard<OrtMutex> lock(callbacks_mutex_);
|
||||
callbacks_.push_back(callback);
|
||||
}
|
||||
|
||||
void NTAPI EtwRegistrationManager::ORT_TL_EtwEnableCallback(
|
||||
_In_ LPCGUID SourceId,
|
||||
_In_ ULONG IsEnabled,
|
||||
_In_ UCHAR Level,
|
||||
_In_ ULONGLONG MatchAnyKeyword,
|
||||
_In_ ULONGLONG MatchAllKeyword,
|
||||
_In_opt_ PEVENT_FILTER_DESCRIPTOR FilterData,
|
||||
_In_opt_ PVOID CallbackContext) {
|
||||
auto& manager = EtwRegistrationManager::Instance();
|
||||
{
|
||||
std::lock_guard<OrtMutex> lock(manager.provider_change_mutex_);
|
||||
manager.is_enabled_ = (IsEnabled != 0);
|
||||
manager.level_ = Level;
|
||||
manager.keyword_ = MatchAnyKeyword;
|
||||
}
|
||||
manager.InvokeCallbacks(SourceId, IsEnabled, Level, MatchAnyKeyword, MatchAllKeyword, FilterData, CallbackContext);
|
||||
}
|
||||
|
||||
EtwRegistrationManager::~EtwRegistrationManager() {
|
||||
::TraceLoggingUnregister(etw_provider_handle);
|
||||
}
|
||||
|
||||
EtwRegistrationManager::EtwRegistrationManager() {
|
||||
}
|
||||
|
||||
void EtwRegistrationManager::LazyInitialize() {
|
||||
if (!initialized_) {
|
||||
std::lock_guard<OrtMutex> lock(init_mutex_);
|
||||
if (!initialized_) { // Double-check locking pattern
|
||||
initialized_ = true;
|
||||
etw_status_ = ::TraceLoggingRegisterEx(etw_provider_handle, ORT_TL_EtwEnableCallback, nullptr);
|
||||
if (FAILED(etw_status_)) {
|
||||
ORT_THROW("ETW registration failed. Logging will be broken: " + std::to_string(etw_status_));
|
||||
}
|
||||
}
|
||||
|
||||
// return an instance that is just used to unregister as the program exits
|
||||
static EtwRegistrationManager instance(etw_status);
|
||||
return instance;
|
||||
}
|
||||
}
|
||||
|
||||
const HRESULT Status() const noexcept {
|
||||
return etw_status_;
|
||||
void EtwRegistrationManager::InvokeCallbacks(LPCGUID SourceId, ULONG IsEnabled, UCHAR Level, ULONGLONG MatchAnyKeyword,
|
||||
ULONGLONG MatchAllKeyword, PEVENT_FILTER_DESCRIPTOR FilterData,
|
||||
PVOID CallbackContext) {
|
||||
std::lock_guard<OrtMutex> lock(callbacks_mutex_);
|
||||
for (const auto& callback : callbacks_) {
|
||||
callback(SourceId, IsEnabled, Level, MatchAnyKeyword, MatchAllKeyword, FilterData, CallbackContext);
|
||||
}
|
||||
|
||||
~EtwRegistrationManager() {
|
||||
::TraceLoggingUnregister(etw_provider_handle);
|
||||
}
|
||||
|
||||
private:
|
||||
ORT_DISALLOW_COPY_ASSIGNMENT_AND_MOVE(EtwRegistrationManager);
|
||||
|
||||
EtwRegistrationManager(const HRESULT status) noexcept : etw_status_{status} {}
|
||||
const HRESULT etw_status_;
|
||||
};
|
||||
}
|
||||
|
||||
void EtwSink::SendImpl(const Timestamp& timestamp, const std::string& logger_id, const Capture& message) {
|
||||
UNREFERENCED_PARAMETER(timestamp);
|
||||
|
||||
// register on first usage
|
||||
static EtwRegistrationManager& etw_manager = EtwRegistrationManager::Register();
|
||||
static EtwRegistrationManager& etw_manager = EtwRegistrationManager::Instance();
|
||||
|
||||
// do something (not that meaningful) with etw_manager so it doesn't get optimized out
|
||||
// as we want an instance around to do the unregister
|
||||
|
|
@ -101,9 +166,8 @@ void EtwSink::SendImpl(const Timestamp& timestamp, const std::string& logger_id,
|
|||
return;
|
||||
}
|
||||
|
||||
// Do we want to output Verbose level messages via ETW at any point it time?
|
||||
// TODO: Validate if this filtering makes sense.
|
||||
if (message.Severity() <= Severity::kVERBOSE || message.DataType() == DataType::USER) {
|
||||
if (message.DataType() == DataType::USER) {
|
||||
return;
|
||||
}
|
||||
|
||||
|
|
@ -114,11 +178,13 @@ void EtwSink::SendImpl(const Timestamp& timestamp, const std::string& logger_id,
|
|||
// TraceLoggingWrite requires (painfully) a compile time constant for the TraceLoggingLevel,
|
||||
// forcing us to use an ugly macro for the call.
|
||||
#define ETW_EVENT_NAME "ONNXRuntimeLogEvent"
|
||||
#define TRACE_LOG_WRITE(level) \
|
||||
TraceLoggingWrite(etw_provider_handle, ETW_EVENT_NAME, TraceLoggingLevel(level), \
|
||||
TraceLoggingString(logger_id.c_str(), "logger"), \
|
||||
TraceLoggingString(message.Category(), "category"), \
|
||||
TraceLoggingString(message.Location().ToString().c_str(), "location"), \
|
||||
#define TRACE_LOG_WRITE(level) \
|
||||
TraceLoggingWrite(etw_provider_handle, ETW_EVENT_NAME, \
|
||||
TraceLoggingKeyword(static_cast<uint64_t>(onnxruntime::logging::ORTTraceLoggingKeyword::Logs)), \
|
||||
TraceLoggingLevel(level), \
|
||||
TraceLoggingString(logger_id.c_str(), "logger"), \
|
||||
TraceLoggingString(message.Category(), "category"), \
|
||||
TraceLoggingString(message.Location().ToString().c_str(), "location"), \
|
||||
TraceLoggingString(message.Message().c_str(), "message"))
|
||||
|
||||
const auto severity{message.Severity()};
|
||||
|
|
|
|||
|
|
@ -3,7 +3,9 @@
|
|||
|
||||
#pragma once
|
||||
|
||||
#include <Windows.h>
|
||||
#include <ntverp.h>
|
||||
#include <evntrace.h>
|
||||
|
||||
// check for Windows 10 SDK or later
|
||||
// https://stackoverflow.com/questions/2665755/how-can-i-determine-the-version-of-the-windows-sdk-installed-on-my-computer
|
||||
|
|
@ -18,9 +20,11 @@
|
|||
#include <atomic>
|
||||
#include <iostream>
|
||||
#include <string>
|
||||
#include <vector>
|
||||
|
||||
#include "core/common/logging/capture.h"
|
||||
#include "core/common/logging/isink.h"
|
||||
#include "core/platform/ort_mutex.h"
|
||||
|
||||
namespace onnxruntime {
|
||||
namespace logging {
|
||||
|
|
@ -41,6 +45,62 @@ class EtwSink : public ISink {
|
|||
// EtwTracingManager to ensure we cleanly unregister it
|
||||
static std::atomic_flag have_instance_;
|
||||
};
|
||||
|
||||
class EtwRegistrationManager {
|
||||
public:
|
||||
using EtwInternalCallback = std::function<void(LPCGUID SourceId, ULONG IsEnabled, UCHAR Level,
|
||||
ULONGLONG MatchAnyKeyword, ULONGLONG MatchAllKeyword,
|
||||
PEVENT_FILTER_DESCRIPTOR FilterData, PVOID CallbackContext)>;
|
||||
|
||||
// Singleton instance access
|
||||
static EtwRegistrationManager& Instance();
|
||||
|
||||
// Check if ETW logging is enabled
|
||||
bool IsEnabled() const;
|
||||
|
||||
// Get the current logging level
|
||||
UCHAR Level() const;
|
||||
|
||||
Severity MapLevelToSeverity();
|
||||
|
||||
// Get the current keyword
|
||||
uint64_t Keyword() const;
|
||||
|
||||
// Get the ETW registration status
|
||||
HRESULT Status() const;
|
||||
|
||||
void RegisterInternalCallback(const EtwInternalCallback& callback);
|
||||
|
||||
private:
|
||||
EtwRegistrationManager();
|
||||
~EtwRegistrationManager();
|
||||
void LazyInitialize();
|
||||
|
||||
ORT_DISALLOW_COPY_ASSIGNMENT_AND_MOVE(EtwRegistrationManager);
|
||||
|
||||
void InvokeCallbacks(LPCGUID SourceId, ULONG IsEnabled, UCHAR Level, ULONGLONG MatchAnyKeyword,
|
||||
ULONGLONG MatchAllKeyword, PEVENT_FILTER_DESCRIPTOR FilterData, PVOID CallbackContext);
|
||||
|
||||
static void NTAPI ORT_TL_EtwEnableCallback(
|
||||
_In_ LPCGUID SourceId,
|
||||
_In_ ULONG IsEnabled,
|
||||
_In_ UCHAR Level,
|
||||
_In_ ULONGLONG MatchAnyKeyword,
|
||||
_In_ ULONGLONG MatchAllKeyword,
|
||||
_In_opt_ PEVENT_FILTER_DESCRIPTOR FilterData,
|
||||
_In_opt_ PVOID CallbackContext);
|
||||
|
||||
std::vector<EtwInternalCallback> callbacks_;
|
||||
OrtMutex callbacks_mutex_;
|
||||
mutable OrtMutex provider_change_mutex_;
|
||||
OrtMutex init_mutex_;
|
||||
bool initialized_ = false;
|
||||
bool is_enabled_;
|
||||
UCHAR level_;
|
||||
ULONGLONG keyword_;
|
||||
HRESULT etw_status_;
|
||||
};
|
||||
|
||||
} // namespace logging
|
||||
} // namespace onnxruntime
|
||||
|
||||
|
|
|
|||
|
|
@ -2,6 +2,7 @@
|
|||
// Licensed under the MIT License.
|
||||
|
||||
#include "core/platform/windows/telemetry.h"
|
||||
#include "core/common/logging/logging.h"
|
||||
#include "onnxruntime_config.h"
|
||||
|
||||
// ETW includes
|
||||
|
|
@ -16,6 +17,7 @@
|
|||
|
||||
#include <TraceLoggingProvider.h>
|
||||
#include <evntrace.h>
|
||||
#include <winmeta.h>
|
||||
|
||||
// Seems this workaround can be dropped when we drop support for VS2017 toolchains
|
||||
// https://developercommunity.visualstudio.com/content/problem/85934/traceloggingproviderh-is-incompatible-with-utf-8.html
|
||||
|
|
@ -55,15 +57,18 @@ TRACELOGGING_DEFINE_PROVIDER(telemetry_provider_handle, "Microsoft.ML.ONNXRuntim
|
|||
#endif
|
||||
|
||||
OrtMutex WindowsTelemetry::mutex_;
|
||||
OrtMutex WindowsTelemetry::provider_change_mutex_;
|
||||
uint32_t WindowsTelemetry::global_register_count_ = 0;
|
||||
bool WindowsTelemetry::enabled_ = true;
|
||||
uint32_t WindowsTelemetry::projection_ = 0;
|
||||
UCHAR WindowsTelemetry::level_ = 0;
|
||||
UINT64 WindowsTelemetry::keyword_ = 0;
|
||||
|
||||
WindowsTelemetry::WindowsTelemetry() {
|
||||
std::lock_guard<OrtMutex> lock(mutex_);
|
||||
if (global_register_count_ == 0) {
|
||||
// TraceLoggingRegister is fancy in that you can only register once GLOBALLY for the whole process
|
||||
HRESULT hr = TraceLoggingRegister(telemetry_provider_handle);
|
||||
HRESULT hr = TraceLoggingRegisterEx(telemetry_provider_handle, ORT_TL_EtwEnableCallback, nullptr);
|
||||
if (SUCCEEDED(hr)) {
|
||||
global_register_count_ += 1;
|
||||
}
|
||||
|
|
@ -80,6 +85,44 @@ WindowsTelemetry::~WindowsTelemetry() {
|
|||
}
|
||||
}
|
||||
|
||||
bool WindowsTelemetry::IsEnabled() const {
|
||||
std::lock_guard<OrtMutex> lock(provider_change_mutex_);
|
||||
return enabled_;
|
||||
}
|
||||
|
||||
UCHAR WindowsTelemetry::Level() const {
|
||||
std::lock_guard<OrtMutex> lock(provider_change_mutex_);
|
||||
return level_;
|
||||
}
|
||||
|
||||
UINT64 WindowsTelemetry::Keyword() const {
|
||||
std::lock_guard<OrtMutex> lock(provider_change_mutex_);
|
||||
return keyword_;
|
||||
}
|
||||
|
||||
// HRESULT WindowsTelemetry::Status() {
|
||||
// return etw_status_;
|
||||
// }
|
||||
|
||||
void NTAPI WindowsTelemetry::ORT_TL_EtwEnableCallback(
|
||||
_In_ LPCGUID SourceId,
|
||||
_In_ ULONG IsEnabled,
|
||||
_In_ UCHAR Level,
|
||||
_In_ ULONGLONG MatchAnyKeyword,
|
||||
_In_ ULONGLONG MatchAllKeyword,
|
||||
_In_opt_ PEVENT_FILTER_DESCRIPTOR FilterData,
|
||||
_In_opt_ PVOID CallbackContext) {
|
||||
(void)SourceId;
|
||||
(void)MatchAllKeyword;
|
||||
(void)FilterData;
|
||||
(void)CallbackContext;
|
||||
|
||||
std::lock_guard<OrtMutex> lock(provider_change_mutex_);
|
||||
enabled_ = (IsEnabled != 0);
|
||||
level_ = Level;
|
||||
keyword_ = MatchAnyKeyword;
|
||||
}
|
||||
|
||||
void WindowsTelemetry::EnableTelemetryEvents() const {
|
||||
enabled_ = true;
|
||||
}
|
||||
|
|
@ -110,6 +153,7 @@ void WindowsTelemetry::LogProcessInfo() const {
|
|||
TraceLoggingBool(true, "UTCReplace_AppSessionGuid"),
|
||||
TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage),
|
||||
TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES),
|
||||
TraceLoggingLevel(WINEVENT_LEVEL_INFO),
|
||||
// Telemetry info
|
||||
TraceLoggingUInt8(0, "schemaVersion"),
|
||||
TraceLoggingString(ORT_VERSION, "runtimeVersion"),
|
||||
|
|
@ -126,7 +170,8 @@ void WindowsTelemetry::LogSessionCreationStart() const {
|
|||
"SessionCreationStart",
|
||||
TraceLoggingBool(true, "UTCReplace_AppSessionGuid"),
|
||||
TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage),
|
||||
TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES));
|
||||
TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES),
|
||||
TraceLoggingLevel(WINEVENT_LEVEL_INFO));
|
||||
}
|
||||
|
||||
void WindowsTelemetry::LogEvaluationStop() const {
|
||||
|
|
@ -199,6 +244,8 @@ void WindowsTelemetry::LogSessionCreation(uint32_t session_id, int64_t ir_versio
|
|||
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"),
|
||||
|
|
@ -227,6 +274,7 @@ void WindowsTelemetry::LogRuntimeError(uint32_t session_id, const common::Status
|
|||
TraceLoggingBool(true, "UTCReplace_AppSessionGuid"),
|
||||
TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance),
|
||||
TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES),
|
||||
TraceLoggingLevel(WINEVENT_LEVEL_ERROR),
|
||||
// Telemetry info
|
||||
TraceLoggingUInt8(0, "schemaVersion"),
|
||||
TraceLoggingHResult(hr, "hResult"),
|
||||
|
|
@ -243,6 +291,7 @@ void WindowsTelemetry::LogRuntimeError(uint32_t session_id, const common::Status
|
|||
TraceLoggingBool(true, "UTCReplace_AppSessionGuid"),
|
||||
TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance),
|
||||
TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES),
|
||||
TraceLoggingLevel(WINEVENT_LEVEL_ERROR),
|
||||
// Telemetry info
|
||||
TraceLoggingUInt8(0, "schemaVersion"),
|
||||
TraceLoggingUInt32(session_id, "sessionId"),
|
||||
|
|
|
|||
|
|
@ -3,6 +3,8 @@
|
|||
|
||||
#pragma once
|
||||
#include "core/platform/telemetry.h"
|
||||
#include <Windows.h>
|
||||
#include <TraceLoggingProvider.h>
|
||||
#include "core/platform/ort_mutex.h"
|
||||
#include "core/platform/windows/TraceLoggingConfig.h"
|
||||
#include <atomic>
|
||||
|
|
@ -22,6 +24,17 @@ class WindowsTelemetry : public Telemetry {
|
|||
void DisableTelemetryEvents() const override;
|
||||
void SetLanguageProjection(uint32_t projection) const override;
|
||||
|
||||
bool IsEnabled() const override;
|
||||
|
||||
// Get the current logging level
|
||||
unsigned char Level() const override;
|
||||
|
||||
// Get the current keyword
|
||||
UINT64 Keyword() const override;
|
||||
|
||||
// Get the ETW registration status
|
||||
// static HRESULT Status();
|
||||
|
||||
void LogProcessInfo() const override;
|
||||
|
||||
void LogSessionCreationStart() const override;
|
||||
|
|
@ -50,6 +63,19 @@ class WindowsTelemetry : public Telemetry {
|
|||
static uint32_t global_register_count_;
|
||||
static bool enabled_;
|
||||
static uint32_t projection_;
|
||||
|
||||
static OrtMutex provider_change_mutex_;
|
||||
static UCHAR level_;
|
||||
static ULONGLONG keyword_;
|
||||
|
||||
static void NTAPI ORT_TL_EtwEnableCallback(
|
||||
_In_ LPCGUID SourceId,
|
||||
_In_ ULONG IsEnabled,
|
||||
_In_ UCHAR Level,
|
||||
_In_ ULONGLONG MatchAnyKeyword,
|
||||
_In_ ULONGLONG MatchAllKeyword,
|
||||
_In_opt_ PEVENT_FILTER_DESCRIPTOR FilterData,
|
||||
_In_opt_ PVOID CallbackContext);
|
||||
};
|
||||
|
||||
} // namespace onnxruntime
|
||||
|
|
|
|||
|
|
@ -18,6 +18,11 @@
|
|||
#include "core/common/logging/capture.h"
|
||||
#include "core/providers/qnn/builder/onnx_ctx_model_helper.h"
|
||||
|
||||
#ifdef _WIN32
|
||||
#include <winmeta.h>
|
||||
#include "core/platform/tracing.h"
|
||||
#endif
|
||||
|
||||
// Flag to determine if Backend should do node validation for each opNode added
|
||||
#define DO_GRAPH_NODE_VALIDATIONS 1
|
||||
|
||||
|
|
@ -843,28 +848,46 @@ Status QnnBackendManager::ExtractBackendProfilingInfo() {
|
|||
LOGS(*logger_, VERBOSE) << "The QNN backend does not support extended event data.";
|
||||
}
|
||||
|
||||
// Write to CSV in append mode
|
||||
const char* profilingCsvFilename = "qnn-profiling-data.csv";
|
||||
std::ifstream infile(profilingCsvFilename);
|
||||
bool exists = infile.good();
|
||||
infile.close();
|
||||
bool tracelogging_provider_ep_enabled = false;
|
||||
const Env& env = Env::Default();
|
||||
auto& provider = env.GetTelemetryProvider();
|
||||
if (provider.IsEnabled()) {
|
||||
auto keyword = provider.Keyword();
|
||||
if ((keyword & static_cast<uint64_t>(onnxruntime::logging::ORTTraceLoggingKeyword::Profiling)) != 0) {
|
||||
tracelogging_provider_ep_enabled = true;
|
||||
}
|
||||
}
|
||||
std::ofstream outfile;
|
||||
if (!tracelogging_provider_ep_enabled) {
|
||||
// Write to CSV in append mode
|
||||
const char* profilingCsvFilename = "qnn-profiling-data.csv";
|
||||
std::ifstream infile(profilingCsvFilename);
|
||||
bool exists = infile.good();
|
||||
infile.close();
|
||||
|
||||
std::ofstream outfile(profilingCsvFilename, std::ios_base::app);
|
||||
ORT_RETURN_IF(!outfile.is_open(), "Failed to open qnn-profiling-data.csv");
|
||||
// If file didn't exist before, write the header
|
||||
if (!exists) {
|
||||
outfile << "Msg Timestamp,Message,Time,Unit of Measurement,Timing Source,Event Level,Event Identifier\n";
|
||||
outfile.open(profilingCsvFilename, std::ios_base::app);
|
||||
ORT_RETURN_IF(!outfile.is_open(), "Failed to open qnn-profiling-data.csv");
|
||||
// If file didn't exist before, write the header
|
||||
if (!exists) {
|
||||
outfile << "Msg Timestamp,Message,Time,Unit of Measurement,Timing Source,Event Level,Event Identifier\n";
|
||||
}
|
||||
}
|
||||
|
||||
for (size_t event_idx = 0; event_idx < num_events; event_idx++) {
|
||||
ORT_RETURN_IF_ERROR(
|
||||
ExtractProfilingEvent(*(profile_events + event_idx), "ROOT", outfile, backendSupportsExtendedEventData));
|
||||
ExtractProfilingEvent(*(profile_events + event_idx), "ROOT", outfile, backendSupportsExtendedEventData,
|
||||
tracelogging_provider_ep_enabled));
|
||||
ORT_RETURN_IF_ERROR(
|
||||
ExtractProfilingSubEvents(*(profile_events + event_idx), outfile, backendSupportsExtendedEventData));
|
||||
ExtractProfilingSubEvents(*(profile_events + event_idx), outfile, backendSupportsExtendedEventData,
|
||||
tracelogging_provider_ep_enabled));
|
||||
}
|
||||
|
||||
outfile.close();
|
||||
LOGS(*logger_, INFO) << "Wrote QNN profiling events (" << num_events << ") to qnn-profiling-data.csv";
|
||||
if (!tracelogging_provider_ep_enabled) {
|
||||
outfile.close();
|
||||
LOGS(*logger_, VERBOSE) << "Wrote QNN profiling events (" << num_events << ") to qnn-profiling-data.csv";
|
||||
} else {
|
||||
LOGS(*logger_, VERBOSE) << "Wrote QNN profiling events (" << num_events << ") to ETW";
|
||||
}
|
||||
}
|
||||
|
||||
return Status::OK();
|
||||
|
|
@ -873,7 +896,8 @@ Status QnnBackendManager::ExtractBackendProfilingInfo() {
|
|||
Status QnnBackendManager::ExtractProfilingSubEvents(
|
||||
QnnProfile_EventId_t profile_event_id,
|
||||
std::ofstream& outfile,
|
||||
bool useExtendedEventData) {
|
||||
bool useExtendedEventData,
|
||||
bool tracelogging_provider_ep_enabled) {
|
||||
const QnnProfile_EventId_t* profile_sub_events{nullptr};
|
||||
uint32_t num_sub_events{0};
|
||||
auto result = qnn_interface_.profileGetSubEvents(profile_event_id, &profile_sub_events, &num_sub_events);
|
||||
|
|
@ -884,12 +908,14 @@ Status QnnBackendManager::ExtractProfilingSubEvents(
|
|||
|
||||
for (size_t sub_event_idx = 0; sub_event_idx < num_sub_events; sub_event_idx++) {
|
||||
ORT_RETURN_IF_ERROR(
|
||||
ExtractProfilingEvent(*(profile_sub_events + sub_event_idx), "SUB-EVENT", outfile, useExtendedEventData));
|
||||
ExtractProfilingEvent(*(profile_sub_events + sub_event_idx), "SUB-EVENT", outfile, useExtendedEventData,
|
||||
tracelogging_provider_ep_enabled));
|
||||
ORT_RETURN_IF_ERROR(
|
||||
ExtractProfilingSubEvents(*(profile_sub_events + sub_event_idx), outfile, useExtendedEventData));
|
||||
ExtractProfilingSubEvents(*(profile_sub_events + sub_event_idx), outfile, useExtendedEventData,
|
||||
tracelogging_provider_ep_enabled));
|
||||
}
|
||||
|
||||
LOGS(*logger_, INFO) << "Wrote QNN profiling sub events (" << num_sub_events << ") to qnn-profiling-data.csv";
|
||||
LOGS(*logger_, VERBOSE) << "Wrote QNN profiling sub events (" << num_sub_events << ")";
|
||||
}
|
||||
|
||||
return Status::OK();
|
||||
|
|
@ -899,18 +925,20 @@ Status QnnBackendManager::ExtractProfilingEvent(
|
|||
QnnProfile_EventId_t profile_event_id,
|
||||
const std::string& eventLevel,
|
||||
std::ofstream& outfile,
|
||||
bool useExtendedEventData) {
|
||||
bool useExtendedEventData,
|
||||
bool tracelogging_provider_ep_enabled) {
|
||||
if (useExtendedEventData) {
|
||||
return ExtractProfilingEventExtended(profile_event_id, eventLevel, outfile);
|
||||
return ExtractProfilingEventExtended(profile_event_id, eventLevel, outfile, tracelogging_provider_ep_enabled);
|
||||
} else {
|
||||
return ExtractProfilingEventBasic(profile_event_id, eventLevel, outfile);
|
||||
return ExtractProfilingEventBasic(profile_event_id, eventLevel, outfile, tracelogging_provider_ep_enabled);
|
||||
}
|
||||
}
|
||||
|
||||
Status QnnBackendManager::ExtractProfilingEventBasic(
|
||||
QnnProfile_EventId_t profile_event_id,
|
||||
const std::string& eventLevel,
|
||||
std::ofstream& outfile) {
|
||||
std::ofstream& outfile,
|
||||
bool tracelogging_provider_ep_enabled) {
|
||||
QnnProfile_EventData_t event_data;
|
||||
auto result = qnn_interface_.profileGetEventData(profile_event_id, &event_data);
|
||||
QnnProfile_Error_t errorCode = static_cast<QnnProfile_Error_t>(result & 0xFFFF);
|
||||
|
|
@ -919,15 +947,32 @@ Status QnnBackendManager::ExtractProfilingEventBasic(
|
|||
std::string message = GetEventTypeString(event_data.type);
|
||||
std::string unit = GetUnitString(event_data.unit);
|
||||
|
||||
outfile << "UNKNOWN"
|
||||
<< ","
|
||||
<< message << ","
|
||||
<< event_data.value << ","
|
||||
<< unit << ","
|
||||
<< "BACKEND"
|
||||
<< ","
|
||||
<< eventLevel << ","
|
||||
<< (event_data.identifier ? event_data.identifier : "NULL") << "\n";
|
||||
#ifndef _WIN32
|
||||
tracelogging_provider_ep_enabled = false;
|
||||
#endif
|
||||
|
||||
if (!tracelogging_provider_ep_enabled) {
|
||||
outfile << "UNKNOWN"
|
||||
<< ","
|
||||
<< message << ","
|
||||
<< event_data.value << ","
|
||||
<< unit << ","
|
||||
<< "BACKEND"
|
||||
<< ","
|
||||
<< eventLevel << ","
|
||||
<< (event_data.identifier ? event_data.identifier : "NULL") << "\n";
|
||||
} else {
|
||||
#ifdef _WIN32
|
||||
LogQnnProfileEventAsTraceLogging(
|
||||
(uint64_t)0,
|
||||
message,
|
||||
std::to_string(event_data.value),
|
||||
unit,
|
||||
"BACKEND",
|
||||
eventLevel,
|
||||
(event_data.identifier ? event_data.identifier : "NULL"));
|
||||
#endif
|
||||
}
|
||||
|
||||
return Status::OK();
|
||||
}
|
||||
|
|
@ -935,7 +980,8 @@ Status QnnBackendManager::ExtractProfilingEventBasic(
|
|||
Status QnnBackendManager::ExtractProfilingEventExtended(
|
||||
QnnProfile_EventId_t profile_event_id,
|
||||
const std::string& eventLevel,
|
||||
std::ofstream& outfile) {
|
||||
std::ofstream& outfile,
|
||||
bool tracelogging_provider_ep_enabled) {
|
||||
QnnProfile_ExtendedEventData_t event_data_extended;
|
||||
auto resultGetExtendedEventData = qnn_interface_.profileGetExtendedEventData(profile_event_id, &event_data_extended);
|
||||
QnnProfile_Error_t errorCode = static_cast<QnnProfile_Error_t>(resultGetExtendedEventData & 0xFFFF);
|
||||
|
|
@ -944,20 +990,61 @@ Status QnnBackendManager::ExtractProfilingEventExtended(
|
|||
std::string message = GetEventTypeString(event_data_extended.v1.type);
|
||||
std::string unit = GetUnitString(event_data_extended.v1.unit);
|
||||
|
||||
if (event_data_extended.version == QNN_PROFILE_DATA_VERSION_1) {
|
||||
outfile << event_data_extended.v1.timestamp << ","
|
||||
<< message << ","
|
||||
<< ExtractQnnScalarValue(event_data_extended.v1.value) << ","
|
||||
<< unit << ","
|
||||
<< "BACKEND"
|
||||
<< ","
|
||||
<< eventLevel << ","
|
||||
<< (event_data_extended.v1.identifier ? event_data_extended.v1.identifier : "NULL") << "\n";
|
||||
#ifndef _WIN32
|
||||
tracelogging_provider_ep_enabled = false;
|
||||
#endif
|
||||
|
||||
if (!tracelogging_provider_ep_enabled) {
|
||||
if (event_data_extended.version == QNN_PROFILE_DATA_VERSION_1) {
|
||||
outfile << event_data_extended.v1.timestamp << ","
|
||||
<< message << ","
|
||||
<< ExtractQnnScalarValue(event_data_extended.v1.value) << ","
|
||||
<< unit << ","
|
||||
<< "BACKEND"
|
||||
<< ","
|
||||
<< eventLevel << ","
|
||||
<< (event_data_extended.v1.identifier ? event_data_extended.v1.identifier : "NULL") << "\n";
|
||||
}
|
||||
} else {
|
||||
#ifdef _WIN32
|
||||
LogQnnProfileEventAsTraceLogging(
|
||||
event_data_extended.v1.timestamp,
|
||||
message,
|
||||
ExtractQnnScalarValue(event_data_extended.v1.value),
|
||||
unit,
|
||||
"BACKEND",
|
||||
eventLevel,
|
||||
(event_data_extended.v1.identifier ? event_data_extended.v1.identifier : "NULL"));
|
||||
#endif
|
||||
}
|
||||
|
||||
return Status::OK();
|
||||
}
|
||||
|
||||
#ifdef _WIN32
|
||||
void QnnBackendManager::LogQnnProfileEventAsTraceLogging(
|
||||
uint64_t timestamp,
|
||||
const std::string& message,
|
||||
const std::string& qnnScalarValue,
|
||||
const std::string& unit,
|
||||
const std::string& timingSource,
|
||||
const std::string& eventLevel,
|
||||
const char* eventIdentifier) {
|
||||
TraceLoggingWrite(
|
||||
telemetry_provider_handle,
|
||||
"QNNProfilingEvent",
|
||||
TraceLoggingKeyword(static_cast<uint64_t>(onnxruntime::logging::ORTTraceLoggingKeyword::Profiling)),
|
||||
TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
|
||||
TraceLoggingValue(timestamp, "Timestamp"),
|
||||
TraceLoggingString(message.c_str(), "Message"),
|
||||
TraceLoggingString(qnnScalarValue.c_str(), "Value"),
|
||||
TraceLoggingString(unit.c_str(), "Unit of Measurement"),
|
||||
TraceLoggingString(timingSource.c_str(), "Timing Source"),
|
||||
TraceLoggingString(eventLevel.c_str(), "Event Level"),
|
||||
TraceLoggingString(eventIdentifier, "Event Identifier"));
|
||||
}
|
||||
#endif
|
||||
|
||||
const std::string& QnnBackendManager::GetUnitString(QnnProfile_EventUnit_t unitType) {
|
||||
const auto& unitStringMap = GetUnitStringMap();
|
||||
auto it = unitStringMap.find(unitType);
|
||||
|
|
|
|||
|
|
@ -6,10 +6,15 @@
|
|||
#include <windows.h>
|
||||
#include <psapi.h>
|
||||
#include <libloaderapi.h>
|
||||
#include <set>
|
||||
#else
|
||||
#include <dlfcn.h>
|
||||
#endif
|
||||
|
||||
#include <memory>
|
||||
#include <string>
|
||||
#include <unordered_map>
|
||||
#include <vector>
|
||||
#include "HTP/QnnHtpDevice.h"
|
||||
#include "QnnLog.h"
|
||||
#include "System/QnnSystemInterface.h"
|
||||
|
|
@ -117,8 +122,11 @@ class QnnBackendManager {
|
|||
void Split(std::vector<std::string>& split_string, const std::string& tokenized_string, const char separator);
|
||||
|
||||
Status ExtractBackendProfilingInfo();
|
||||
Status ExtractProfilingSubEvents(QnnProfile_EventId_t profile_event_id, std::ofstream& outfile, bool backendSupportsExtendedEventData);
|
||||
Status ExtractProfilingEvent(QnnProfile_EventId_t profile_event_id, const std::string& eventLevel, std::ofstream& outfile, bool backendSupportsExtendedEventData);
|
||||
Status ExtractProfilingSubEvents(QnnProfile_EventId_t profile_event_id, std::ofstream& outfile,
|
||||
bool backendSupportsExtendedEventData, bool tracelogging_provider_ep_enabled);
|
||||
Status ExtractProfilingEvent(QnnProfile_EventId_t profile_event_id, const std::string& eventLevel,
|
||||
std::ofstream& outfile, bool backendSupportsExtendedEventData,
|
||||
bool tracelogging_provider_ep_enabled);
|
||||
|
||||
void SetQnnBackendType(uint32_t backend_id);
|
||||
QnnBackendType GetQnnBackendType() { return qnn_backend_type_; }
|
||||
|
|
@ -175,13 +183,25 @@ class QnnBackendManager {
|
|||
return (backend_build_id == nullptr ? std::string("") : std::string(backend_build_id));
|
||||
}
|
||||
|
||||
Status ExtractProfilingEventBasic(QnnProfile_EventId_t profile_event_id, const std::string& eventLevel, std::ofstream& outfile);
|
||||
Status ExtractProfilingEventExtended(QnnProfile_EventId_t profile_event_id, const std::string& eventLevel, std::ofstream& outfile);
|
||||
Status ExtractProfilingEventBasic(QnnProfile_EventId_t profile_event_id, const std::string& eventLevel,
|
||||
std::ofstream& outfile, bool tracelogging_provider_ep_enabled);
|
||||
Status ExtractProfilingEventExtended(QnnProfile_EventId_t profile_event_id, const std::string& eventLevel,
|
||||
std::ofstream& outfile, bool tracelogging_provider_ep_enabled);
|
||||
static const std::string& GetUnitString(QnnProfile_EventUnit_t unitType);
|
||||
static const std::unordered_map<QnnProfile_EventUnit_t, std::string>& GetUnitStringMap();
|
||||
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);
|
||||
#ifdef _WIN32
|
||||
void LogQnnProfileEventAsTraceLogging(
|
||||
uint64_t timestamp,
|
||||
const std::string& message,
|
||||
const std::string& qnnScalarValue,
|
||||
const std::string& unit,
|
||||
const std::string& timingSource,
|
||||
const std::string& eventLevel,
|
||||
const char* eventIdentifier);
|
||||
#endif
|
||||
|
||||
private:
|
||||
const std::string backend_path_;
|
||||
|
|
|
|||
|
|
@ -4,12 +4,13 @@
|
|||
#include "qnn_execution_provider.h"
|
||||
|
||||
#include <filesystem>
|
||||
#include "core/providers/common.h"
|
||||
#include "core/framework/compute_capability.h"
|
||||
#include "core/graph/graph_viewer.h"
|
||||
#include "core/session/onnxruntime_session_options_config_keys.h"
|
||||
#include "core/session/onnxruntime_cxx_api.h"
|
||||
#include "core/framework/kernel_registry.h"
|
||||
#include "core/platform/env.h"
|
||||
#include "core/providers/common.h"
|
||||
#include "core/providers/partitioning_utils.h"
|
||||
#include "core/providers/qnn/builder/op_builder_factory.h"
|
||||
#include "core/providers/partitioning_utils.h"
|
||||
|
|
@ -28,7 +29,7 @@ static void ParseProfilingLevel(std::string profiling_level_string,
|
|||
profiling_level_string.end(),
|
||||
profiling_level_string.begin(),
|
||||
[](unsigned char c) { return static_cast<unsigned char>(std::tolower(c)); });
|
||||
LOGS_DEFAULT(VERBOSE) << "profiling_level: " << profiling_level_string;
|
||||
LOGS_DEFAULT(INFO) << "profiling_level: " << profiling_level_string;
|
||||
if (profiling_level_string == "off") {
|
||||
profiling_level = qnn::ProfilingLevel::OFF;
|
||||
} else if (profiling_level_string == "basic") {
|
||||
|
|
@ -146,9 +147,30 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio
|
|||
|
||||
static const std::string PROFILING_LEVEL = "profiling_level";
|
||||
qnn::ProfilingLevel profiling_level = qnn::ProfilingLevel::OFF;
|
||||
auto profiling_level_pos = provider_options_map.find(PROFILING_LEVEL);
|
||||
if (profiling_level_pos != provider_options_map.end()) {
|
||||
ParseProfilingLevel(profiling_level_pos->second, profiling_level);
|
||||
const Env& env = Env::Default();
|
||||
auto& provider = env.GetTelemetryProvider();
|
||||
if (provider.IsEnabled()) {
|
||||
auto level = provider.Level();
|
||||
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);
|
||||
ParseProfilingLevel("basic", profiling_level);
|
||||
} else if (level < 5) {
|
||||
LOGS_DEFAULT(INFO) << "QNN Profiler ETW level not supported below level 5. Level: "
|
||||
<< static_cast<int>(level);
|
||||
} else {
|
||||
LOGS_DEFAULT(INFO) << "Overriding profiling to detailed based on ETW level: " << static_cast<int>(level);
|
||||
ParseProfilingLevel("detailed", profiling_level);
|
||||
}
|
||||
}
|
||||
}
|
||||
} else {
|
||||
auto profiling_level_pos = provider_options_map.find(PROFILING_LEVEL);
|
||||
if (profiling_level_pos != provider_options_map.end()) {
|
||||
ParseProfilingLevel(profiling_level_pos->second, profiling_level);
|
||||
}
|
||||
}
|
||||
|
||||
static const std::string RPC_CONTROL_LANTENCY = "rpc_control_latency";
|
||||
|
|
|
|||
|
|
@ -69,6 +69,11 @@
|
|||
#include "core/util/protobuf_parsing_utils.h"
|
||||
#include "core/util/thread_utils.h"
|
||||
|
||||
#ifdef _WIN32
|
||||
#include "core/platform/windows/logging/etw_sink.h"
|
||||
#include "core/common/logging/sinks/composite_sink.h"
|
||||
#endif
|
||||
|
||||
// custom ops are not available in a minimal build unless ORT_MINIMAL_BUILD_CUSTOM_OPS is set
|
||||
#if !defined(ORT_MINIMAL_BUILD) || defined(ORT_MINIMAL_BUILD_CUSTOM_OPS)
|
||||
#include "core/framework/customregistry.h"
|
||||
|
|
@ -307,6 +312,7 @@ static Status FinalizeSessionOptions(const SessionOptions& user_provided_session
|
|||
|
||||
logging::Severity GetSeverity(const SessionOptions& session_options) {
|
||||
logging::Severity severity = logging::Severity::kWARNING;
|
||||
|
||||
if (session_options.session_log_severity_level == -1) {
|
||||
severity = logging::LoggingManager::DefaultLogger().GetSeverity();
|
||||
} else {
|
||||
|
|
@ -322,11 +328,17 @@ logging::Severity GetSeverity(const SessionOptions& session_options) {
|
|||
void InferenceSession::SetLoggingManager(const SessionOptions& session_options,
|
||||
const Environment& session_env) {
|
||||
logging_manager_ = session_env.GetLoggingManager();
|
||||
std::unique_ptr<logging::ISink> sink;
|
||||
|
||||
if (session_options.user_logging_function) {
|
||||
std::unique_ptr<logging::ISink> user_sink = std::make_unique<UserLoggingSink>(session_options.user_logging_function,
|
||||
session_options.user_logging_param);
|
||||
user_logging_manager_ = std::make_unique<logging::LoggingManager>(std::move(user_sink),
|
||||
GetSeverity(session_options),
|
||||
sink = std::make_unique<UserLoggingSink>(session_options.user_logging_function,
|
||||
session_options.user_logging_param);
|
||||
auto sessionSeverity = GetSeverity(session_options);
|
||||
auto etwOverrideSeverity = logging::OverrideLevelWithEtw(sessionSeverity);
|
||||
sink = EnhanceLoggerWithEtw(std::move(sink), sessionSeverity, etwOverrideSeverity);
|
||||
|
||||
user_logging_manager_ = std::make_unique<logging::LoggingManager>(std::move(sink),
|
||||
std::min(sessionSeverity, etwOverrideSeverity),
|
||||
false,
|
||||
logging::LoggingManager::InstanceType::Temporal,
|
||||
&session_options.session_logid);
|
||||
|
|
@ -467,6 +479,8 @@ void InferenceSession::TraceSessionOptions(const SessionOptions& session_options
|
|||
#ifdef _WIN32
|
||||
TraceLoggingWrite(telemetry_provider_handle,
|
||||
"SessionOptions",
|
||||
TraceLoggingKeyword(static_cast<uint64_t>(onnxruntime::logging::ORTTraceLoggingKeyword::Session)),
|
||||
TraceLoggingLevel(WINEVENT_LEVEL_INFO),
|
||||
TraceLoggingUInt8(static_cast<UINT8>(session_options.execution_mode), "execution_mode"),
|
||||
TraceLoggingUInt8(static_cast<UINT8>(session_options.execution_order), "execution_order"),
|
||||
TraceLoggingBoolean(session_options.enable_profiling, "enable_profiling"),
|
||||
|
|
@ -487,6 +501,8 @@ void InferenceSession::TraceSessionOptions(const SessionOptions& session_options
|
|||
TraceLoggingWrite(
|
||||
telemetry_provider_handle,
|
||||
"SessionOptions_IntraOrtThreadPoolParams",
|
||||
TraceLoggingKeyword(static_cast<uint64_t>(onnxruntime::logging::ORTTraceLoggingKeyword::Session)),
|
||||
TraceLoggingLevel(WINEVENT_LEVEL_INFO),
|
||||
TraceLoggingInt32(session_options.intra_op_param.thread_pool_size, "thread_pool_size"),
|
||||
TraceLoggingBoolean(session_options.intra_op_param.auto_set_affinity, "auto_set_affinity"),
|
||||
TraceLoggingBoolean(session_options.intra_op_param.allow_spinning, "allow_spinning"),
|
||||
|
|
@ -499,6 +515,8 @@ void InferenceSession::TraceSessionOptions(const SessionOptions& session_options
|
|||
TraceLoggingWrite(
|
||||
telemetry_provider_handle,
|
||||
"SessionOptions_ConfigEntry",
|
||||
TraceLoggingKeyword(static_cast<uint64_t>(onnxruntime::logging::ORTTraceLoggingKeyword::Session)),
|
||||
TraceLoggingLevel(WINEVENT_LEVEL_INFO),
|
||||
TraceLoggingString(config_pair.first.c_str(), "Key"),
|
||||
TraceLoggingString(config_pair.second.c_str(), "Value"));
|
||||
}
|
||||
|
|
|
|||
|
|
@ -39,23 +39,23 @@ OrtEnv* OrtEnv::GetInstance(const OrtEnv::LoggingManagerConstructionInfo& lm_inf
|
|||
if (!p_instance_) {
|
||||
std::unique_ptr<LoggingManager> lmgr;
|
||||
std::string name = lm_info.logid;
|
||||
if (lm_info.logging_function) {
|
||||
std::unique_ptr<ISink> logger = std::make_unique<UserLoggingSink>(lm_info.logging_function,
|
||||
lm_info.logger_param);
|
||||
lmgr = std::make_unique<LoggingManager>(std::move(logger),
|
||||
static_cast<Severity>(lm_info.default_warning_level),
|
||||
false,
|
||||
LoggingManager::InstanceType::Default,
|
||||
&name);
|
||||
} else {
|
||||
auto sink = MakePlatformDefaultLogSink();
|
||||
|
||||
lmgr = std::make_unique<LoggingManager>(std::move(sink),
|
||||
static_cast<Severity>(lm_info.default_warning_level),
|
||||
false,
|
||||
LoggingManager::InstanceType::Default,
|
||||
&name);
|
||||
std::unique_ptr<ISink> sink = nullptr;
|
||||
if (lm_info.logging_function) {
|
||||
sink = std::make_unique<UserLoggingSink>(lm_info.logging_function, lm_info.logger_param);
|
||||
|
||||
} else {
|
||||
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);
|
||||
lmgr = std::make_unique<LoggingManager>(std::move(sink),
|
||||
std::min(static_cast<Severity>(lm_info.default_warning_level), etwOverrideSeverity),
|
||||
false,
|
||||
LoggingManager::InstanceType::Default,
|
||||
&name);
|
||||
|
||||
std::unique_ptr<onnxruntime::Environment> env;
|
||||
if (!tp_options) {
|
||||
status = onnxruntime::Environment::Create(std::move(lmgr), env);
|
||||
|
|
|
|||
|
|
@ -4,6 +4,7 @@
|
|||
#include <string>
|
||||
|
||||
#include "core/common/common.h"
|
||||
#include "core/common/logging/logging.h"
|
||||
#include "core/framework/error_code_helper.h"
|
||||
#include "core/framework/provider_options.h"
|
||||
#include "core/providers/provider_factory_creators.h"
|
||||
|
|
@ -13,6 +14,7 @@
|
|||
#include "core/providers/openvino/openvino_provider_factory_creator.h"
|
||||
|
||||
#ifdef _WIN32
|
||||
#include <winmeta.h>
|
||||
#include "core/platform/tracing.h"
|
||||
#endif
|
||||
|
||||
|
|
@ -75,6 +77,8 @@ ORT_API_STATUS_IMPL(OrtApis::SessionOptionsAppendExecutionProvider,
|
|||
TraceLoggingWrite(
|
||||
telemetry_provider_handle,
|
||||
"ProviderOptionsAppendExecutionProvider",
|
||||
TraceLoggingKeyword(static_cast<uint64_t>(onnxruntime::logging::ORTTraceLoggingKeyword::Session)),
|
||||
TraceLoggingLevel(WINEVENT_LEVEL_INFO),
|
||||
TraceLoggingString(provider_name, "ProviderName"),
|
||||
TraceLoggingString(config_pair.first.c_str(), "Key"),
|
||||
TraceLoggingString(config_pair.second.c_str(), "Value"));
|
||||
|
|
|
|||
|
|
@ -156,7 +156,7 @@ TEST(LoggingTests, TestCompositeSink) {
|
|||
EXPECT_CALL(*sink_ptr2, SendImpl(testing::_, testing::_, testing::_)).Times(1);
|
||||
|
||||
CompositeSink* sink = new CompositeSink();
|
||||
sink->AddSink(std::unique_ptr<ISink>{sink_ptr1}).AddSink(std::unique_ptr<ISink>{sink_ptr2});
|
||||
sink->AddSink(std::unique_ptr<ISink>{sink_ptr1}, min_log_level).AddSink(std::unique_ptr<ISink>{sink_ptr2}, min_log_level);
|
||||
LoggingManager manager{std::unique_ptr<ISink>(sink), min_log_level, false, InstanceType::Temporal};
|
||||
|
||||
auto logger = manager.CreateLogger(logid);
|
||||
|
|
|
|||
|
|
@ -1,10 +1,19 @@
|
|||
## Validating ETW Sink unit test output
|
||||
## About the ETW Sink
|
||||
|
||||
## Setup
|
||||
Install Windows Performance Toolkit from <https://docs.microsoft.com/en-us/windows-hardware/get-started/adk-install>
|
||||
You get to select components when installing, so can select just the performance toolkit.
|
||||
The ETW Sink (ONNXRuntimeTraceLoggingProvider) allows ONNX semi-structured printf style logs to be output via ETW.
|
||||
|
||||
Overview of the steps is at <https://msdn.microsoft.com/en-us/library/windows/desktop/dn904629(v=vs.85).aspx> if you want more detail.
|
||||
ETW makes it easy and useful to only enable and listen for events with great performance, and when you need them instead of only at compile time.
|
||||
Therefore ONNX will preserve any existing loggers and log severity [provided at compile time](docs/FAQ.md?plain=1#L7).
|
||||
|
||||
However, when the provider is enabled a new ETW logger sink will also be added and the severity separately controlled via ETW dynamically.
|
||||
|
||||
- Provider GUID: 929DD115-1ECB-4CB5-B060-EBD4983C421D
|
||||
- Keyword: Logs (0x2) keyword per [logging.h](include\onnxruntime\core\common\logging\logging.h)
|
||||
- Level: 1-5 ([CRITICAL through VERBOSE](https://learn.microsoft.com/en-us/windows/win32/api/evntprov/ns-evntprov-event_descriptor)) [mapping](onnxruntime\core\platform\windows\logging\etw_sink.cc) to [ONNX severity](include\onnxruntime\core\common\logging\severity.h) in an intuitive manner
|
||||
|
||||
Notes:
|
||||
- The ETW provider must be enabled prior to session creation, as that as when internal logging setup is complete
|
||||
- Other structured ETW logs are output via the other Microsoft.ML.ONNXRuntime ETW provider. Both used together are recommended
|
||||
|
||||
## Capturing ETW trace output
|
||||
|
||||
|
|
@ -25,9 +34,17 @@ Run the ETW sink unit tests
|
|||
Stop the ETW tracing
|
||||
`<path to repo>\onnxruntime\test\platform\windows\logging> wpr -stop TraceCaptureFile.etl EtwSinkTest`
|
||||
|
||||
## View the output
|
||||
## View the trace output
|
||||
|
||||
Open TraceCaptureFile.etl file Windows Performance Analyzer.
|
||||
### Setup
|
||||
- Install Windows Performance Analyzer (Preview) from the Windows Store - <https://www.microsoft.com/en-us/p/windows-performance-analyzer-preview/9n58qrw40dfw>
|
||||
- Or from the ADK <https://docs.microsoft.com/en-us/windows-hardware/get-started/adk-install>
|
||||
- You get to select components when installing, so can select just the performance toolkit.
|
||||
- Overview of the steps is at <https://msdn.microsoft.com/en-us/library/windows/desktop/dn904629(v=vs.85).aspx> if you want more detail.
|
||||
|
||||
### Viewing
|
||||
|
||||
Open TraceCaptureFile.etl file in Windows Performance Analyzer.
|
||||
|
||||
Expand the "System Activity" dropdown in the left pane, and double-click "Generic Events".
|
||||
That should open events in an Analysis window in the right pane. You should see an event
|
||||
|
|
|
|||
|
|
@ -47,8 +47,8 @@ TEST(LoggingTests, TestEtwSink) {
|
|||
/// </summary>
|
||||
TEST(LoggingTests, TestEtwSinkCtor) {
|
||||
CompositeSink* sinks = new CompositeSink();
|
||||
sinks->AddSink(std::unique_ptr<ISink>(new EtwSink()))
|
||||
.AddSink(std::unique_ptr<ISink>(new EtwSink()));
|
||||
sinks->AddSink(std::unique_ptr<ISink>(new EtwSink()), Severity::kWARNING)
|
||||
.AddSink(std::unique_ptr<ISink>(new EtwSink()), Severity::kWARNING);
|
||||
|
||||
LoggingManager manager{std::unique_ptr<ISink>{sinks},
|
||||
Severity::kWARNING,
|
||||
|
|
|
|||
4
ort.wprp
4
ort.wprp
|
|
@ -8,12 +8,12 @@
|
|||
<Profiles>
|
||||
<EventCollector Id="EventCollector_OrtTraceLoggingProvider"
|
||||
Name="OrtTraceLoggingProviderCollector">
|
||||
<BufferSize Value="65536" />
|
||||
<BufferSize Value="1024" />
|
||||
<Buffers Value="10" PercentageOfTotalMemory="true"/>
|
||||
</EventCollector>
|
||||
|
||||
<EventProvider Id="EventProvider_OrtTraceLoggingProvider"
|
||||
Name="3a26b1ff-7484-7484-7484-15261f42614d" />
|
||||
Name="3a26b1ff-7484-7484-7484-15261f42614d" Level="5" />
|
||||
<Profile Id="OrtTraceLoggingProvider.Verbose.File"
|
||||
Name="OrtTraceLoggingProvider" Description="OrtTraceLoggingProvider"
|
||||
LoggingMode="File" DetailLevel="Verbose">
|
||||
|
|
|
|||
Loading…
Reference in a new issue