Register WinML TraceLogging provider on Onnxruntime.dll (#2455)

* Register WinML TraceLogging provider on Onnxruntime.dll

* Add ifdef to make sure trace logging provider has telemetry option when LAYERING_DONE

* No need for ifdef for TraceLoggingOptionMicrosoftTelemetry

* PR feedback

* Move etw registration into lotus environment constructor and deresgister in lotus environment destructor

winml/lib/Api.Core/FeatureDescriptorFactory.cpp

@@ -13,7 +13,7 @@
 
 #include "winrt/windows.foundation.collections.h"
 #include "winrt/windows.graphics.imaging.h"
-
+#include "inc/WinMLAdapter.h"
 using namespace winrt::Windows::AI::MachineLearning;
 
 // BitmapPixelFormat constants
@@ -473,14 +473,12 @@ GetTensorType(
        has_unsupported_image_metadata);
 
   if (is_tensor_improperly_annotated_as_image) {
-#ifdef LAYERING_DONE
-    TraceLoggingWrite(winml_trace_logging_provider,
+    TraceLoggingWrite(_winmla::winml_trace_logging_provider,
                       "WinMLInputValidation",
                       TraceLoggingKeyword(WINML_PROVIDER_KEYWORD_DEFAULT),
                       TraceLoggingLevel(WINEVENT_LEVEL_WARNING),
                       TraceLoggingOpcode(EVENT_TRACE_TYPE_INFO),
                       TraceLoggingString(log_stream.str().c_str()));
-#endif
   }
 
   auto is_valid_image_tensor =

winml/lib/Api.Core/LotusEnvironment.cpp

@@ -3,7 +3,6 @@
 
 #include "pch.h"
 #include "inc/LotusEnvironment.h"
-#include <TraceLoggingProvider.h>
 #include "core/platform/windows/TraceLoggingConfig.h"
 #include <evntrace.h>
 
@@ -12,12 +11,11 @@ void Windows::AI::MachineLearning::CWinMLLogSink::SendImpl(
     const onnxruntime::logging::Timestamp& timestamp,
     const std::string& logger_id,
     const onnxruntime::logging::Capture& message) {
-#ifdef LAYERING_DONE
   // ORT Fatal and Error Messages are logged as Telemetry, rest are non-telemetry.
   switch (message.Severity()) {
     case (onnxruntime::logging::Severity::kFATAL):  //Telemetry
       TraceLoggingWrite(
-          winml_trace_logging_provider,
+          _winmla::winml_trace_logging_provider,
           "WinMLLogSink",
           TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance),
           TraceLoggingKeyword(WINML_PROVIDER_KEYWORD_DEFAULT),
@@ -31,7 +29,7 @@ void Windows::AI::MachineLearning::CWinMLLogSink::SendImpl(
       break;
     case (onnxruntime::logging::Severity::kERROR):  //Telemetry
       TraceLoggingWrite(
-          winml_trace_logging_provider,
+          _winmla::winml_trace_logging_provider,
           "WinMLLogSink",
           TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance),
           TraceLoggingKeyword(WINML_PROVIDER_KEYWORD_DEFAULT),
@@ -45,7 +43,7 @@ void Windows::AI::MachineLearning::CWinMLLogSink::SendImpl(
       break;
     case (onnxruntime::logging::Severity::kWARNING):
       TraceLoggingWrite(
-          winml_trace_logging_provider,
+          _winmla::winml_trace_logging_provider,
           "WinMLLogSink",
           TraceLoggingKeyword(WINML_PROVIDER_KEYWORD_DEFAULT),
           TraceLoggingLevel(WINEVENT_LEVEL_WARNING),
@@ -57,7 +55,7 @@ void Windows::AI::MachineLearning::CWinMLLogSink::SendImpl(
       break;
     case (onnxruntime::logging::Severity::kINFO):
       TraceLoggingWrite(
-          winml_trace_logging_provider,
+          _winmla::winml_trace_logging_provider,
           "WinMLLogSink",
           TraceLoggingKeyword(WINML_PROVIDER_KEYWORD_DEFAULT),
           TraceLoggingLevel(WINEVENT_LEVEL_INFO),
@@ -71,7 +69,7 @@ void Windows::AI::MachineLearning::CWinMLLogSink::SendImpl(
       __fallthrough;  //Default is Verbose too.
     default:
       TraceLoggingWrite(
-          winml_trace_logging_provider,
+          _winmla::winml_trace_logging_provider,
           "WinMLLogSink",
           TraceLoggingKeyword(WINML_PROVIDER_KEYWORD_DEFAULT),
           TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
@@ -81,17 +79,15 @@ void Windows::AI::MachineLearning::CWinMLLogSink::SendImpl(
           TraceLoggingString(message.Message().c_str()),
           TraceLoggingString(message.Location().ToString(onnxruntime::CodeLocation::kFilenameAndPath).c_str()));
   }
-#endif
   if (debug_output_) {
     OutputDebugStringA(std::string(message.Message() + "\r\n").c_str());
   }
 }
 
 void Windows::AI::MachineLearning::CWinMLLogSink::SendProfileEvent(onnxruntime::profiling::EventRecord& eventRecord) const {
-#ifdef LAYERING_DONE
   if (eventRecord.cat == onnxruntime::profiling::EventCategory::NODE_EVENT) {
     TraceLoggingWrite(
-        winml_trace_logging_provider,
+        _winmla::winml_trace_logging_provider,
         "OnnxRuntimeProfiling",
         TraceLoggingKeyword(WINML_PROVIDER_KEYWORD_LOTUS_PROFILING),
         TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
@@ -106,7 +102,7 @@ void Windows::AI::MachineLearning::CWinMLLogSink::SendProfileEvent(onnxruntime::
         TraceLoggingString(eventRecord.args["provider"].c_str(), "Execution Provider"));
   } else {
     TraceLoggingWrite(
-        winml_trace_logging_provider,
+        _winmla::winml_trace_logging_provider,
         "OnnxRuntimeProfiling",
         TraceLoggingKeyword(WINML_PROVIDER_KEYWORD_LOTUS_PROFILING),
         TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
@@ -118,5 +114,4 @@ void Windows::AI::MachineLearning::CWinMLLogSink::SendProfileEvent(onnxruntime::
         TraceLoggingInt32(eventRecord.pid, "Process ID"),
         TraceLoggingInt32(eventRecord.tid, "Thread ID"));
   }
-#endif
 }

winml/lib/Api.Core/WinMLAdapter.cpp

@@ -15,8 +15,7 @@
 #include "TensorFeatureDescriptor.h"
 #include "ImageFeatureDescriptor.h"
 #include "api.image/inc/D3DDeviceCache.h"
-
-#include "PheonixSingleton.h"
+#include "Common/inc/WinMLTelemetryHelper.h"
 
 #include "DmlOrtSessionBuilder.h"
 #include "CpuOrtSessionBuilder.h"
@@ -33,6 +32,12 @@ using namespace winrt::Windows::AI::MachineLearning;
 
 namespace Windows::AI::MachineLearning::Adapter {
 
+// Define winml trace logging provider with WinML GUID
+TRACELOGGING_DEFINE_PROVIDER(
+    winml_trace_logging_provider,
+    WINML_PROVIDER_DESC,
+    WINML_PROVIDER_GUID);
+
 // ORT intentionally requires callers derive from their session class to access
 // the protected Load method used below.
 class InferenceSessionProtectedLoadAccessor : public onnxruntime::InferenceSession {
@@ -93,11 +98,11 @@ class AbiSafeOrtValue : public Microsoft::WRL::RuntimeClass<
 
  public:
   AbiSafeOrtValue() : ort_value_weak_(nullptr) {}
-  AbiSafeOrtValue(OrtValue* weak_value_in) : ort_value_weak_(weak_value_in) { }
+  AbiSafeOrtValue(OrtValue* weak_value_in) : ort_value_weak_(weak_value_in) {}
 
   OrtValue* STDMETHODCALLTYPE get() override {
-    if (ort_value_weak_ != nullptr) 
-        return ort_value_weak_;
+    if (ort_value_weak_ != nullptr)
+      return ort_value_weak_;
     return &ort_value_;
   }
 
@@ -609,133 +614,133 @@ class WinMLAdapter : public Microsoft::WRL::RuntimeClass<
     }
   }
 
-HRESULT STDMETHODCALLTYPE GetCustomRegistry(IMLOperatorRegistry** registry) override {
-  auto impl = wil::MakeOrThrow<AbiCustomRegistryImpl>();
-  *registry = impl.Detach();
-  return S_OK;
-}
+  HRESULT STDMETHODCALLTYPE GetCustomRegistry(IMLOperatorRegistry** registry) override {
+    auto impl = wil::MakeOrThrow<AbiCustomRegistryImpl>();
+    *registry = impl.Detach();
+    return S_OK;
+  }
 
-void* STDMETHODCALLTYPE CreateGPUAllocationFromD3DResource(ID3D12Resource* pResource) override {
-  return Dml::CreateGPUAllocationFromD3DResource(pResource);
-}
+  void* STDMETHODCALLTYPE CreateGPUAllocationFromD3DResource(ID3D12Resource* pResource) override {
+    return Dml::CreateGPUAllocationFromD3DResource(pResource);
+  }
 
-void STDMETHODCALLTYPE FreeGPUAllocation(void* ptr) override {
-  Dml::FreeGPUAllocation(ptr);
-}
-HRESULT STDMETHODCALLTYPE CopyTensor(
-    onnxruntime::IExecutionProvider* provider,
-    ITensor* src,
-    ITensor* dst) override {
-  ORT_THROW_IF_ERROR(Dml::CopyTensor(provider, src->get(), *(dst->getMutable())));
-  return S_OK;
-}
+  void STDMETHODCALLTYPE FreeGPUAllocation(void* ptr) override {
+    Dml::FreeGPUAllocation(ptr);
+  }
+  HRESULT STDMETHODCALLTYPE CopyTensor(
+      onnxruntime::IExecutionProvider* provider,
+      ITensor* src,
+      ITensor* dst) override {
+    ORT_THROW_IF_ERROR(Dml::CopyTensor(provider, src->get(), *(dst->getMutable())));
+    return S_OK;
+  }
 
-HRESULT STDMETHODCALLTYPE CreateGPUMLValue(
-    void* execution_provider_allocated_resource,
-    onnxruntime::IExecutionProvider* provider,
-    std::vector<int64_t>* shape,
-    onnxruntime::MLDataType data_type,
-    IOrtValue** gpu_value) override {
-  THROW_HR_IF_MSG(WINML_ERR_INVALID_BINDING,
-                  "DmlExecutionProvider" != provider->Type(),
-                  "Cannot creat GPU tensor on CPU device");
+  HRESULT STDMETHODCALLTYPE CreateGPUMLValue(
+      void* execution_provider_allocated_resource,
+      onnxruntime::IExecutionProvider* provider,
+      std::vector<int64_t>* shape,
+      onnxruntime::MLDataType data_type,
+      IOrtValue** gpu_value) override {
+    THROW_HR_IF_MSG(WINML_ERR_INVALID_BINDING,
+                    "DmlExecutionProvider" != provider->Type(),
+                    "Cannot creat GPU tensor on CPU device");
 
-  onnxruntime::TensorShape tensor_shape(*shape);
+    onnxruntime::TensorShape tensor_shape(*shape);
 
-  auto tensor = new onnxruntime::Tensor(
-      data_type,
-      tensor_shape,
-      execution_provider_allocated_resource,
-      provider->GetAllocator(0, ::OrtMemType::OrtMemTypeDefault)->Info());
+    auto tensor = new onnxruntime::Tensor(
+        data_type,
+        tensor_shape,
+        execution_provider_allocated_resource,
+        provider->GetAllocator(0, ::OrtMemType::OrtMemTypeDefault)->Info());
 
-  auto ort_value = wil::MakeOrThrow<AbiSafeOrtValue>();
-  ort_value->get()->Init(tensor,
-                         onnxruntime::DataTypeImpl::GetType<onnxruntime::Tensor>(),
-                         onnxruntime::DataTypeImpl::GetType<onnxruntime::Tensor>()->GetDeleteFunc());
+    auto ort_value = wil::MakeOrThrow<AbiSafeOrtValue>();
+    ort_value->get()->Init(tensor,
+                           onnxruntime::DataTypeImpl::GetType<onnxruntime::Tensor>(),
+                           onnxruntime::DataTypeImpl::GetType<onnxruntime::Tensor>()->GetDeleteFunc());
 
-  *gpu_value = ort_value.Detach();
-  return S_OK;
-}
+    *gpu_value = ort_value.Detach();
+    return S_OK;
+  }
 
-HRESULT STDMETHODCALLTYPE CreateCPUMLValue(
-    std::vector<int64_t>* shape,
-    onnxruntime::MLDataType data_type,
-    onnxruntime::BufferNakedPtr buffer,
-    IOrtValue** cpu_value) override {
-  auto registrations = onnxruntime::DeviceAllocatorRegistry::Instance().AllRegistrations();
-  auto alloc = registrations[onnxruntime::CPU].factory(0);
+  HRESULT STDMETHODCALLTYPE CreateCPUMLValue(
+      std::vector<int64_t>* shape,
+      onnxruntime::MLDataType data_type,
+      onnxruntime::BufferNakedPtr buffer,
+      IOrtValue** cpu_value) override {
+    auto registrations = onnxruntime::DeviceAllocatorRegistry::Instance().AllRegistrations();
+    auto alloc = registrations[onnxruntime::CPU].factory(0);
 
-  onnxruntime::TensorShape tensor_shape(*shape);
+    onnxruntime::TensorShape tensor_shape(*shape);
 
-  // Unowned raw tensor pointer passed to engine
-  auto tensor = new onnxruntime::Tensor(
-      data_type,
-      tensor_shape,
-      buffer,
-      alloc->Info());
+    // Unowned raw tensor pointer passed to engine
+    auto tensor = new onnxruntime::Tensor(
+        data_type,
+        tensor_shape,
+        buffer,
+        alloc->Info());
 
-  auto ort_value = wil::MakeOrThrow<AbiSafeOrtValue>();
-  ort_value->get()->Init(tensor,
-                         onnxruntime::DataTypeImpl::GetType<onnxruntime::Tensor>(),
-                         onnxruntime::DataTypeImpl::GetType<onnxruntime::Tensor>()->GetDeleteFunc());
+    auto ort_value = wil::MakeOrThrow<AbiSafeOrtValue>();
+    ort_value->get()->Init(tensor,
+                           onnxruntime::DataTypeImpl::GetType<onnxruntime::Tensor>(),
+                           onnxruntime::DataTypeImpl::GetType<onnxruntime::Tensor>()->GetDeleteFunc());
 
-  *cpu_value = ort_value.Detach();
-  return S_OK;
-}
+    *cpu_value = ort_value.Detach();
+    return S_OK;
+  }
 
-HRESULT STDMETHODCALLTYPE CreateMLValue(
-    winml::TensorKind kind,
-    onnxruntime::MLDataType data_type,
-    const int64_t* shape,
-    uint32_t shape_count,
-    onnxruntime::IExecutionProvider* provider,
-    IOrtValue** ort_value) override {
-  onnxruntime::TensorShape tensor_shape(shape, shape_count);
-  auto tensor = new onnxruntime::Tensor(
-      GetType(kind),
-      tensor_shape,
-      provider->GetAllocator(0, ::OrtMemType::OrtMemTypeDefault));
-  auto ort_value_out = wil::MakeOrThrow<AbiSafeOrtValue>();
-  ort_value_out->get()->Init(tensor,
-                             data_type,
-                             data_type->GetDeleteFunc());
+  HRESULT STDMETHODCALLTYPE CreateMLValue(
+      winml::TensorKind kind,
+      onnxruntime::MLDataType data_type,
+      const int64_t* shape,
+      uint32_t shape_count,
+      onnxruntime::IExecutionProvider* provider,
+      IOrtValue** ort_value) override {
+    onnxruntime::TensorShape tensor_shape(shape, shape_count);
+    auto tensor = new onnxruntime::Tensor(
+        GetType(kind),
+        tensor_shape,
+        provider->GetAllocator(0, ::OrtMemType::OrtMemTypeDefault));
+    auto ort_value_out = wil::MakeOrThrow<AbiSafeOrtValue>();
+    ort_value_out->get()->Init(tensor,
+                               data_type,
+                               data_type->GetDeleteFunc());
 
-  *ort_value = ort_value_out.Detach();
-  ;
-  return S_OK;
-}
+    *ort_value = ort_value_out.Detach();
+    ;
+    return S_OK;
+  }
 
-static void Delete(void* p) {
-  // do nothing
-}
+  static void Delete(void* p) {
+    // do nothing
+  }
 
-HRESULT STDMETHODCALLTYPE CreateOrtValue(
-  void* data,
-  onnxruntime::MLDataType data_type,
-  IOrtValue** ort_value) override {
-  auto ort_value_out = wil::MakeOrThrow<AbiSafeOrtValue>();
-  // pass the data in as a weak ref, don't let it delete it
-  ort_value_out->get()->Init(
-      data,
-      data_type,
-      &Delete);
+  HRESULT STDMETHODCALLTYPE CreateOrtValue(
+      void* data,
+      onnxruntime::MLDataType data_type,
+      IOrtValue** ort_value) override {
+    auto ort_value_out = wil::MakeOrThrow<AbiSafeOrtValue>();
+    // pass the data in as a weak ref, don't let it delete it
+    ort_value_out->get()->Init(
+        data,
+        data_type,
+        &Delete);
 
-  *ort_value = ort_value_out.Detach();
-  return S_OK;
-}
+    *ort_value = ort_value_out.Detach();
+    return S_OK;
+  }
 
-// Override select shape inference functions which are incomplete in ONNX with versions that are complete,
-// and are also used in DML kernel registrations.  Doing this avoids kernel and shader creation being
-// deferred until first evaluation.  It also prevents a situation where inference functions in externally
-// registered schema are reachable only after upstream schema have been revised in a later OS release,
-// which would be a compatibility risk.
-HRESULT STDMETHODCALLTYPE OverrideSchemaInferenceFunctions() override {
-  static std::once_flag schema_override_once_flag;
-  std::call_once(schema_override_once_flag, []() {
-    SchemaInferenceOverrider::OverrideSchemaInferenceFunctions();
-  });
-  return S_OK;
-}
+  // Override select shape inference functions which are incomplete in ONNX with versions that are complete,
+  // and are also used in DML kernel registrations.  Doing this avoids kernel and shader creation being
+  // deferred until first evaluation.  It also prevents a situation where inference functions in externally
+  // registered schema are reachable only after upstream schema have been revised in a later OS release,
+  // which would be a compatibility risk.
+  HRESULT STDMETHODCALLTYPE OverrideSchemaInferenceFunctions() override {
+    static std::once_flag schema_override_once_flag;
+    std::call_once(schema_override_once_flag, []() {
+      SchemaInferenceOverrider::OverrideSchemaInferenceFunctions();
+    });
+    return S_OK;
+  }
 };  // namespace Windows::AI::MachineLearning::Adapter
 
 extern "C" HRESULT STDMETHODCALLTYPE OrtGetWinMLAdapter(IWinMLAdapter** adapter) {

winml/lib/Api.Core/inc/LotusEnvironment.h

@@ -6,6 +6,7 @@
 #include "WinMLProfiler.h"
 #include <winrt/Windows.ApplicationModel.h>
 #include <winrt/Windows.ApplicationModel.Core.h>
+#include "inc/WinMLAdapter.h"
 
 #pragma warning(push)
 #pragma warning(disable : 4505)
@@ -54,6 +55,11 @@ static void OnSuspending(winrt::Windows::Foundation::IInspectable const& sender,
 class LotusEnvironment {
  public:
   LotusEnvironment() {
+    const HRESULT etw_status = TraceLoggingRegister(winml_trace_logging_provider);
+    if (FAILED(etw_status)) {
+      throw std::runtime_error("WinML TraceLogging registration failed. Logging will be broken: " + std::to_string(etw_status));
+    }
+
     // TODO: Do we need to call this or just define the method?
     default_logging_manager_ = &DefaultLoggingManager();
 
@@ -72,6 +78,7 @@ class LotusEnvironment {
   }
 
   ~LotusEnvironment() {
+    TraceLoggingUnregister(winml_trace_logging_provider);
     if (suspend_token_) {
       winrt::Windows::ApplicationModel::Core::CoreApplication::Suspending(suspend_token_);
     }

winml/lib/Api.Core/inc/WinMLAdapter.h

@@ -6,6 +6,7 @@
 #include "core/session/onnxruntime_c_api.h"
 
 namespace Windows::AI::MachineLearning::Adapter {
+TRACELOGGING_DECLARE_PROVIDER(winml_trace_logging_provider);
 
 MIDL_INTERFACE("eaae30b5-7381-432d-9730-322136b02371") IModelInfo : IUnknown{
     // model metadata