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 <emailpranav@gmail.com>

* 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 <emailpranav@gmail.com>
Co-authored-by: Guoyu Wang <62914304+gwang-msft@users.noreply.github.com>
This commit is contained in:
Chun-Wei Chen 2020-10-14 05:32:43 -07:00 committed by GitHub
parent 1514509fd7
commit 2b6b3a2ee6
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
10 changed files with 102 additions and 8 deletions

View file

@ -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<OrtValue> RunImpl(RunOptions options, IntPtr[] inputNames, IntPtr[] inputValues, IntPtr[] outputNames,
private DisposableList<OrtValue> RunImpl(RunOptions options, IntPtr[] inputNames, IntPtr[] inputValues, IntPtr[] outputNames,
DisposableList<IDisposable> cleanupList)
{
var ortValues = new DisposableList<OrtValue>(outputNames.Length);
@ -656,6 +657,19 @@ namespace Microsoft.ML.OnnxRuntime
}
}
/// <summary>
/// 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
/// </summary>
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
}

View file

@ -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

View file

@ -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<NamedOnnxValue> results)
{
// validate the results

View file

@ -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);

View file

@ -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<std::chrono::nanoseconds>(
profiling_start_time_.time_since_epoch()).count();
}

View file

@ -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<const ::onnxruntime::InferenceSession*>(sess);
auto profiling_start_time = session->GetProfiling().GetStartTime();
auto profiling_start_time = session->GetProfiling().GetStartTimeNs();
*out = static_cast<uint64_t>(profiling_start_time);
return nullptr;
API_IMPL_END

View file

@ -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

View file

@ -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<std::string>& {
return sess->GetSessionHandle()->GetRegisteredProviderTypes();
})

View file

@ -683,7 +683,7 @@ TEST(InferenceSessionTests, CheckRunProfilerStartTime) {
uint64_t before_start_time = std::chrono::duration_cast<std::chrono::nanoseconds>(
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::nanoseconds>(
std::chrono::high_resolution_clock::now().time_since_epoch()).count();

View file

@ -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