From 2b6b3a2ee6fdef5b4670a4017f889004981fa05a Mon Sep 17 00:00:00 2001 From: Chun-Wei Chen Date: Wed, 14 Oct 2020 05:32:43 -0700 Subject: [PATCH] Add GetProfilingStartTimeNs() to Python/C# APIs (#5280) * add Python API for getProfilingStartTime * debug for using Python API * add in C# api * use uint intead of uint64_t to prevent warning * typo for GetProfilingStartTimeNs * remove const * Update onnxruntime/python/session.py Co-authored-by: Pranav Sharma * remove unnecessary return * Add Python unit test * Add C# unit test and refactor Python test * use ulong in C# for uint64_t in C++ * remove time.monotonic_ns * syntax: remove public for inner function * correct the API's order * getprofilingstarttime after run * Correct the right order in NativeMethod.cs * update order * nit: remove spaces * Update csharp/src/Microsoft.ML.OnnxRuntime/InferenceSession.cs Co-authored-by: Guoyu Wang <62914304+gwang-msft@users.noreply.github.com> * use the updated function * add comment about the precision * add more comments * add session.py back * fix flake8 * remove session.py * Add comments in C, C#, Python APIs about precision Co-authored-by: Pranav Sharma Co-authored-by: Guoyu Wang <62914304+gwang-msft@users.noreply.github.com> --- .../InferenceSession.cs | 24 ++++++++++++-- .../Microsoft.ML.OnnxRuntime/NativeMethods.cs | 12 ++++++- .../InferenceTest.cs | 31 +++++++++++++++++++ .../core/session/onnxruntime_c_api.h | 2 ++ onnxruntime/core/common/profiler.h | 6 ++-- onnxruntime/core/session/onnxruntime_c_api.cc | 2 +- .../onnxruntime_inference_collection.py | 11 +++++++ .../python/onnxruntime_pybind_state.cc | 3 ++ .../test/framework/inference_session_test.cc | 2 +- .../test/python/onnxruntime_test_python.py | 17 ++++++++++ 10 files changed, 102 insertions(+), 8 deletions(-) diff --git a/csharp/src/Microsoft.ML.OnnxRuntime/InferenceSession.cs b/csharp/src/Microsoft.ML.OnnxRuntime/InferenceSession.cs index a54e6c0f51..f32f19f069 100644 --- a/csharp/src/Microsoft.ML.OnnxRuntime/InferenceSession.cs +++ b/csharp/src/Microsoft.ML.OnnxRuntime/InferenceSession.cs @@ -22,6 +22,7 @@ namespace Microsoft.ML.OnnxRuntime private RunOptions _builtInRunOptions = null; private ModelMetadata _modelMetadata = null; private bool _disposed = false; + private ulong _profilingStartTimeNs = 0; #region Public API @@ -597,7 +598,7 @@ namespace Microsoft.ML.OnnxRuntime } - private DisposableList RunImpl(RunOptions options, IntPtr[] inputNames, IntPtr[] inputValues, IntPtr[] outputNames, + private DisposableList RunImpl(RunOptions options, IntPtr[] inputNames, IntPtr[] inputValues, IntPtr[] outputNames, DisposableList cleanupList) { var ortValues = new DisposableList(outputNames.Length); @@ -656,6 +657,19 @@ namespace Microsoft.ML.OnnxRuntime } } + /// + /// Return the nanoseconds of profiling's start time + /// On some platforms, this timer may not be as precise as nanoseconds + /// For instance, on Windows and MacOS, the precision will be ~100ns + /// + public ulong ProfilingStartTimeNs + { + get + { + return _profilingStartTimeNs; + } + } + #endregion #region private methods @@ -724,7 +738,11 @@ namespace Microsoft.ML.OnnxRuntime { _overridableInitializerMetadata[GetOverridableInitializerName(i)] = GetOverridableInitializerMetadata(i); } - + // set profiling's start time + UIntPtr startTime = UIntPtr.Zero; + NativeApiStatus.VerifySuccess(NativeMethods.OrtSessionGetProfilingStartTimeNs(_nativeHandle, + out startTime)); + _profilingStartTimeNs = (ulong) startTime; } catch (OnnxRuntimeException e) { @@ -736,7 +754,7 @@ namespace Microsoft.ML.OnnxRuntime throw e; } - _builtInRunOptions = new RunOptions(); // create a default built-in run option, and avoid creating a new one every run() call + _builtInRunOptions = new RunOptions(); // create a default built-in run option, and avoid creating a new one every run() call } diff --git a/csharp/src/Microsoft.ML.OnnxRuntime/NativeMethods.cs b/csharp/src/Microsoft.ML.OnnxRuntime/NativeMethods.cs index 2b3dbda98e..692ba0b671 100644 --- a/csharp/src/Microsoft.ML.OnnxRuntime/NativeMethods.cs +++ b/csharp/src/Microsoft.ML.OnnxRuntime/NativeMethods.cs @@ -177,6 +177,10 @@ namespace Microsoft.ML.OnnxRuntime public IntPtr TensorAt; public IntPtr CreateAndRegisterAllocator; public IntPtr SetLanguageProjection; + public IntPtr SessionGetProfilingStartTimeNs; + public IntPtr SetGlobalIntraOpNumThreads; + public IntPtr SetGlobalInterOpNumThreads; + public IntPtr SetGlobalSpinControl; public IntPtr AddInitializer; } @@ -219,6 +223,7 @@ namespace Microsoft.ML.OnnxRuntime OrtSessionGetOverridableInitializerTypeInfo = (DOrtSessionGetOverridableInitializerTypeInfo)Marshal.GetDelegateForFunctionPointer(api_.SessionGetOverridableInitializerTypeInfo, typeof(DOrtSessionGetOverridableInitializerTypeInfo)); OrtReleaseTypeInfo = (DOrtReleaseTypeInfo)Marshal.GetDelegateForFunctionPointer(api_.ReleaseTypeInfo, typeof(DOrtReleaseTypeInfo)); OrtReleaseSession = (DOrtReleaseSession)Marshal.GetDelegateForFunctionPointer(api_.ReleaseSession, typeof(DOrtReleaseSession)); + OrtSessionGetProfilingStartTimeNs = (DOrtSessionGetProfilingStartTimeNs)Marshal.GetDelegateForFunctionPointer(api_.SessionGetProfilingStartTimeNs, typeof(DOrtSessionGetProfilingStartTimeNs)); OrtCreateSessionOptions = (DOrtCreateSessionOptions)Marshal.GetDelegateForFunctionPointer(api_.CreateSessionOptions, typeof(DOrtCreateSessionOptions)); OrtReleaseSessionOptions = (DOrtReleaseSessionOptions)Marshal.GetDelegateForFunctionPointer(api_.ReleaseSessionOptions, typeof(DOrtReleaseSessionOptions)); @@ -413,7 +418,7 @@ namespace Microsoft.ML.OnnxRuntime IntPtr /*(const OrtSession*)*/ session, IntPtr /*(OrtAllocator*)*/ allocator, out IntPtr /*(char**)*/profile_file); - public static DOrtSessionEndProfiling OrtSessionEndProfiling; + public static DOrtSessionEndProfiling OrtSessionEndProfiling; public delegate IntPtr /*(OrtStatus*)*/DOrtSessionGetOverridableInitializerName( IntPtr /*(OrtSession*)*/ session, @@ -447,6 +452,11 @@ namespace Microsoft.ML.OnnxRuntime public delegate void DOrtReleaseSession(IntPtr /*(OrtSession*)*/session); public static DOrtReleaseSession OrtReleaseSession; + public delegate IntPtr /*(OrtStatus*)*/ DOrtSessionGetProfilingStartTimeNs( + IntPtr /*(const OrtSession*)*/ session, + out UIntPtr /*(ulong* out)*/ startTime); + public static DOrtSessionGetProfilingStartTimeNs OrtSessionGetProfilingStartTimeNs; + #endregion InferenceSession API #region SessionOptions API diff --git a/csharp/test/Microsoft.ML.OnnxRuntime.Tests/InferenceTest.cs b/csharp/test/Microsoft.ML.OnnxRuntime.Tests/InferenceTest.cs index 3744325ae7..76945366e3 100644 --- a/csharp/test/Microsoft.ML.OnnxRuntime.Tests/InferenceTest.cs +++ b/csharp/test/Microsoft.ML.OnnxRuntime.Tests/InferenceTest.cs @@ -366,6 +366,37 @@ namespace Microsoft.ML.OnnxRuntime.Tests } + [Fact] + public void InferenceSessionGetProfilingStartTimeNs() + { + ulong getSingleSessionProfilingStartTime() + { + ulong startTime = 0; + using (SessionOptions options = new SessionOptions()) + { + options.EnableProfiling = true; + string modelPath = Path.Combine(Directory.GetCurrentDirectory(), "squeezenet.onnx"); + using (var session = new InferenceSession(modelPath, options)) + { + startTime = session.ProfilingStartTimeNs; + } + } + return startTime; + } + + // Get 1st profiling's start time + ulong startTime1 = getSingleSessionProfilingStartTime(); + // Get 2nd profiling's start time + ulong startTime2 = getSingleSessionProfilingStartTime(); + // Get 3rd profiling's start time + ulong startTime3 = getSingleSessionProfilingStartTime(); + + // Check the profiling's start time has been updated + Assert.True(startTime1 != 0); + // Chronological profiling's start time + Assert.True(startTime1 <= startTime2 && startTime2 <= startTime3); + } + private void validateRunResults(IReadOnlyCollection results) { // validate the results diff --git a/include/onnxruntime/core/session/onnxruntime_c_api.h b/include/onnxruntime/core/session/onnxruntime_c_api.h index 2e0d6f4e77..1ef7786104 100644 --- a/include/onnxruntime/core/session/onnxruntime_c_api.h +++ b/include/onnxruntime/core/session/onnxruntime_c_api.h @@ -1043,6 +1043,8 @@ struct OrtApi { ORT_API2_STATUS(SetLanguageProjection, _In_ const OrtEnv* ort_env, _In_ OrtLanguageProjection projection); /** + * On some platforms, this timer may not be as precise as nanoseconds + * For instance, on Windows and MacOS, the precision will be ~100ns * \param out is set to the nanoseconds of profiling's start time */ ORT_API2_STATUS(SessionGetProfilingStartTimeNs, _In_ const OrtSession* sess, _Outptr_ uint64_t* out); diff --git a/onnxruntime/core/common/profiler.h b/onnxruntime/core/common/profiler.h index 71f7ce487f..2ef1a8ac65 100644 --- a/onnxruntime/core/common/profiler.h +++ b/onnxruntime/core/common/profiler.h @@ -60,9 +60,11 @@ class Profiler { return enabled_; } /* - Return the stored start time of profiler + Return the stored start time of profiler. + On some platforms, this timer may not be as precise as nanoseconds + For instance, on Windows and MacOS, the precision (high_resolution_clock) will be ~100ns */ - uint64_t GetStartTime() const { + uint64_t GetStartTimeNs() const { return std::chrono::duration_cast( profiling_start_time_.time_since_epoch()).count(); } diff --git a/onnxruntime/core/session/onnxruntime_c_api.cc b/onnxruntime/core/session/onnxruntime_c_api.cc index c8fb7d0ca6..7e67edcb56 100644 --- a/onnxruntime/core/session/onnxruntime_c_api.cc +++ b/onnxruntime/core/session/onnxruntime_c_api.cc @@ -1797,7 +1797,7 @@ ORT_API_STATUS_IMPL(OrtApis::SetLanguageProjection, _In_ const OrtEnv* ort_env, ORT_API_STATUS_IMPL(OrtApis::SessionGetProfilingStartTimeNs, _In_ const OrtSession* sess, _Outptr_ uint64_t* out) { API_IMPL_BEGIN const auto* session = reinterpret_cast(sess); - auto profiling_start_time = session->GetProfiling().GetStartTime(); + auto profiling_start_time = session->GetProfiling().GetStartTimeNs(); *out = static_cast(profiling_start_time); return nullptr; API_IMPL_END diff --git a/onnxruntime/python/onnxruntime_inference_collection.py b/onnxruntime/python/onnxruntime_inference_collection.py index d27fb57cc2..4a36123df9 100644 --- a/onnxruntime/python/onnxruntime_inference_collection.py +++ b/onnxruntime/python/onnxruntime_inference_collection.py @@ -142,6 +142,15 @@ class Session: """ return self._sess.end_profiling() + def get_profiling_start_time_ns(self): + """ + Return the nanoseconds of profiling's start time + Comparable to time.monotonic_ns() after Python 3.3 + On some platforms, this timer may not be as precise as nanoseconds + For instance, on Windows and MacOS, the precision will be ~100ns + """ + return self._sess.get_profiling_start_time_ns + def io_binding(self): "Return an onnxruntime.IOBinding object`." return IOBinding(self) @@ -229,6 +238,7 @@ class InferenceSession(Session): self._model_meta = self._sess.model_meta self._providers = self._sess.get_providers() self._provider_options = self._sess.get_provider_options() + self._profiling_start_time_ns = self._sess.get_profiling_start_time_ns def _reset_session(self, providers, provider_options): "release underlying session object." @@ -241,6 +251,7 @@ class InferenceSession(Session): self._model_meta = None self._providers = None self._provider_options = None + self._profiling_start_time_ns = None # create a new C.InferenceSession self._sess = None diff --git a/onnxruntime/python/onnxruntime_pybind_state.cc b/onnxruntime/python/onnxruntime_pybind_state.cc index 6499389eee..a9ed3ee113 100644 --- a/onnxruntime/python/onnxruntime_pybind_state.cc +++ b/onnxruntime/python/onnxruntime_pybind_state.cc @@ -1690,6 +1690,9 @@ including arg name, arg type (contains both type and shape).)pbdoc") .def("end_profiling", [](PyInferenceSession* sess) -> std::string { return sess->GetSessionHandle()->EndProfiling(); }) + .def_property_readonly("get_profiling_start_time_ns", [](const PyInferenceSession* sess) -> uint64_t{ + return sess->GetSessionHandle()->GetProfiling().GetStartTimeNs(); + }) .def("get_providers", [](PyInferenceSession* sess) -> const std::vector& { return sess->GetSessionHandle()->GetRegisteredProviderTypes(); }) diff --git a/onnxruntime/test/framework/inference_session_test.cc b/onnxruntime/test/framework/inference_session_test.cc index 6e676f9e2d..967def5ba1 100644 --- a/onnxruntime/test/framework/inference_session_test.cc +++ b/onnxruntime/test/framework/inference_session_test.cc @@ -683,7 +683,7 @@ TEST(InferenceSessionTests, CheckRunProfilerStartTime) { uint64_t before_start_time = std::chrono::duration_cast( std::chrono::high_resolution_clock::now().time_since_epoch()).count(); // get current time session_object.StartProfiling("onnxruntime_profile_start"); - uint64_t profiling_start_time = session_object.GetProfiling().GetStartTime(); + uint64_t profiling_start_time = session_object.GetProfiling().GetStartTimeNs(); uint64_t after_start_time = std::chrono::duration_cast( std::chrono::high_resolution_clock::now().time_since_epoch()).count(); diff --git a/onnxruntime/test/python/onnxruntime_test_python.py b/onnxruntime/test/python/onnxruntime_test_python.py index 1d81da6b56..b0291b2d19 100644 --- a/onnxruntime/test/python/onnxruntime_test_python.py +++ b/onnxruntime/test/python/onnxruntime_test_python.py @@ -513,6 +513,23 @@ class TestInferenceSession(unittest.TestCase): self.assertTrue(tag in lines[i]) self.assertTrue(']' in lines[8]) + def testProfilerGetStartTimeNs(self): + def getSingleSessionProfilingStartTime(): + so = onnxrt.SessionOptions() + so.enable_profiling = True + sess = onnxrt.InferenceSession(get_name("mul_1.onnx"), sess_options=so) + return sess.get_profiling_start_time_ns() + + # Get 1st profiling's start time + start_time_1 = getSingleSessionProfilingStartTime() + # Get 2nd profiling's start time + start_time_2 = getSingleSessionProfilingStartTime() + # Get 3rd profiling's start time + start_time_3 = getSingleSessionProfilingStartTime() + + # Chronological profiling's start time + self.assertTrue(start_time_1 <= start_time_2 <= start_time_3) + def testGraphOptimizationLevel(self): opt = onnxrt.SessionOptions() # default should be all optimizations optimization