diff --git a/onnxruntime/core/platform/telemetry.cc b/onnxruntime/core/platform/telemetry.cc index 7c587a1b5d..da3d21ae50 100644 --- a/onnxruntime/core/platform/telemetry.cc +++ b/onnxruntime/core/platform/telemetry.cc @@ -1,6 +1,7 @@ // Copyright (c) Microsoft Corporation. All rights reserved. // Licensed under the MIT License. +#include #include "core/platform/telemetry.h" #include "core/platform/env.h" @@ -27,7 +28,8 @@ void Telemetry::LogSessionCreation(uint32_t session_id, int64_t ir_version, cons const std::unordered_map& domain_to_version_map, const std::string& model_graph_name, const std::unordered_map& model_metadata, - const std::string& loadedFrom, const std::vector& execution_provider_ids) const { + const std::string& loadedFrom, const std::vector& execution_provider_ids, + bool use_fp16) const { ORT_UNUSED_PARAMETER(session_id); ORT_UNUSED_PARAMETER(ir_version); ORT_UNUSED_PARAMETER(model_producer_name); @@ -38,6 +40,7 @@ void Telemetry::LogSessionCreation(uint32_t session_id, int64_t ir_version, cons ORT_UNUSED_PARAMETER(model_metadata); ORT_UNUSED_PARAMETER(loadedFrom); ORT_UNUSED_PARAMETER(execution_provider_ids); + ORT_UNUSED_PARAMETER(use_fp16); } void Telemetry::LogRuntimeError(uint32_t session_id, const common::Status& status, const char* file, @@ -55,5 +58,9 @@ void Telemetry::LogRuntimePerf(uint32_t session_id, uint32_t total_runs_since_la ORT_UNUSED_PARAMETER(total_run_duration_since_last); } +void Telemetry::LogExecutionProviderEvent(LUID adapterLuid) const { + ORT_UNUSED_PARAMETER(adapterLuid); +} + } // namespace onnxruntime diff --git a/onnxruntime/core/platform/telemetry.h b/onnxruntime/core/platform/telemetry.h index a0fc42e045..f7ffd6ed7d 100644 --- a/onnxruntime/core/platform/telemetry.h +++ b/onnxruntime/core/platform/telemetry.h @@ -10,6 +10,8 @@ #include "core/common/status.h" #include "core/common/common.h" +typedef struct _LUID LUID; + namespace onnxruntime { /** @@ -41,13 +43,16 @@ class Telemetry { const std::unordered_map& domain_to_version_map, const std::string& model_graph_name, const std::unordered_map& model_metadata, - const std::string& loadedFrom, const std::vector& execution_provider_ids) const; + const std::string& loadedFrom, const std::vector& execution_provider_ids, + bool use_fp16) const; virtual void LogRuntimeError(uint32_t session_id, const common::Status& status, const char* file, const char* function, uint32_t line) const; virtual void LogRuntimePerf(uint32_t session_id, uint32_t total_runs_since_last, int64_t total_run_duration_since_last) const; + virtual void LogExecutionProviderEvent(LUID adapterLuid) const; + private: ORT_DISALLOW_COPY_ASSIGNMENT_AND_MOVE(Telemetry); }; diff --git a/onnxruntime/core/platform/windows/telemetry.cc b/onnxruntime/core/platform/windows/telemetry.cc index d83868ec34..b347202e8a 100644 --- a/onnxruntime/core/platform/windows/telemetry.cc +++ b/onnxruntime/core/platform/windows/telemetry.cc @@ -92,7 +92,8 @@ void WindowsTelemetry::LogSessionCreation(uint32_t session_id, int64_t ir_versio const std::unordered_map& domain_to_version_map, const std::string& model_graph_name, const std::unordered_map& model_metadata, - const std::string& loadedFrom, const std::vector& execution_provider_ids) const { + const std::string& loaded_from, const std::vector& execution_provider_ids, + bool use_fp16) const { if (global_register_count_ == 0 || enabled_ == false) return; @@ -147,10 +148,11 @@ void WindowsTelemetry::LogSessionCreation(uint32_t session_id, int64_t ir_versio 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(loadedFrom.c_str(), "loadedFrom"), + TraceLoggingString(loaded_from.c_str(), "loadedFrom"), TraceLoggingString(execution_provider_string.c_str(), "executionProviderIds")); } @@ -161,6 +163,7 @@ void WindowsTelemetry::LogRuntimeError(uint32_t session_id, const common::Status TraceLoggingWrite(telemetry_provider_handle, "RuntimeError", + TraceLoggingBool(true, "UTCReplace_AppSessionGuid"), TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance), TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES), // Telemetry info @@ -189,4 +192,17 @@ void WindowsTelemetry::LogRuntimePerf(uint32_t session_id, uint32_t total_runs_s TraceLoggingInt64(total_run_duration_since_last, "totalRunDuration")); } +void WindowsTelemetry::LogExecutionProviderEvent(LUID adapterLuid) const { + if (global_register_count_ == 0 || enabled_ == false) + return; + + TraceLoggingWrite(telemetry_provider_handle, + "ExecutionProviderEvent", + TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance), + TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES), + // Telemetry info + TraceLoggingUInt32(adapterLuid.LowPart, "adapterLuidLowPart"), + TraceLoggingUInt32(adapterLuid.HighPart, "adapterLuidHighPart")); +} + } // namespace onnxruntime diff --git a/onnxruntime/core/platform/windows/telemetry.h b/onnxruntime/core/platform/windows/telemetry.h index dd5da6205b..cf786a4aa3 100644 --- a/onnxruntime/core/platform/windows/telemetry.h +++ b/onnxruntime/core/platform/windows/telemetry.h @@ -13,9 +13,7 @@ namespace onnxruntime { * derives and implments a Telemetry provider on Windows */ class WindowsTelemetry : public Telemetry { - public: - // these are allowed to be created, WindowsEnv will create one WindowsTelemetry(); ~WindowsTelemetry(); @@ -30,13 +28,16 @@ class WindowsTelemetry : public Telemetry { const std::unordered_map& domain_to_version_map, const std::string& model_graph_name, const std::unordered_map& model_metadata, - const std::string& loadedFrom, const std::vector& execution_provider_ids) const override; - + const std::string& loadedFrom, const std::vector& execution_provider_ids, + bool use_fp16) const override; + void LogRuntimeError(uint32_t session_id, const common::Status& status, const char* file, const char* function, uint32_t line) const override; void LogRuntimePerf(uint32_t session_id, uint32_t total_runs_since_last, int64_t total_run_duration_since_last) const override; + void LogExecutionProviderEvent(LUID adapterLuid) const override; + private: static OrtMutex mutex_; static uint32_t global_register_count_; diff --git a/onnxruntime/core/providers/dml/dml_provider_factory.cc b/onnxruntime/core/providers/dml/dml_provider_factory.cc index d936cd0262..5194a4b18f 100644 --- a/onnxruntime/core/providers/dml/dml_provider_factory.cc +++ b/onnxruntime/core/providers/dml/dml_provider_factory.cc @@ -13,6 +13,7 @@ using Microsoft::WRL::ComPtr; #include "core/providers/dml/dml_provider_factory.h" #include "core/session/abi_session_options_impl.h" #include "DmlExecutionProvider/inc/DmlExecutionProvider.h" +#include "core/platform/env.h" namespace onnxruntime { @@ -46,6 +47,11 @@ std::shared_ptr CreateExecutionProviderFactory_DML(ID THROW_HR(E_INVALIDARG); } + ComPtr d3d12_device; + THROW_IF_FAILED(dml_device->GetParentDevice(IID_PPV_ARGS(&d3d12_device))); + const Env& env = Env::Default(); + env.GetTelemetryProvider().LogExecutionProviderEvent(d3d12_device->GetAdapterLuid()); + return std::make_shared(dml_device, cmd_queue); } @@ -62,7 +68,7 @@ std::shared_ptr CreateExecutionProviderFactory_DML(in D3D12_COMMAND_QUEUE_DESC cmd_queue_desc = {}; cmd_queue_desc.Type = D3D12_COMMAND_LIST_TYPE_COMPUTE; cmd_queue_desc.Flags = D3D12_COMMAND_QUEUE_FLAG_NONE; - + ComPtr cmd_queue; THROW_IF_FAILED(d3d12_device->CreateCommandQueue(&cmd_queue_desc, IID_PPV_ARGS(&cmd_queue))); @@ -85,6 +91,7 @@ std::shared_ptr CreateExecutionProviderFactory_DML(in DML_FEATURE_LEVEL_2_0, IID_PPV_ARGS(&dml_device))); + return CreateExecutionProviderFactory_DML(dml_device.Get(), cmd_queue.Get()); } diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index c9aad03a7d..40ba0b43a1 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -546,6 +546,43 @@ common::Status InferenceSession::InitializeSubgraphSessions(Graph& graph, Sessio return Status::OK(); } +static bool ModelUseFP16Helper(const onnx::TypeProto& type_proto) { + switch (type_proto.value_case()) { + case ::onnx::TypeProto::ValueCase::kTensorType: { + if (type_proto.has_tensor_type()) { + auto& tensor_type = type_proto.tensor_type(); + if (tensor_type.elem_type() == ONNX_NAMESPACE::TensorProto_DataType::TensorProto_DataType_FLOAT16) { + return true; + } + } + } break; + case ::onnx::TypeProto::ValueCase::kSequenceType: { + if (type_proto.has_sequence_type()) { + auto& sequence_type = type_proto.sequence_type(); + return ModelUseFP16Helper(sequence_type.elem_type()); + } + } break; + case ::onnx::TypeProto::ValueCase::kMapType: { + if (type_proto.has_map_type()) { + auto& map_type = type_proto.map_type(); + return ModelUseFP16Helper(map_type.value_type()); + } + } break; + } + return false; +} + +static bool ModelUseFP16(const onnx::ModelProto& model_proto) { + auto& graph = model_proto.graph(); + auto& inputs = graph.input(); + for (auto& input : inputs) { + if (input.has_name() && input.has_type() && ModelUseFP16Helper(input.type())) { + return true; + } + } + return false; +} + common::Status InferenceSession::Initialize() { Status status = Status::OK(); TimePoint tp; @@ -633,12 +670,13 @@ common::Status InferenceSession::Initialize() { // handle any subgraphs ORT_RETURN_IF_ERROR_SESSIONID_(InitializeSubgraphSessions(graph, session_state_)); is_inited_ = true; - + // and log telemetry const Env& env = Env::Default(); + bool model_use_fp16 = ModelUseFP16(model_->ToProto()); env.GetTelemetryProvider().LogSessionCreation(session_id_, model_->IrVersion(), model_->ProducerName(), model_->ProducerVersion(), model_->Domain(), model_->MainGraph().DomainToVersionMap(), model_->MainGraph().Name(), - model_->MetaData(), event_name_, execution_providers_.GetIds()); + model_->MetaData(), event_name_, execution_providers_.GetIds(), model_use_fp16); LOGS(*session_logger_, INFO) << "Session successfully initialized."; } catch (const NotImplementedException& ex) { @@ -1151,7 +1189,6 @@ void InferenceSession::AddPredefinedTransformers(GraphTransformerManager& transf add_transformers(level); } } - } common::Status InferenceSession::WaitForNotification(Notification* p_executor_done, int64_t timeout_in_ms) { diff --git a/winml/adapter/DmlOrtSessionBuilder.cpp b/winml/adapter/DmlOrtSessionBuilder.cpp index 7081eac8bf..436e141afc 100644 --- a/winml/adapter/DmlOrtSessionBuilder.cpp +++ b/winml/adapter/DmlOrtSessionBuilder.cpp @@ -124,6 +124,8 @@ HRESULT DmlOrtSessionBuilder::CreateSession( std::unique_ptr gpu_provider = Dml::CreateExecutionProvider(dmlDevice.Get(), p_queue); auto session = std::make_unique(options->value); + const onnxruntime::Env& env = onnxruntime::Env::Default(); + env.GetTelemetryProvider().LogExecutionProviderEvent(p_d3d_device->GetAdapterLuid()); // Cache the provider's raw pointer *pp_provider = gpu_provider.get(); diff --git a/winml/adapter/LotusEnvironment.h b/winml/adapter/LotusEnvironment.h index b2d9a0ac0e..37bb8ad7ed 100644 --- a/winml/adapter/LotusEnvironment.h +++ b/winml/adapter/LotusEnvironment.h @@ -3,7 +3,6 @@ #pragma once #include "core/common/logging/isink.h" -#include "WinMLProfiler.h" #include #include #include "WinMLAdapter.h" diff --git a/winml/dll/module.cpp b/winml/dll/module.cpp index b00483d2f5..e4910209ad 100644 --- a/winml/dll/module.cpp +++ b/winml/dll/module.cpp @@ -4,7 +4,6 @@ #include "pch.h" #include #include -#include "WinMLProfiler.h" #include "LearningModelDevice.h" @@ -31,18 +30,9 @@ extern "C" BOOL WINAPI DllMain(_In_ HINSTANCE hInstance, DWORD dwReason, _In_ vo // Register the TraceLogging provider feeding telemetry. It's OK if this fails; // trace logging calls just become no-ops. telemetry_helper.Register(); - - // Log Dll load - telemetry_helper.LogDllAttachEvent(); - // Enable Profiling if the device is sampled at measure level - if (telemetry_helper.IsMeasureSampled()) { - profiler.Enable(ProfilerType::CPU); - profiler.Reset(ProfilerType::CPU); - } wil::SetResultTelemetryFallback(&OnErrorReported); break; case DLL_PROCESS_DETACH: - telemetry_helper.LogRuntimePerf(profiler, true); // Unregister Trace Logging Provider feeding telemetry telemetry_helper.UnRegister(); diff --git a/winml/lib/Api/LearningModel.cpp b/winml/lib/Api/LearningModel.cpp index 3a4e210cef..51c8a02e04 100644 --- a/winml/lib/Api/LearningModel.cpp +++ b/winml/lib/Api/LearningModel.cpp @@ -6,7 +6,6 @@ #include "LearningModel.h" #include "TelemetryEvent.h" - #include "MapFeatureDescriptor.h" #include "SequenceFeatureDescriptor.h" #include "TensorFeatureDescriptor.h" @@ -22,25 +21,20 @@ WINML_CATCH_ALL LearningModel::LearningModel( const std::string& path, const winml::ILearningModelOperatorProvider operator_provider) try : operator_provider_(operator_provider) { - _winmlt::PerformanceTelemetryEvent kLoadModel_event( - WinMLRuntimePerf::kLoadModel); - + _winmlt::TelemetryEvent loadModel_event(_winmlt::EventCategory::kModelLoad); WINML_THROW_IF_FAILED(OrtGetWinMLAdapter(adapter_.put())); WINML_THROW_IF_FAILED(adapter_->OverrideSchemaInferenceFunctions()); WINML_THROW_IF_FAILED(adapter_->CreateModelProto(path.c_str(), model_proto_.put())); Initialize(); - LogCreationEvent(true); } WINML_CATCH_ALL LearningModel::LearningModel( const wss::IRandomAccessStreamReference stream, const winml::ILearningModelOperatorProvider operator_provider) try : operator_provider_(operator_provider) { - _winmlt::PerformanceTelemetryEvent kLoadModel_event( - WinMLRuntimePerf::kLoadModel); - + _winmlt::TelemetryEvent loadModel_event(_winmlt::EventCategory::kModelLoad); WINML_THROW_IF_FAILED(OrtGetWinMLAdapter(adapter_.put())); WINML_THROW_IF_FAILED(adapter_->OverrideSchemaInferenceFunctions()); WINML_THROW_IF_FAILED(adapter_->CreateModelProto( @@ -49,7 +43,6 @@ LearningModel::LearningModel( Initialize(); - LogCreationEvent(true); } WINML_CATCH_ALL @@ -57,56 +50,6 @@ void LearningModel::Initialize() { WINML_THROW_IF_FAILED(adapter_->CreateModelInfo(model_proto_.get(), model_info_.put())); } -void LearningModel::LogCreationEvent(bool /*fromStream*/) { - auto input_descriptors = InputFeatures(); - bool use_fp16 = false; - for (auto descriptor : input_descriptors) { - ModelUseFP16(descriptor, use_fp16); - if (use_fp16) { - break; - } - } -#ifdef LAYERING_DONE - telemetry_helper.LogModelCreation( - fromStream, - model_info_->author(), - model_info_->name(), - model_info_->domain(), - model_info_->description(), - model_info_->version(), - use_fp16, - model_info_->model_metadata()); -#endif -} - -void LearningModel::ModelUseFP16( - winml::ILearningModelFeatureDescriptor descriptor, - bool& use_fp16) { - auto kind = descriptor.Kind(); - switch (kind) { - case LearningModelFeatureKind::Image: - //images do not support float16 yet - break; - case LearningModelFeatureKind::Map: { - auto map_descriptor = descriptor.as(); - ModelUseFP16(map_descriptor->ValueDescriptor(), use_fp16); - } break; - case LearningModelFeatureKind::Sequence: { - auto sequence_descriptor = descriptor.as(); - ModelUseFP16(sequence_descriptor->ElementDescriptor(), use_fp16); - } break; - case LearningModelFeatureKind::Tensor: { - auto tensor_descriptor = descriptor.as(); - if (tensor_descriptor->TensorKind() == TensorKind::Float16) { - use_fp16 = true; - return; - } - } break; - default: - break; - } -} - hstring LearningModel::Author() try { return WinML::Strings::HStringFromUTF8(model_info_->author()); diff --git a/winml/lib/Api/LearningModelBinding.cpp b/winml/lib/Api/LearningModelBinding.cpp index d2e7fb0156..540f3dee1b 100644 --- a/winml/lib/Api/LearningModelBinding.cpp +++ b/winml/lib/Api/LearningModelBinding.cpp @@ -487,7 +487,6 @@ STDMETHODIMP LearningModelBinding::Bind( IUnknown* value) { try { _winmlt::TelemetryEvent binding_event(_winmlt::EventCategory::kBinding); - BindingType bindingType; std::string bindingName; OrtValue* binding_value_ptr = nullptr; diff --git a/winml/lib/Api/LearningModelDevice.cpp b/winml/lib/Api/LearningModelDevice.cpp index 90d33e40ba..ab1de4b8dd 100644 --- a/winml/lib/Api/LearningModelDevice.cpp +++ b/winml/lib/Api/LearningModelDevice.cpp @@ -8,7 +8,6 @@ #include #include "D3DDeviceCache.h" -#include "TelemetryEvent.h" #include "ConverterResourceStore.h" namespace winrt::Windows::AI::MachineLearning::implementation { @@ -28,9 +27,6 @@ LearningModelDevice::LearningModelDevice(Windows::AI::MachineLearning::LearningM m_isCpuDevice = m_deviceKind == LearningModelDeviceKind::Cpu || m_deviceKind == LearningModelDeviceKind::Default; if (m_isCpuDevice) { assert(m_deviceCache->GetD3D12Device() == nullptr); - } else if (telemetry_helper.IsMeasureSampled()) { - profiler.Enable(ProfilerType::GPU); - profiler.Reset(ProfilerType::GPU); } } WINML_CATCH_ALL diff --git a/winml/lib/Api/LearningModelSession.cpp b/winml/lib/Api/LearningModelSession.cpp index 41755e95c6..c4f5862f43 100644 --- a/winml/lib/Api/LearningModelSession.cpp +++ b/winml/lib/Api/LearningModelSession.cpp @@ -92,7 +92,6 @@ void LearningModelSession::Initialize() { // Begin recording session creation telemetry _winmlt::TelemetryEvent session_creation_event( _winmlt::EventCategory::kSessionCreation); - // Get the optimized model proto from the learning model com_ptr model_proto; model_proto.attach(GetOptimizedModel()); @@ -142,11 +141,6 @@ void LearningModelSession::Initialize() { // Cache the constructed session inference_session_ = session; - - telemetry_helper.LogSessionCreation( - WinML::Strings::UTF8FromHString(model_.Name()), - device_impl->IsCpuDevice(), - device_impl->GetDeviceLuid()); } wfc::IPropertySet @@ -312,8 +306,7 @@ wf::IAsyncOperation LearningModelSession::EvaluateAsync( winml::LearningModelBinding binding, hstring const correlation_id) { - _winmlt::PerformanceTelemetryEvent kEvaluateModel_event(WinMLRuntimePerf::kEvaluateModel); - + _winmlt::TelemetryEvent kEvaluateModel_event(_winmlt::EventCategory::kEvaluation); auto device = device_.as(); // Get the ORT binding collection @@ -361,7 +354,7 @@ LearningModelSession::Evaluate( winml::LearningModelBinding binding, hstring const& correlation_id) try { ToggleProfiler(); - _winmlt::PerformanceTelemetryEvent kEvaluateModel_event(WinMLRuntimePerf::kEvaluateModel); + _winmlt::TelemetryEvent kEvaluateModel_event(_winmlt::EventCategory::kEvaluation); ApplyEvaluationProperties(); diff --git a/winml/lib/Common/inc/TimerHelper.h b/winml/lib/Common/inc/TimerHelper.h deleted file mode 100644 index 33c690ec57..0000000000 --- a/winml/lib/Common/inc/TimerHelper.h +++ /dev/null @@ -1,586 +0,0 @@ -// Copyright (c) Microsoft Corporation. -// Licensed under the MIT License. - -#pragma once - -#include -#include -#ifndef DISABLE_GPU_COUNTERS -#include -#include -#endif -#include -#include -#include -#include "core/common/common.h" - -#define TIMER_SLOT_SIZE (128) -#define CONVERT_100NS_TO_SECOND(x) ((x)*0.0000001) -#define BYTE_TO_MB(x) ((x) / (1024.0 * 1024.0)) - -// A stopwatch to measure the time passed (in seconds) between current Stop call and the closest Start call that has been called before. -class Timer { - public: - void Start() { - LARGE_INTEGER t; - QueryPerformanceCounter(&t); - start_time_ = static_cast(t.QuadPart); - } - - double Stop() { - LARGE_INTEGER stop_time; - QueryPerformanceCounter(&stop_time); - double t = static_cast(stop_time.QuadPart) - start_time_; - LARGE_INTEGER tps; - QueryPerformanceFrequency(&tps); - return t / static_cast(tps.QuadPart); - } - - private: - double start_time_; -}; - -typedef enum CounterType { - TIMER = 0, - CPU_USAGE, - PAGE_FAULT_COUNT, - PAGE_FILE_USAGE, - PEAK_PAGE_FILE_USAGE, - WORKING_SET_USAGE, - PEAK_WORKING_SET_USAGE, - // GPU specific counter starts here - GPU_USAGE, - GPU_DEDICATED_MEM_USAGE, - GPU_SHARED_MEM_USAGE, - TYPE_COUNT -} CounterType; - -typedef enum ProfilerType { - CPU, - GPU, - PROFILER_TYPE_COUNT -} ProfilerType; - -class IPerfCounter { - public: - virtual void Reset() = 0; - virtual void Stop() = 0; - virtual void Start() = 0; - virtual void GetValues(double (&values)[CounterType::TYPE_COUNT], double time) = 0; -}; - -class CpuPerfCounter : public IPerfCounter { - public: - CpuPerfCounter() {} - - ~CpuPerfCounter() {} - - void Reset() override { - SYSTEM_INFO sysInfo = {0}; - GetSystemInfo(&sysInfo); - - m_startKernelTime = {0}; - m_startUserTime = {0}; - m_numProcessors = sysInfo.dwNumberOfProcessors; - m_procHandle = GetCurrentProcess(); - ; - m_pid = GetCurrentProcessId(); - ; - m_previousStartCallFailed = true; - m_processTime = 0; - m_startPageFaultCount = 0; - m_startPagefileUsage = 0; - m_startPeakPagefileUsage = 0; - m_startWorkingSetSize = 0; - m_startPeakWorkingSetSize = 0; - m_deltaPageFaultCount = 0; - m_deltaPagefileUsage = 0; - m_deltaPeakPagefileUsage = 0; - m_deltaWorkingSetSize = 0; - m_deltaPeakWorkingSetSize = 0; - } - - void Start() override { - FILETIME ftIgnore, ftKernel, ftUser; - - if (!GetProcessTimes(m_procHandle, &ftIgnore, &ftIgnore, &ftKernel, &ftUser) || - !GetProcessMemoryCounters(m_pid, m_startPageFaultCount, m_startPagefileUsage, m_startPeakPagefileUsage, m_startWorkingSetSize, m_startPeakWorkingSetSize)) { - m_previousStartCallFailed = true; - } else { - memcpy(&m_startKernelTime, &ftKernel, sizeof(FILETIME)); - memcpy(&m_startUserTime, &ftUser, sizeof(FILETIME)); - m_previousStartCallFailed = false; - } - } - - void Stop() override { - FILETIME ftIgnore, ftKernel, ftUser; - ULARGE_INTEGER stopKernelTime, stopUserTime; - ULONG stopPageFaultCount = 0; - SIZE_T stopPagefileUsage = 0; - SIZE_T stopPeakPagefileUsage = 0; - SIZE_T stopWorkingSetSize = 0; - SIZE_T stopPeakWorkingSetSize = 0; - - if (m_previousStartCallFailed || - m_numProcessors == 0 || - !GetProcessTimes(m_procHandle, &ftIgnore, &ftIgnore, &ftKernel, &ftUser) || - !GetProcessMemoryCounters(m_pid, stopPageFaultCount, stopPagefileUsage, stopPeakPagefileUsage, stopWorkingSetSize, stopPeakWorkingSetSize)) { - return; - } - - memcpy(&stopKernelTime, &ftKernel, sizeof(FILETIME)); - memcpy(&stopUserTime, &ftUser, sizeof(FILETIME)); - m_processTime = CONVERT_100NS_TO_SECOND((stopKernelTime.QuadPart - m_startKernelTime.QuadPart) + (stopUserTime.QuadPart - m_startUserTime.QuadPart)) / m_numProcessors; - - m_deltaPageFaultCount = stopPageFaultCount - m_startPageFaultCount; - m_deltaPagefileUsage = (double)BYTE_TO_MB((double)stopPagefileUsage - (double)m_startPagefileUsage); - m_deltaPeakPagefileUsage = (double)BYTE_TO_MB((double)stopPeakPagefileUsage - (double)m_startPeakPagefileUsage); - m_deltaWorkingSetSize = (double)BYTE_TO_MB((double)stopWorkingSetSize - (double)m_startWorkingSetSize); - m_deltaPeakWorkingSetSize = (double)BYTE_TO_MB((double)stopPeakWorkingSetSize - (double)m_startPeakWorkingSetSize); - } - - void GetValues(double (&values)[CounterType::TYPE_COUNT], double time) override { - values[CounterType::CPU_USAGE] = 100.0 * GetProcessTime() / time; - values[CounterType::PAGE_FAULT_COUNT] = GetDeltaPageFaultCount(); - values[CounterType::PAGE_FILE_USAGE] = GetDeltaPageFileUsage(); - values[CounterType::PEAK_PAGE_FILE_USAGE] = GetDeltaPeakPageFileUsage(); - values[CounterType::WORKING_SET_USAGE] = GetDeltaWorkingSetUsage(); - values[CounterType::PEAK_WORKING_SET_USAGE] = GetDeltaPeakWorkingSetUsage(); - } - - double GetProcessTime() { return m_processTime; } - ULONG GetDeltaPageFaultCount() { return m_deltaPageFaultCount; } - double GetDeltaPageFileUsage() { return m_deltaPagefileUsage; } - double GetDeltaPeakPageFileUsage() { return m_deltaPeakPagefileUsage; } - double GetDeltaWorkingSetUsage() { return m_deltaWorkingSetSize; } - double GetDeltaPeakWorkingSetUsage() { return m_deltaPeakWorkingSetSize; } - - private: - bool GetProcessMemoryCounters(DWORD pid, ULONG& pageFaultCount, SIZE_T& pageFileUsage, SIZE_T& peakPageFileUsage, SIZE_T& workingSetSize, SIZE_T& peakWorkingSetSize) { - HANDLE hProcess = NULL; - - hProcess = OpenProcess(PROCESS_QUERY_INFORMATION | PROCESS_VM_READ, FALSE, pid); - if (NULL == hProcess) - return false; - - PROCESS_MEMORY_COUNTERS pmc = {0}; - - bool result = GetProcessMemoryInfo(hProcess, &pmc, sizeof(pmc)); - if (result) { - pageFaultCount = pmc.PageFaultCount; - pageFileUsage = pmc.PagefileUsage; - peakPageFileUsage = pmc.PeakPagefileUsage; - workingSetSize = pmc.WorkingSetSize; - peakWorkingSetSize = pmc.PeakWorkingSetSize; - } - - CloseHandle(hProcess); - - return result; - } - - ULARGE_INTEGER m_startKernelTime = {}; - ULARGE_INTEGER m_startUserTime = {}; - UINT m_numProcessors = 0; - HANDLE m_procHandle; - DWORD m_pid = 0; - bool m_previousStartCallFailed; - double m_processTime = 0; // in second - ULONG m_startPageFaultCount = 0; - SIZE_T m_startPagefileUsage = 0; // in byte - SIZE_T m_startPeakPagefileUsage = 0; // in byte - SIZE_T m_startWorkingSetSize = 0; // in byte - SIZE_T m_startPeakWorkingSetSize = 0; // in byte - ULONG m_deltaPageFaultCount = 0; - double m_deltaPagefileUsage = 0; // in MByte - double m_deltaPeakPagefileUsage = 0; // in MByte - double m_deltaWorkingSetSize = 0; // in MByte - double m_deltaPeakWorkingSetSize = 0; // in MByte -}; -#ifndef DISABLE_GPU_COUNTERS - -class GpuPerfCounter : public IPerfCounter { - public: - GpuPerfCounter() : m_hPDH(NULL), - m_pfnPdhOpenQuery(NULL), - m_pfnPdhAddCounter(NULL), - m_pfnPdhCollectQueryData(NULL), - m_pfnPdhGetFormattedCounterArray(NULL), - m_pfnPdhGetFormattedCounterValue(NULL), - m_pfnPdhCloseQuery(NULL), - m_query(NULL) { - //#ifdef DISABLE_LOADLIBRARY - m_hPDH = LoadLibraryExW(L"pdh.dll", NULL, 0); - //#endif - if (m_hPDH != NULL) { - m_pfnPdhOpenQuery = (PFNPdhOpenQuery)GetProcAddress(m_hPDH, "PdhOpenQueryW"); - m_pfnPdhAddCounter = (PFNPdhAddCounter)GetProcAddress(m_hPDH, "PdhAddCounterW"); - m_pfnPdhCollectQueryData = (PFNPdhCollectQueryData)GetProcAddress(m_hPDH, "PdhCollectQueryData"); - m_pfnPdhGetFormattedCounterArray = (PFNPdhGetFormattedCounterArray)GetProcAddress(m_hPDH, "PdhGetFormattedCounterArrayW"); - m_pfnPdhGetFormattedCounterValue = (PFNPdhGetFormattedCounterValue)GetProcAddress(m_hPDH, "PdhGetFormattedCounterValue"); - m_pfnPdhCloseQuery = (PFNPdhCloseQuery)GetProcAddress(m_hPDH, "PdhCloseQuery"); - } - } - ~GpuPerfCounter() { - if (m_query) { - CloseQuery(m_query); - m_query = NULL; - } - - if (m_hPDH) { - FreeLibrary(m_hPDH); - m_hPDH = NULL; - } - } - - // This function consumes a lot of memory - // Avoid calling this function unless it's necessary - void Reset() override { - m_gpuUsage = 0; - m_deltaGpuDedicatedMemory = 0; - m_deltaGpuSharedMemory = 0; - - // Setup PDH performance query - std::wstring pidStr = std::to_wstring(GetCurrentProcessId()); - std::wstring gpuUsageQueryStr = L"\\GPU Engine(pid_*_*)\\Utilization Percentage"; - std::wstring gpuDedicatedMemQueryStr = L"\\GPU Process Memory(pid_*_*)\\Dedicated Usage"; - std::wstring gpuSharedMemQueryStr = L"\\GPU Process Memory(pid_*_*)\\Shared Usage"; - gpuUsageQueryStr.replace(gpuUsageQueryStr.find('*'), 1, pidStr); - gpuDedicatedMemQueryStr.replace(gpuDedicatedMemQueryStr.find('*'), 1, pidStr); - gpuSharedMemQueryStr.replace(gpuSharedMemQueryStr.find('*'), 1, pidStr); - - // Open query - if (m_query) CloseQuery(m_query); - OpenQuery(NULL, NULL, &m_query); - AddCounter(m_query, gpuUsageQueryStr.c_str(), NULL, &m_gpuUsageCounter); - AddCounter(m_query, gpuDedicatedMemQueryStr.c_str(), NULL, &m_gpuDedicatedMemUsageCounter); - AddCounter(m_query, gpuSharedMemQueryStr.c_str(), NULL, &m_gpuSharedMemUsageCounter); - } - - void Start() override { - PDH_FMT_COUNTERVALUE gpuDedicatedMemUsageCounterValue = {}; - PDH_FMT_COUNTERVALUE gpuSharedMemUsageCounterValue = {}; - PDH_STATUS status = S_OK; - - // Usage rate counter require two queries. Put first one at Start() and second on at Stop() - CollectQueryData(m_query); - - // Gpu dedicated ememory - status = GetFormattedCounterValue(m_gpuDedicatedMemUsageCounter, PDH_FMT_LARGE, NULL, &gpuDedicatedMemUsageCounterValue); - m_startGpuDedicatedMemory = (ERROR_SUCCESS == status) ? (double)BYTE_TO_MB(gpuDedicatedMemUsageCounterValue.largeValue) : m_startGpuDedicatedMemory; - - // Gpu shared ememory - status = GetFormattedCounterValue(m_gpuSharedMemUsageCounter, PDH_FMT_LARGE, NULL, &gpuSharedMemUsageCounterValue); - m_startGpuSharedMemory = (ERROR_SUCCESS == status) ? (double)BYTE_TO_MB(gpuSharedMemUsageCounterValue.largeValue) : m_startGpuSharedMemory; - } - - void Stop() override { - PPDH_FMT_COUNTERVALUE_ITEM_W gpuUsageCounterValue = nullptr; - PDH_FMT_COUNTERVALUE gpuDedicatedMemUsageCounterValue = {}; - PDH_FMT_COUNTERVALUE gpuSharedMemUsageCounterValue = {}; - DWORD bufferSize = 0; - DWORD itemCount = 0; - PDH_STATUS status = S_OK; - - // Query the gpu usage. - // For different IHVs, compute shader usage could be counted as either 3D or compute engine usage. - // Here we simply pick the max usage from all types of engines to see if bottleneck is from GPU. - // The same concept has been used in task manager to display GPU usage. - status = CollectQueryData(m_query); - if (S_OK != status && PDH_NO_DATA != status) - return; - - status = GetFormattedCounterArray(m_gpuUsageCounter, PDH_FMT_DOUBLE, &bufferSize, &itemCount, gpuUsageCounterValue); - if (PDH_MORE_DATA != status) - return; - - gpuUsageCounterValue = (PPDH_FMT_COUNTERVALUE_ITEM_W)malloc(bufferSize); - if (gpuUsageCounterValue != nullptr) { - status = GetFormattedCounterArray(m_gpuUsageCounter, PDH_FMT_DOUBLE, &bufferSize, &itemCount, gpuUsageCounterValue); - if (ERROR_SUCCESS == status) { - double maxValue = 0; - for (size_t i = 0; i < itemCount; ++i) { - maxValue = (gpuUsageCounterValue[i].FmtValue.doubleValue > maxValue) ? gpuUsageCounterValue[i].FmtValue.doubleValue : maxValue; - } - m_gpuUsage = maxValue; - } - } - - free(gpuUsageCounterValue); - gpuUsageCounterValue = NULL; - bufferSize = 0; - itemCount = 0; - - double stopGpuDedicatedMemory; // in MB - double stopGpuSharedMemory; // in MB - - // Gpu dedicated ememory delta. Don't update the value if counter doesn't get values correctly. - status = GetFormattedCounterValue(m_gpuDedicatedMemUsageCounter, PDH_FMT_LARGE, NULL, &gpuDedicatedMemUsageCounterValue); - if (ERROR_SUCCESS == status) { - stopGpuDedicatedMemory = (double)BYTE_TO_MB(gpuDedicatedMemUsageCounterValue.largeValue); - m_deltaGpuDedicatedMemory = stopGpuDedicatedMemory - m_startGpuDedicatedMemory; - } - - // Gpu shared ememory. Don't update the value if counter doesn't get values correctly. - status = GetFormattedCounterValue(m_gpuSharedMemUsageCounter, PDH_FMT_LARGE, NULL, &gpuSharedMemUsageCounterValue); - if (ERROR_SUCCESS == status) { - stopGpuSharedMemory = (double)BYTE_TO_MB(gpuSharedMemUsageCounterValue.largeValue); - m_deltaGpuSharedMemory = stopGpuSharedMemory - m_startGpuSharedMemory; - } - } - - void GetValues(double (&values)[CounterType::TYPE_COUNT], double time) override { - ORT_UNUSED_PARAMETER(time); - values[CounterType::GPU_USAGE] = GetGpuUsage(); - values[CounterType::GPU_DEDICATED_MEM_USAGE] = GetDedicatedMemory(); - values[CounterType::GPU_SHARED_MEM_USAGE] = GetSharedMemory(); - } - - double GetGpuUsage() const { return m_gpuUsage; } - double GetDedicatedMemory() const { return m_deltaGpuDedicatedMemory; } - double GetSharedMemory() const { return m_deltaGpuSharedMemory; } - - private: - // Pdh function prototypes - typedef PDH_STATUS(WINAPI* PFNPdhOpenQuery)(_In_opt_ LPCWSTR szDataSource, _In_ DWORD_PTR dwUserData, _Out_ PDH_HQUERY* phQuery); - typedef PDH_STATUS(WINAPI* PFNPdhAddCounter)(_In_ PDH_HQUERY hQuery, _In_ LPCWSTR szFullCounterPath, _In_ DWORD_PTR dwUserData, _Out_ PDH_HCOUNTER* phCounter); - typedef PDH_STATUS(WINAPI* PFNPdhCollectQueryData)(_Inout_ PDH_HQUERY hQuery); - typedef PDH_STATUS(WINAPI* PFNPdhGetFormattedCounterArray)(_In_ PDH_HCOUNTER hCounter, _In_ DWORD dwFormat, _Inout_ LPDWORD lpdwBufferSize, _Out_ LPDWORD lpdwItemCount, _Out_writes_bytes_opt_(*lpdwBufferSize) PPDH_FMT_COUNTERVALUE_ITEM_W ItemBuffer); - typedef PDH_STATUS(WINAPI* PFNPdhGetFormattedCounterValue)(_In_ PDH_HCOUNTER hCounter, _In_ DWORD dwFormat, _Out_opt_ LPDWORD lpdwType, _Out_ PPDH_FMT_COUNTERVALUE pValue); - typedef PDH_STATUS(WINAPI* PFNPdhCloseQuery)(_Inout_ PDH_HQUERY hQuery); - - PDH_STATUS OpenQuery(LPCWSTR szDataSource, DWORD_PTR dwUserData, PDH_HQUERY* phQuery) { - return (m_pfnPdhOpenQuery) ? m_pfnPdhOpenQuery(szDataSource, dwUserData, phQuery) : ERROR_MOD_NOT_FOUND; - } - PDH_STATUS AddCounter(PDH_HQUERY hQuery, LPCWSTR szFullCounterPath, DWORD_PTR dwUserData, PDH_HCOUNTER* phCounter) { - return (m_pfnPdhAddCounter) ? m_pfnPdhAddCounter(hQuery, szFullCounterPath, dwUserData, phCounter) : ERROR_MOD_NOT_FOUND; - } - PDH_STATUS CollectQueryData(PDH_HQUERY hQuery) { - return (m_pfnPdhCollectQueryData) ? m_pfnPdhCollectQueryData(hQuery) : ERROR_MOD_NOT_FOUND; - } - PDH_STATUS GetFormattedCounterArray(PDH_HCOUNTER hCounter, DWORD dwFormat, LPDWORD lpdwBufferSize, LPDWORD lpdwItemCount, PPDH_FMT_COUNTERVALUE_ITEM_W ItemBuffer) { - return (m_pfnPdhGetFormattedCounterArray) ? m_pfnPdhGetFormattedCounterArray(hCounter, dwFormat, lpdwBufferSize, lpdwItemCount, ItemBuffer) : ERROR_MOD_NOT_FOUND; - } - PDH_STATUS GetFormattedCounterValue(PDH_HCOUNTER hCounter, DWORD dwFormat, LPDWORD lpdwType, PPDH_FMT_COUNTERVALUE pValue) { - return (m_pfnPdhGetFormattedCounterValue) ? m_pfnPdhGetFormattedCounterValue(hCounter, dwFormat, lpdwType, pValue) : ERROR_MOD_NOT_FOUND; - } - PDH_STATUS CloseQuery(PDH_HQUERY hQuery) { - return (m_pfnPdhCloseQuery) ? m_pfnPdhCloseQuery(hQuery) : ERROR_MOD_NOT_FOUND; - } - - // PDH Performance Query - HMODULE m_hPDH; - PFNPdhOpenQuery m_pfnPdhOpenQuery; - PFNPdhAddCounter m_pfnPdhAddCounter; - PFNPdhCollectQueryData m_pfnPdhCollectQueryData; - PFNPdhGetFormattedCounterArray m_pfnPdhGetFormattedCounterArray; - PFNPdhGetFormattedCounterValue m_pfnPdhGetFormattedCounterValue; - PFNPdhCloseQuery m_pfnPdhCloseQuery; - HQUERY m_query; - HCOUNTER m_gpuUsageCounter = NULL; - HCOUNTER m_gpuDedicatedMemUsageCounter = NULL; - HCOUNTER m_gpuSharedMemUsageCounter = NULL; - // Process info - DWORD m_pid = 0; - // Data - double m_gpuUsage = 0; - double m_startGpuDedicatedMemory = 0; // in MB - double m_startGpuSharedMemory = 0; // in MB - double m_deltaGpuDedicatedMemory = 0; // in MB - double m_deltaGpuSharedMemory = 0; // in MB -}; - -#endif -; - -// A statistics helper for Timer/CpuPerfCounter/GpuPerfCounter class. -// It keeps the latest "TIMER_SLOT_SIZE" measured data in a ring buffer. -// The statistic functions (e.g. GetVariance) assume data always starts from index 0 of the buffer. -class PerfCounterStatistics { - public: - void Enable(ProfilerType type) { - if (type == ProfilerType::CPU) { - m_perfCounter[type] = std::make_unique(); - } else if (type == ProfilerType::GPU) { - m_perfCounter[type] = std::make_unique(); - } - } - - void Disable(ProfilerType type) { - m_perfCounter[type].reset(); - } - - void Reset(ProfilerType type) { - m_pos = 0; - m_bufferFull = false; - for (int i = 0; i < CounterType::TYPE_COUNT; ++i) { - if (!IsCounterTypeDisabled(static_cast(i))) { - m_data[i].Reset(); - } - } - if (m_perfCounter[type]) { - m_perfCounter[type]->Reset(); - } - } - - void Start() { - m_timer.Start(); - for (unsigned int i = 0; i < m_perfCounter.size(); ++i) { - if (m_perfCounter[i]) { - m_perfCounter[i]->Start(); - } - } - } - - void Stop() { - double counterValue[CounterType::TYPE_COUNT] = {0.0f}; - // Query counters - double time = m_timer.Stop(); - counterValue[CounterType::TIMER] = time; - for (unsigned int i = 0; i < m_perfCounter.size(); ++i) { - if (m_perfCounter[i]) { - m_perfCounter[i]->Stop(); - m_perfCounter[i]->GetValues(counterValue, time); - } - } - - // Update data blocks - for (int i = 0; i < CounterType::TYPE_COUNT; ++i) { - m_data[i].total = m_data[i].total - m_data[i].measured[m_pos] + counterValue[i]; - m_data[i].measured[m_pos] = counterValue[i]; - m_data[i].max = (counterValue[i] > m_data[i].max) ? counterValue[i] : m_data[i].max; - m_data[i].min = (counterValue[i] < m_data[i].min) ? counterValue[i] : m_data[i].min; - } - - // Update buffer index - if (m_pos + 1 >= TIMER_SLOT_SIZE) { - m_pos = 0; - m_bufferFull = true; - } else { - ++m_pos; - } - } - - int GetCount() const { return (m_bufferFull) ? TIMER_SLOT_SIZE : m_pos; } - - double GetAverage(CounterType t) const { return IsCounterTypeDisabled(t) ? 0 : m_data[t].total / GetCount(); } - double GetMin(CounterType t) const { return IsCounterTypeDisabled(t) ? 0 : m_data[t].min; } - double GetMax(CounterType t) const { return IsCounterTypeDisabled(t) ? 0 : m_data[t].max; } - double GetValues(CounterType t, int index) const { return IsCounterTypeDisabled(t) ? 0 : m_data[t].measured[index]; } - double GetStdev(CounterType t) const { return IsCounterTypeDisabled(t) ? 0 : sqrt(GetVariance(t)); } - double GetVariance(CounterType t) const { - if (IsCounterTypeDisabled(t)) - return 0; - - int count = GetCount(); - double average = m_data[t].total / count; - double var = 0; - for (int i = 0; i < count; ++i) { - var += (m_data[t].measured[i] - average) * (m_data[t].measured[i] - average); - } - return var / count; - } - - private: - bool IsCounterTypeDisabled(CounterType t) const { - switch (t) { - case CPU_USAGE: - case PAGE_FAULT_COUNT: - case PAGE_FILE_USAGE: - case PEAK_PAGE_FILE_USAGE: - case WORKING_SET_USAGE: - case PEAK_WORKING_SET_USAGE: - return m_perfCounter[ProfilerType::CPU] == nullptr; - case GPU_USAGE: - case GPU_DEDICATED_MEM_USAGE: - case GPU_SHARED_MEM_USAGE: - return m_perfCounter[ProfilerType::GPU] == nullptr; - case TIMER: - return false; - default: - return true; - } - } - - struct DataBlock { - void Reset() { - max = 0; - min = DBL_MAX; - total = 0; - memset(measured, 0, sizeof(double) * TIMER_SLOT_SIZE); - } - - double max; - double min; - double total; - double measured[TIMER_SLOT_SIZE]; - }; - - int m_pos; - bool m_bufferFull; - std::array, ProfilerType::PROFILER_TYPE_COUNT> m_perfCounter; - - Timer m_timer; - DataBlock m_data[CounterType::TYPE_COUNT]; -}; - -// A class to wrap up multiple PerfCounterStatistics objects. -// To create a profiler, define intervals in an enum and use it to create the profiler object. -// See an example in engine/test/Model/ModelTest.cpp -template -class Profiler { - public: - void Reset(ProfilerType type) { - for (int i = 0; i < T::kCount; ++i) { - m_perfCounterStat[i].Reset(type); - } - } - - PerfCounterStatistics& GetCounter(int t) { - return m_perfCounterStat[t]; - } - - PerfCounterStatistics& operator[](int t) { - return m_perfCounterStat[t]; - } - - void Enable(ProfilerType type) { - for (int i = 0; i < T::kCount; ++i) { - m_perfCounterStat[i].Enable(type); - } - } - - void Disable(ProfilerType type) { - for (int i = 0; i < T::kCount; ++i) { - m_perfCounterStat[i].Disable(type); - } - } - - //Checks if Profiler is still reseted - bool IsStillReset() { - for (int i = 0; i < T::kCount; ++i) { - if (m_perfCounterStat[i].GetCount() > 0) { - return false; - } - } - return true; - } - - private: - PerfCounterStatistics m_perfCounterStat[T::kCount]; -}; - -#define WINML_PROFILING - -#ifdef WINML_PROFILING -#define WINML_PROFILING_START(profiler, interval) profiler[interval].Start() -#define WINML_PROFILING_STOP(profiler, interval) profiler[interval].Stop() -#else -#define WINML_PROFILING_START(profiler, interval) \ - do { \ - } while (0) -#define WINML_PROFILING_STOP(profiler, interval) \ - do { \ - } while (0) -#endif diff --git a/winml/lib/Common/inc/WinMLProfiler.h b/winml/lib/Common/inc/WinMLProfiler.h deleted file mode 100644 index 4e1e308e16..0000000000 --- a/winml/lib/Common/inc/WinMLProfiler.h +++ /dev/null @@ -1,13 +0,0 @@ -// Copyright (c) Microsoft Corporation. -// Licensed under the MIT License. - -#pragma once -#include "TimerHelper.h" - -enum WinMLRuntimePerf { - kLoadModel = 0, - kEvaluateModel, - kCount -}; - -extern Profiler profiler; \ No newline at end of file diff --git a/winml/lib/Common/inc/WinMLTelemetryHelper.h b/winml/lib/Common/inc/WinMLTelemetryHelper.h index 01e42e7a75..a88d564538 100644 --- a/winml/lib/Common/inc/WinMLTelemetryHelper.h +++ b/winml/lib/Common/inc/WinMLTelemetryHelper.h @@ -25,7 +25,6 @@ typedef struct WinMLModelDescription { SIZE_T Version; } WinMLModelDescription; -enum WinMLRuntimePerf; template class Profiler; @@ -80,20 +79,8 @@ class WinMLTelemetryHelper { void UnRegister() { TraceLoggingUnregister(provider_); } - - void LogDllAttachEvent(); - void LogSessionCreation(const std::string& modelname, bool isCpu, LUID adapterLuid); - void LogModelCreation(bool fromStream, - const char* author, - const char* name, - const char* domain, - const char* description, - int64_t version, - bool bUseFP16, - const std::unordered_map& modelMetadata); void LogRuntimeError(HRESULT hr, std::string message, PCSTR file, PCSTR function, int line); void LogRuntimeError(HRESULT hr, PCSTR message, PCSTR file, PCSTR function, int line); - void LogRuntimePerf(Profiler& profiler, bool force); void LogRegisterOperatorKernel( const char* name, const char* domain, diff --git a/winml/lib/Telemetry/Telemetry.cpp b/winml/lib/Telemetry/Telemetry.cpp index 959663962c..7c835cbfa8 100644 --- a/winml/lib/Telemetry/Telemetry.cpp +++ b/winml/lib/Telemetry/Telemetry.cpp @@ -11,7 +11,3 @@ TRACELOGGING_DEFINE_PROVIDER( WINML_PROVIDER_GUID, TraceLoggingOptionMicrosoftTelemetry()); -// -// Perf profiling support -// -Profiler profiler; diff --git a/winml/lib/Telemetry/TelemetryEvent.cpp b/winml/lib/Telemetry/TelemetryEvent.cpp index 11c37cb5c5..ee2d32fc9f 100644 --- a/winml/lib/Telemetry/TelemetryEvent.cpp +++ b/winml/lib/Telemetry/TelemetryEvent.cpp @@ -26,22 +26,6 @@ EventCategoryToString( } } -static EventCategory -GetEventCategoryFromRuntimePerfMode( - WinMLRuntimePerf mode) { - switch (mode) { - case WinMLRuntimePerf::kLoadModel: - return EventCategory::kModelLoad; - case WinMLRuntimePerf::kEvaluateModel: - return EventCategory::kEvaluation; - default: - // This should never happen. - // If caught downstream by cppwinrt this will be converted to - // a winrt::hresult_invalid_argument(...); - throw std::invalid_argument("mode"); - } -} - TelemetryEvent::TelemetryEvent( EventCategory category) { auto is_provider_enabled = @@ -73,16 +57,3 @@ TelemetryEvent::~TelemetryEvent() { TraceLoggingKeyword(WINML_PROVIDER_KEYWORD_START_STOP)); } } - -PerformanceTelemetryEvent::PerformanceTelemetryEvent( - WinMLRuntimePerf mode) : TelemetryEvent(GetEventCategoryFromRuntimePerfMode(mode)), - mode_(mode) { - WINML_PROFILING_START(profiler, mode_); -} - -PerformanceTelemetryEvent::~PerformanceTelemetryEvent() { - WINML_PROFILING_STOP(profiler, mode_); - if (mode_ == WinMLRuntimePerf::kEvaluateModel) { - telemetry_helper.LogRuntimePerf(profiler, false); - } -} diff --git a/winml/lib/Telemetry/WinMLTelemetryHelper.cpp b/winml/lib/Telemetry/WinMLTelemetryHelper.cpp index d3683956aa..7154401d15 100644 --- a/winml/lib/Telemetry/WinMLTelemetryHelper.cpp +++ b/winml/lib/Telemetry/WinMLTelemetryHelper.cpp @@ -16,93 +16,6 @@ WinMLTelemetryHelper::WinMLTelemetryHelper() WinMLTelemetryHelper::~WinMLTelemetryHelper() { } -void WinMLTelemetryHelper::LogDllAttachEvent() { - if (!telemetry_enabled_) - return; - - WinMLTraceLoggingWrite( - provider_, - "ProcessInfo", - TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage), - // Telemetry info - TraceLoggingKeyword(WINML_PROVIDER_KEYWORD_DEFAULT), - TraceLoggingUInt8(WINML_TLM_PROCESS_INFO_SCHEMA_VERSION, "schemaVersion"), - TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES)); -} - -void WinMLTelemetryHelper::LogSessionCreation(const std::string& modelname, bool isCpu, LUID adapterLuid) { - if (!telemetry_enabled_) - return; - - WinMLTraceLoggingWrite( - provider_, - "SessionCreation", - TraceLoggingKeyword(WINML_PROVIDER_KEYWORD_DEFAULT), - TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage), - // Telemetry info - TraceLoggingUInt8(WINML_TLM_CONTEXT_CREATION_VERSION, "schemaVersion"), - // Session info - TraceLoggingString(modelname.c_str(), "modelname"), - TraceLoggingBool(isCpu, "isCpu"), - TraceLoggingUInt32(adapterLuid.LowPart, "adapterLuidLowPart"), - TraceLoggingUInt32(adapterLuid.HighPart, "adapterLuidHighPart"), - TraceLoggingInt32(runtime_session_id_, "runtimeSessionId"), - TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES)); -} - -void WinMLTelemetryHelper::LogModelCreation(bool fromStream, - const char* author, - const char* name, - const char* domain, - const char* description, - int64_t version, - bool bUseFP16, - const std::unordered_map& modelMetadata) { - if (!telemetry_enabled_) - return; - - std::string keyStr; - std::string valueStr; - for (auto item : modelMetadata) { - keyStr.append(item.first); - keyStr.append("|"); - valueStr.append(item.second); - valueStr.append("|"); - } - auto BitmapPixelFormatMetadata = modelMetadata.find("Image.BitmapPixelFormat"); - auto ColorSpaceGammaMetadata = modelMetadata.find("Image.ColorSpaceGamma"); - auto NominalPixelRangeMetadata = modelMetadata.find("Image.NominalPixelRange"); - - std::string BitmapPixelFormatString = (BitmapPixelFormatMetadata != modelMetadata.end()) ? BitmapPixelFormatMetadata->second : ""; - std::string ColorSpaceGammaString = (ColorSpaceGammaMetadata != modelMetadata.end()) ? ColorSpaceGammaMetadata->second : ""; - std::string NominalPixelRangeString = (NominalPixelRangeMetadata != modelMetadata.end()) ? NominalPixelRangeMetadata->second : ""; - - WinMLTraceLoggingWrite( - provider_, - "ModelCreation", - TraceLoggingKeyword(WINML_PROVIDER_KEYWORD_DEFAULT), - TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage), - // Telemetry info - TraceLoggingUInt8(WINML_TLM_MODEL_CREATION_VERSION, "schemaVersion"), - //stream - TraceLoggingBool(fromStream, "fromStream"), - // Model Desc - TraceLoggingString(author, "author"), - TraceLoggingString(name, "name"), - TraceLoggingString(domain, "domain"), - TraceLoggingString(description, "description"), - TraceLoggingInt64(version, "version"), - TraceLoggingBool(bUseFP16, "usefp16"), - TraceLoggingString(BitmapPixelFormatString.c_str(), "bitmappixelformat"), - TraceLoggingString(ColorSpaceGammaString.c_str(), "colorspacegamma"), - TraceLoggingString(NominalPixelRangeString.c_str(), "nominalpixelrange"), - // MetaData - TraceLoggingUInt64(modelMetadata.size(), "metaDataCount"), - TraceLoggingString(keyStr.c_str(), "metaDataKeys"), - TraceLoggingString(valueStr.c_str(), "metaDataValues"), - TraceLoggingInt32(runtime_session_id_, "runtimeSessionId"), - TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES)); -} void WinMLTelemetryHelper::LogRuntimeError(HRESULT hr, PCSTR message, PCSTR file, PCSTR function, int line) { if (!telemetry_enabled_) @@ -129,104 +42,6 @@ void WinMLTelemetryHelper::LogRuntimeError(HRESULT hr, std::string message, PCST LogRuntimeError(hr, message.c_str(), file, function, line); } -// The default behavior is to log the telemetry every Nth time this gets called, -// but the caller can override that and log now by specifying force = true. -void WinMLTelemetryHelper::LogRuntimePerf(Profiler& runtime_profiler, bool force) { - if (!telemetry_enabled_) - return; - - // we log the telemetry if one of the following is true: - // 1. "force" was passed to this method. This happens when the dll is unloaded. - // 2. This method has been called s_telemetryChunkSize number of times. - // 3. Telemetry hasn't been logged for at least s_telemetryMaxTimeBetweenLogs number of milliseconds. - static const unsigned int s_telemetryChunkSize = 10000; - - if (!timer_started_) { - RestartTimer(); - } - - // 1. "force" was passed to this method. This happens when the dll is unloaded. - bool shouldLog = force; - - // 2. This method has been called s_telemetryChunkSize number of times. - if (!shouldLog && ++log_counter_ >= s_telemetryChunkSize) { - shouldLog = true; - } - - static const ULONGLONG s_telemetryMaxTimeBetweenLogs = 10 * 60 * 1000; // 10 minutes - - if (!shouldLog && (GetTickCount64() - timer_start_ > s_telemetryMaxTimeBetweenLogs)) { - shouldLog = true; - } - - if (shouldLog) { - WinMLTraceLoggingWrite( - provider_, - "RuntimePerf", - TraceLoggingKeyword(WINML_PROVIDER_KEYWORD_DEFAULT), - TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance), - // Telemetry info - TraceLoggingUInt8(WINML_TLM_RUNTIME_PERF_VERSION, "schemaVersion"), - TraceLoggingInt32(log_counter_, "totalEvalCalls"), - // Load Model Perf Info - TraceLoggingStruct(22, "loadModelCounters"), - TraceLoggingInt32(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetCount(), "count"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetAverage(CounterType::TIMER), "avgTime"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetAverage(CounterType::CPU_USAGE), "avgCpuUsage"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetAverage(CounterType::PAGE_FAULT_COUNT), "avgPageFaultCount"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetAverage(CounterType::WORKING_SET_USAGE), "avgWorkingSetMemory"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetAverage(CounterType::GPU_USAGE), "avgGpuUsage"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetAverage(CounterType::GPU_DEDICATED_MEM_USAGE), "avgGpuDedicatedMemory"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetAverage(CounterType::GPU_SHARED_MEM_USAGE), "avgGpuSharedMemory"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetMax(CounterType::TIMER), "maxTime"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetMax(CounterType::CPU_USAGE), "maxCpuUsage"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetMax(CounterType::PAGE_FAULT_COUNT), "maxPageFaultCount"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetMax(CounterType::WORKING_SET_USAGE), "maxWorkingSetMemory"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetMax(CounterType::GPU_USAGE), "maxGpuUsage"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetMax(CounterType::GPU_DEDICATED_MEM_USAGE), "maxGpuDedicatedMemory"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetMax(CounterType::GPU_SHARED_MEM_USAGE), "maxGpuSharedMemory"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetMin(CounterType::TIMER), "minTime"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetMin(CounterType::CPU_USAGE), "minCpuUsage"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetMin(CounterType::PAGE_FAULT_COUNT), "minPageFaultCount"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetMin(CounterType::WORKING_SET_USAGE), "minWorkingSetMemory"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetMin(CounterType::GPU_USAGE), "minGpuUsage"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetMin(CounterType::GPU_DEDICATED_MEM_USAGE), "minGpuDedicatedMemory"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kLoadModel].GetMin(CounterType::GPU_SHARED_MEM_USAGE), "minGpuSharedMemory"), - // Evaluate Model Perf Info - TraceLoggingStruct(22, "evalModelCounters"), - TraceLoggingInt32(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetCount(), "count"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetAverage(CounterType::TIMER), "avgTime"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetAverage(CounterType::CPU_USAGE), "avgCpuUsage"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetAverage(CounterType::PAGE_FAULT_COUNT), "avgPageFaultCount"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetAverage(CounterType::WORKING_SET_USAGE), "avgWorkingSetMemory"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetAverage(CounterType::GPU_USAGE), "avgGpuUsage"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetAverage(CounterType::GPU_DEDICATED_MEM_USAGE), "avgGpuDedicatedMemory"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetAverage(CounterType::GPU_SHARED_MEM_USAGE), "avgGpuSharedMemory"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetMax(CounterType::TIMER), "maxTime"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetMax(CounterType::CPU_USAGE), "maxCpuUsage"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetMax(CounterType::PAGE_FAULT_COUNT), "maxPageFaultCount"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetMax(CounterType::WORKING_SET_USAGE), "maxWorkingSetMemory"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetMax(CounterType::GPU_USAGE), "maxGpuUsage"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetMax(CounterType::GPU_DEDICATED_MEM_USAGE), "maxGpuDedicatedMemory"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetMax(CounterType::GPU_SHARED_MEM_USAGE), "maxGpuSharedMemory"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetMin(CounterType::TIMER), "minTime"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetMin(CounterType::CPU_USAGE), "minCpuUsage"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetMin(CounterType::PAGE_FAULT_COUNT), "minPageFaultCount"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetMin(CounterType::WORKING_SET_USAGE), "minWorkingSetMemory"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetMin(CounterType::GPU_USAGE), "minGpuUsage"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetMin(CounterType::GPU_DEDICATED_MEM_USAGE), "minGpuDedicatedMemory"), - TraceLoggingFloat64(runtime_profiler[WinMLRuntimePerf::kEvaluateModel].GetMin(CounterType::GPU_SHARED_MEM_USAGE), "minGpuSharedMemory"), - TraceLoggingInt32(runtime_session_id_, "runtimeSessionId"), - TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES)); - - // clear the profiler data - runtime_profiler.Reset(ProfilerType::GPU); - runtime_profiler.Reset(ProfilerType::CPU); - log_counter_ = 0; - RestartTimer(); - } -} - bool WinMLTelemetryHelper::IsMeasureSampled() { // If the machine isn't sampled at Measure Level, return false. return TraceLoggingProviderEnabled(provider_, WINEVENT_LEVEL_LOG_ALWAYS, MICROSOFT_KEYWORD_MEASURES); diff --git a/winml/lib/Telemetry/inc/TelemetryEvent.h b/winml/lib/Telemetry/inc/TelemetryEvent.h index 061588fb2b..8877b2e5c2 100644 --- a/winml/lib/Telemetry/inc/TelemetryEvent.h +++ b/winml/lib/Telemetry/inc/TelemetryEvent.h @@ -3,8 +3,6 @@ #pragma once -#include "WinMLProfiler.h" - namespace Windows::AI::MachineLearning::Telemetry { enum class EventCategory { @@ -26,16 +24,4 @@ class TelemetryEvent { std::optional event_id_; }; -// Wrapper to telemetry event. if the call throws the destructor is still called -class PerformanceTelemetryEvent : public TelemetryEvent { - public: - PerformanceTelemetryEvent( - WinMLRuntimePerf mode); - - ~PerformanceTelemetryEvent(); - - private: - WinMLRuntimePerf mode_; -}; - } // namespace Windows::AI::MachineLearning::Telemetry \ No newline at end of file diff --git a/winml/lib/Telemetry/pch.h b/winml/lib/Telemetry/pch.h index 67d0789de6..d55c453547 100644 --- a/winml/lib/Telemetry/pch.h +++ b/winml/lib/Telemetry/pch.h @@ -4,5 +4,4 @@ #pragma once #include "common.h" -#include "WinMLProfiler.h" #include "TraceLoggingConfig.h" diff --git a/winml/test/common/SqueezeNetValidator.cpp b/winml/test/common/SqueezeNetValidator.cpp index 6d0c1fb22d..e3fc0978ad 100644 --- a/winml/test/common/SqueezeNetValidator.cpp +++ b/winml/test/common/SqueezeNetValidator.cpp @@ -1,14 +1,13 @@ #include "SqueezeNetValidator.h" #include "protobufHelpers.h" #include "fileHelpers.h" +#include "core/common/common.h" #include #include #include #include #include -#include "WinMLProfiler.h" - // using namespace winrt::Windows::Foundation; using namespace winrt::Windows::AI::MachineLearning; using namespace winrt::Windows::Foundation::Collections; @@ -19,33 +18,7 @@ using namespace winrt::Windows::Storage::Streams; namespace WinML::Engine::Test{ -enum WINML_RUNTIME_TEST_PERF -{ - PREP_TEST = 0, - CREATE_RUNTIME, - LOAD_MODEL, - CREATE_EVAL_CONTEXT, - RUN_TEST, - BIND_VALUE, - EVAL_MODEL, - EVAL_MODEL_FIRST_RUN, - kCount -}; - -static std::vector WINML_RUNTIME_TEST_PERF_NAMES = -{ - "PREP TEST ", - " CREATE RUNTIME ", - " LOAD MODEL ", - " CREATE EVAL CONTEXT", - "RUN TEST ", - " BIND VALUE ", - " EVAL MODEL ", - " EVAL MODEL 1st Run " -}; - #define MAX_PROFILING_LOOP 100 -Profiler g_RuntimeProfiler; static void BindImage( @@ -149,75 +122,63 @@ void ModelValidator::FnsCandy16( bool bindInputsAsIInspectable, float dataTolerance) { - ORT_UNUSED_PARAMETER(dataTolerance); - WINML_PROFILING_START(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::PREP_TEST); - // file name strings - static wchar_t* modelFileName = L"winmlperf_coreml_FNS-Candy_prerelease_fp16.onnx"; - static wchar_t* inputDataImageFileName = L"fish_720.png"; - static wchar_t* outputDataFileName = L"output.png"; - static wchar_t* inputBindingName = L"inputImage"; - static const wchar_t* outputDataBindingName = L"outputImage"; + ORT_UNUSED_PARAMETER(dataTolerance); + // file name strings + static wchar_t* modelFileName = L"winmlperf_coreml_FNS-Candy_prerelease_fp16.onnx"; + static wchar_t* inputDataImageFileName = L"fish_720.png"; + static wchar_t* outputDataFileName = L"output.png"; + static wchar_t* inputBindingName = L"inputImage"; + static const wchar_t* outputDataBindingName = L"outputImage"; - auto modulePath = FileHelpers::GetModulePath(); - auto fullModelPath = modulePath + modelFileName; - auto outputFileName = modulePath + outputDataFileName; - WINML_PROFILING_STOP(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::PREP_TEST); + auto modulePath = FileHelpers::GetModulePath(); + auto fullModelPath = modulePath + modelFileName; + auto outputFileName = modulePath + outputDataFileName; - WINML_PROFILING_START(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::LOAD_MODEL); - // WinML model creation - LearningModel model = nullptr; - EXPECT_NO_THROW(model = LearningModel::LoadFromFilePath(fullModelPath)); - WINML_PROFILING_STOP(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::LOAD_MODEL); + // WinML model creation + LearningModel model = nullptr; + EXPECT_NO_THROW(model = LearningModel::LoadFromFilePath(fullModelPath)); - WINML_PROFILING_START(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::RUN_TEST); - WINML_PROFILING_START(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::CREATE_EVAL_CONTEXT); - LearningModelSession modelSession = nullptr; - EXPECT_NO_THROW(modelSession = LearningModelSession(model, LearningModelDevice(deviceKind))); - WINML_PROFILING_STOP(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::CREATE_EVAL_CONTEXT); + LearningModelSession modelSession = nullptr; + EXPECT_NO_THROW(modelSession = LearningModelSession(model, LearningModelDevice(deviceKind))); - WINML_PROFILING_START(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::BIND_VALUE); - LearningModelBinding modelBinding(modelSession); - auto fullImagePath = modulePath + inputDataImageFileName; - BindImage(modelBinding, inputBindingName, fullImagePath.c_str(), bindInputsAsIInspectable); + LearningModelBinding modelBinding(modelSession); + auto fullImagePath = modulePath + inputDataImageFileName; + BindImage(modelBinding, inputBindingName, fullImagePath.c_str(), bindInputsAsIInspectable); - // create the tensor for the actual output - auto output = model.OutputFeatures().First().Current(); - EXPECT_TRUE(output.Kind() == LearningModelFeatureKind::Tensor); + // create the tensor for the actual output + auto output = model.OutputFeatures().First().Current(); + EXPECT_TRUE(output.Kind() == LearningModelFeatureKind::Tensor); - auto shape = winrt::single_threaded_vector(std::vector {1, 1}); - auto outputTensor = BindImageOutput(outputBindingStrategy, modelBinding, outputDataBindingName); - WINML_PROFILING_STOP(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::BIND_VALUE); + auto shape = winrt::single_threaded_vector(std::vector {1, 1}); + auto outputTensor = BindImageOutput(outputBindingStrategy, modelBinding, outputDataBindingName); - // Evaluate the model - WINML_PROFILING_START(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::EVAL_MODEL_FIRST_RUN); - std::cout << "Calling EvaluateSync on instance" << instance << "\n"; - LearningModelEvaluationResult result = nullptr; - EXPECT_NO_THROW(result = modelSession.Evaluate(modelBinding, {})); - WINML_PROFILING_STOP(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::EVAL_MODEL_FIRST_RUN); + // Evaluate the model + std::cout << "Calling EvaluateSync on instance" << instance << "\n"; + LearningModelEvaluationResult result = nullptr; + EXPECT_NO_THROW(result = modelSession.Evaluate(modelBinding, {})); - // Get results - if (outputBindingStrategy == OutputBindingStrategy::Unbound) - { - // When output binding strategy is unbound, the output tensor was not set on bind. - // Therefore, we need to retrieve it from the LearnignModelEvaluationResult - // TODO: is this right? outputTensorT is unused... - /*auto outputTensorT = */result.Outputs().Lookup(outputDataBindingName).as(); - } - else - { - EXPECT_EQ(result.Outputs().Lookup(outputDataBindingName), outputTensor); + // Get results + if (outputBindingStrategy == OutputBindingStrategy::Unbound) + { + // When output binding strategy is unbound, the output tensor was not set on bind. + // Therefore, we need to retrieve it from the LearnignModelEvaluationResult + // TODO: is this right? outputTensorT is unused... + /*auto outputTensorT = */result.Outputs().Lookup(outputDataBindingName).as(); + } + else + { + EXPECT_EQ(result.Outputs().Lookup(outputDataBindingName), outputTensor); - auto softwareBitmap = outputTensor.VideoFrame().SoftwareBitmap(); + auto softwareBitmap = outputTensor.VideoFrame().SoftwareBitmap(); - auto folder = StorageFolder::GetFolderFromPathAsync(modulePath.c_str()).get(); - auto imagefile = folder.CreateFileAsync(outputDataFileName, CreationCollisionOption::ReplaceExisting).get(); - auto stream = imagefile.OpenAsync(FileAccessMode::ReadWrite).get(); - auto encoder = BitmapEncoder::CreateAsync(BitmapEncoder::JpegEncoderId(), stream).get(); - encoder.SetSoftwareBitmap(softwareBitmap); - encoder.FlushAsync(); + auto folder = StorageFolder::GetFolderFromPathAsync(modulePath.c_str()).get(); + auto imagefile = folder.CreateFileAsync(outputDataFileName, CreationCollisionOption::ReplaceExisting).get(); + auto stream = imagefile.OpenAsync(FileAccessMode::ReadWrite).get(); + auto encoder = BitmapEncoder::CreateAsync(BitmapEncoder::JpegEncoderId(), stream).get(); + encoder.SetSoftwareBitmap(softwareBitmap); + encoder.FlushAsync(); - } - WINML_PROFILING_STOP(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::RUN_TEST); + } } void ModelValidator::SqueezeNet( @@ -228,109 +189,80 @@ void ModelValidator::SqueezeNet( OutputBindingStrategy outputBindingStrategy, bool bindInputsAsIInspectable) { - g_RuntimeProfiler.Enable(ProfilerType::CPU); - g_RuntimeProfiler.Enable(ProfilerType::GPU); - g_RuntimeProfiler.Reset(ProfilerType::CPU); - g_RuntimeProfiler.Reset(ProfilerType::GPU); + // file name strings + static wchar_t* modelFileName = L"model.onnx"; + static wchar_t* inputDataFileName = L"test_data_0_input.pb"; + static wchar_t* outputDataFileName = L"test_data_0_output.pb"; + static wchar_t* inputBindingName = L"data_0"; + static wchar_t* inputDataImageFileName = L"kitten_224.png"; + static const wchar_t* outputDataBindingName = L"softmaxout_1"; - WINML_PROFILING_START(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::PREP_TEST); - // file name strings - static wchar_t* modelFileName = L"model.onnx"; - static wchar_t* inputDataFileName = L"test_data_0_input.pb"; - static wchar_t* outputDataFileName = L"test_data_0_output.pb"; - static wchar_t* inputBindingName = L"data_0"; - static wchar_t* inputDataImageFileName = L"kitten_224.png"; - static const wchar_t* outputDataBindingName = L"softmaxout_1"; + auto modulePath = FileHelpers::GetModulePath(); + auto fullModelPath = modulePath + modelFileName; + auto outputFileName = modulePath + outputDataFileName; + + // WinML model creation + LearningModel model = nullptr; + EXPECT_NO_THROW(model = LearningModel::LoadFromFilePath(fullModelPath)); + + LearningModelSession modelSession = nullptr; + EXPECT_NO_THROW(modelSession = LearningModelSession(model, LearningModelDevice(deviceKind))); - auto modulePath = FileHelpers::GetModulePath(); - auto fullModelPath = modulePath + modelFileName; - auto outputFileName = modulePath + outputDataFileName; - WINML_PROFILING_STOP(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::PREP_TEST); + LearningModelBinding modelBinding(modelSession); - WINML_PROFILING_START(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::LOAD_MODEL); - // WinML model creation - LearningModel model = nullptr; - EXPECT_NO_THROW(model = LearningModel::LoadFromFilePath(fullModelPath)); - WINML_PROFILING_STOP(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::LOAD_MODEL); - - WINML_PROFILING_START(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::RUN_TEST); - WINML_PROFILING_START(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::CREATE_EVAL_CONTEXT); - LearningModelSession modelSession = nullptr; - EXPECT_NO_THROW(modelSession = LearningModelSession(model, LearningModelDevice(deviceKind))); - WINML_PROFILING_STOP(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::CREATE_EVAL_CONTEXT); - - WINML_PROFILING_START(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::BIND_VALUE); - LearningModelBinding modelBinding(modelSession); - - if (bindAsImage) - { - std::wstring fullImagePath = modulePath + inputDataImageFileName; - BindImage(modelBinding, inputBindingName, fullImagePath.c_str(), bindInputsAsIInspectable); - } - else - { - auto inputDataPath = modulePath + inputDataFileName; - auto inputTensor = ProtobufHelpers::LoadTensorFromProtobufFile(inputDataPath, false); - BindTensor(modelBinding, inputBindingName, inputTensor, bindInputsAsIInspectable); - } - - // load up the expected output - auto expectedResultsTensor = ProtobufHelpers::LoadTensorFromProtobufFile(outputFileName, false); - EXPECT_TRUE(expectedResultsTensor != nullptr); - - // create the tensor for the actual output - auto output = model.OutputFeatures().First().Current(); - EXPECT_TRUE(output.Kind() == LearningModelFeatureKind::Tensor); - - auto outputTensor = BindOutput( - outputBindingStrategy, modelBinding, outputDataBindingName, expectedResultsTensor.Shape()); - WINML_PROFILING_STOP(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::BIND_VALUE); - - // Evaluate the model - WINML_PROFILING_START(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::EVAL_MODEL_FIRST_RUN); - std::cout << "Calling EvaluateSync on instance" << instance << "\n"; - LearningModelEvaluationResult result = nullptr; - EXPECT_NO_THROW(result = modelSession.Evaluate(modelBinding, {})); - WINML_PROFILING_STOP(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::EVAL_MODEL_FIRST_RUN); - - // Get results - if (outputBindingStrategy == OutputBindingStrategy::Unbound) - { - // When output binding strategy is unbound, the output tensor was not set on bind. - // Therefore, we need to retrieve it from the LearnignModelEvaluationResult - outputTensor = result.Outputs().Lookup(outputDataBindingName).as(); - } - else - { - EXPECT_EQ(result.Outputs().Lookup(outputDataBindingName), outputTensor); - } - - auto outDataExpected = expectedResultsTensor.as().GetAsVectorView(); - auto outDataActual = outputTensor.as().GetAsVectorView(); - - EXPECT_TRUE(outDataActual.Size() == outDataExpected.Size()); - for (uint32_t i = 0; i < outDataActual.Size(); i++) - { - float delta = std::abs(outDataActual.GetAt(i) - outDataExpected.GetAt(i)); - if (delta > dataTolerance) - { - ADD_FAILURE() << "EXPECTED: " << outDataExpected.GetAt(i) << " , ACTUAL: " << outDataActual.GetAt(i) - << "instance " << instance << ", element " << i; - - } - } - WINML_PROFILING_STOP(g_RuntimeProfiler, WINML_RUNTIME_TEST_PERF::RUN_TEST); - - std::cout << "Profiling data:\n"; - for (int i = 0; i < WINML_RUNTIME_TEST_PERF::kCount; ++i) + if (bindAsImage) { - std::cout << WINML_RUNTIME_TEST_PERF_NAMES[i] - << ": Time=" << g_RuntimeProfiler[i].GetAverage(CounterType::TIMER) - << "\tCPUUse(%%)=" << g_RuntimeProfiler[i].GetAverage(CounterType::CPU_USAGE) - << "\tAvgWorkingSetDelta(MB)=" << g_RuntimeProfiler[i].GetAverage(CounterType::WORKING_SET_USAGE) - << "\tMaxWorkingSetDelta(MB)=" << g_RuntimeProfiler[i].GetMax(CounterType::WORKING_SET_USAGE) - << "\tGPUUse(%%)=" << g_RuntimeProfiler[i].GetAverage(CounterType::GPU_USAGE) - << "\tGPUDedicatedMem(MB)=" << g_RuntimeProfiler[i].GetAverage(CounterType::GPU_DEDICATED_MEM_USAGE); + std::wstring fullImagePath = modulePath + inputDataImageFileName; + BindImage(modelBinding, inputBindingName, fullImagePath.c_str(), bindInputsAsIInspectable); + } + else + { + auto inputDataPath = modulePath + inputDataFileName; + auto inputTensor = ProtobufHelpers::LoadTensorFromProtobufFile(inputDataPath, false); + BindTensor(modelBinding, inputBindingName, inputTensor, bindInputsAsIInspectable); + } + + // load up the expected output + auto expectedResultsTensor = ProtobufHelpers::LoadTensorFromProtobufFile(outputFileName, false); + EXPECT_TRUE(expectedResultsTensor != nullptr); + + // create the tensor for the actual output + auto output = model.OutputFeatures().First().Current(); + EXPECT_TRUE(output.Kind() == LearningModelFeatureKind::Tensor); + + auto outputTensor = BindOutput( + outputBindingStrategy, modelBinding, outputDataBindingName, expectedResultsTensor.Shape()); + + // Evaluate the model + std::cout << "Calling EvaluateSync on instance" << instance << "\n"; + LearningModelEvaluationResult result = nullptr; + EXPECT_NO_THROW(result = modelSession.Evaluate(modelBinding, {})); + + // Get results + if (outputBindingStrategy == OutputBindingStrategy::Unbound) + { + // When output binding strategy is unbound, the output tensor was not set on bind. + // Therefore, we need to retrieve it from the LearnignModelEvaluationResult + outputTensor = result.Outputs().Lookup(outputDataBindingName).as(); + } + else + { + EXPECT_EQ(result.Outputs().Lookup(outputDataBindingName), outputTensor); + } + + auto outDataExpected = expectedResultsTensor.as().GetAsVectorView(); + auto outDataActual = outputTensor.as().GetAsVectorView(); + + EXPECT_TRUE(outDataActual.Size() == outDataExpected.Size()); + for (uint32_t i = 0; i < outDataActual.Size(); i++) + { + float delta = std::abs(outDataActual.GetAt(i) - outDataExpected.GetAt(i)); + if (delta > dataTolerance) + { + ADD_FAILURE() << "EXPECTED: " << outDataExpected.GetAt(i) << " , ACTUAL: " << outDataActual.GetAt(i) + << "instance " << instance << ", element " << i; + + } } } }