From 1978376e1eff681d02bf69c10d8af2821b821295 Mon Sep 17 00:00:00 2001
From: George Wu <George.Wu@microsoft.com>
Date: Wed, 8 Jan 2020 11:17:48 -1000
Subject: [PATCH] add session creation time cost. (#2798)

---
 .../test/perftest/performance_runner.cc       | 19 ++++++++++++-------
 .../test/perftest/performance_runner.h        |  2 ++
 2 files changed, 14 insertions(+), 7 deletions(-)

diff --git a/onnxruntime/test/perftest/performance_runner.cc b/onnxruntime/test/perftest/performance_runner.cc
index 7820639946fad..6e539162bf88a 100644
--- a/onnxruntime/test/perftest/performance_runner.cc
+++ b/onnxruntime/test/perftest/performance_runner.cc
@@ -69,15 +69,17 @@ Status PerformanceRunner::Run() {
   performance_result_.average_CPU_usage = p_ICPUUsage->GetUsage();
   performance_result_.peak_workingset_size = utils::GetPeakWorkingSetSize();
 
+  std::chrono::duration<double> session_create_duration = session_create_end_ - session_create_start_;
   // TODO: end profiling
   // if (!performance_test_config_.run_config.profile_file.empty()) session_object->EndProfiling();
-  std::chrono::duration<double> duration = performance_result_.end_ - performance_result_.start_;
+  std::chrono::duration<double> inference_duration = performance_result_.end_ - performance_result_.start_;
 
-  std::cout << "Total time cost:" << performance_result_.total_time_cost << std::endl  // sum of time taken by each request
-            << "Total iterations:" << performance_result_.time_costs.size() << std::endl
-            << "Average time cost:" << performance_result_.total_time_cost / performance_result_.time_costs.size() * 1000 << " ms" << std::endl
+  std::cout << "Session creation time cost:" << session_create_duration.count() << " s" << std::endl
+            << "Total inference time cost:" << performance_result_.total_time_cost << " s" << std::endl  // sum of time taken by each request
+            << "Total inference requests:" << performance_result_.time_costs.size() << std::endl
+            << "Average inference time cost:" << performance_result_.total_time_cost / performance_result_.time_costs.size() * 1000 << " ms" << std::endl
             // Time between start and end of run. Less than Total time cost when running requests in parallel.
-            << "Total run time:" << duration.count() << " s" << std::endl;
+            << "Total inference run time:" << inference_duration.count() << " s" << std::endl;
   return Status::OK();
 }
 
@@ -191,8 +193,11 @@ static TestSession* CreateSession(Ort::Env& env, std::random_device& rd,
 }
 PerformanceRunner::PerformanceRunner(Ort::Env& env, const PerformanceTestConfig& test_config, std::random_device& rd)
     : performance_test_config_(test_config),
-      test_model_info_(CreateModelInfo(test_config)),
-      session_(CreateSession(env, rd, test_config, test_model_info_)) {}
+      test_model_info_(CreateModelInfo(test_config)) {
+  session_create_start_ = std::chrono::high_resolution_clock::now();
+  session_.reset(CreateSession(env, rd, test_config, test_model_info_));
+  session_create_end_ = std::chrono::high_resolution_clock::now();
+}
 
 PerformanceRunner::~PerformanceRunner() = default;
 
diff --git a/onnxruntime/test/perftest/performance_runner.h b/onnxruntime/test/perftest/performance_runner.h
index bd3d03e80475f..902422bb4af66 100644
--- a/onnxruntime/test/perftest/performance_runner.h
+++ b/onnxruntime/test/perftest/performance_runner.h
@@ -132,6 +132,8 @@ class PerformanceRunner {
   }
 
  private:
+  std::chrono::time_point<std::chrono::high_resolution_clock> session_create_start_;
+  std::chrono::time_point<std::chrono::high_resolution_clock> session_create_end_;
   PerformanceResult performance_result_;
   PerformanceTestConfig performance_test_config_;
   TestModelInfo* test_model_info_;