IVGCVSW-6649 Add Timepoints to Android NN Driver

 * Added timepoints to ArmnnDriverImpl across all versions
 * Added ALOGV message to display time taken for prepareModel function
 * Added ALOGV message to display time taken for prepareModelFromCache function

Signed-off-by: Ryan OShea <ryan.oshea3@arm.com>
Change-Id: I07f341099e81a0da45db0e8f575ba3c26631e024

3 files changed, 33 insertions, 0 deletions

diff --git a/1.2/ArmnnDriverImpl.cpp b/1.2/ArmnnDriverImpl.cpp
index 1c31384a..563c88e0 100644
--- a/1.2/ArmnnDriverImpl.cpp
+++ b/1.2/ArmnnDriverImpl.cpp
@@ -12,6 +12,7 @@
 
 #include <log/log.h>
 #include <sys/stat.h>
+#include <chrono>
 
 namespace
 {
@@ -101,6 +102,8 @@ Return<V1_0::ErrorStatus> ArmnnDriverImpl::prepareArmnnModel_1_2(
 {
     ALOGV("ArmnnDriverImpl::prepareArmnnModel_1_2()");
 
+    std::chrono::time_point<std::chrono::system_clock> prepareModelTimepoint = std::chrono::system_clock::now();
+
     if (cb.get() == nullptr)
     {
         ALOGW("ArmnnDriverImpl::prepareModel: Invalid callback passed to prepareModel");
@@ -372,6 +375,10 @@ Return<V1_0::ErrorStatus> ArmnnDriverImpl::prepareArmnnModel_1_2(
     }
 
     NotifyCallbackAndCheck(cb, V1_0::ErrorStatus::NONE, preparedModel.release());
+
+    ALOGV("ArmnnDriverImpl::prepareModel cache timing = %lld µs", std::chrono::duration_cast<std::chrono::microseconds>
+         (std::chrono::system_clock::now() - prepareModelTimepoint).count());
+
     return V1_0::ErrorStatus::NONE;
 }
 
@@ -385,6 +392,7 @@ Return<V1_0::ErrorStatus> ArmnnDriverImpl::prepareModelFromCache(
     bool float32ToFloat16)
 {
     ALOGV("ArmnnDriverImpl::prepareModelFromCache()");
+    std::chrono::time_point<std::chrono::system_clock> modelFromCacheTimepoint = std::chrono::system_clock::now();
 
     if (cb.get() == nullptr)
     {
@@ -637,6 +645,11 @@ Return<V1_0::ErrorStatus> ArmnnDriverImpl::prepareModelFromCache(
                     true));
 
     NotifyCallbackAndCheck(cb, V1_0::ErrorStatus::NONE, preparedModel.release());
+
+    ALOGV("ArmnnDriverImpl::prepareModelFromCache cache timing = %lld µs",
+          std::chrono::duration_cast<std::chrono::microseconds>
+          (std::chrono::system_clock::now() - modelFromCacheTimepoint).count());
+
     return V1_0::ErrorStatus::NONE;
 }
 
diff --git a/1.3/ArmnnDriverImpl.cpp b/1.3/ArmnnDriverImpl.cpp
index 474e1c1f..c164dc08 100644
--- a/1.3/ArmnnDriverImpl.cpp
+++ b/1.3/ArmnnDriverImpl.cpp
@@ -13,6 +13,7 @@
 #include <log/log.h>
 
 #include <sys/stat.h>
+#include <chrono>
 
 namespace
 {
@@ -113,6 +114,8 @@ Return<V1_3::ErrorStatus> ArmnnDriverImpl::prepareArmnnModel_1_3(
 {
     ALOGV("ArmnnDriverImpl::prepareArmnnModel_1_3()");
 
+    std::chrono::time_point<std::chrono::system_clock> prepareModelTimepoint = std::chrono::system_clock::now();
+
     if (cb.get() == nullptr)
     {
         ALOGW("ArmnnDriverImpl::prepareModel: Invalid callback passed to prepareModel");
@@ -387,6 +390,11 @@ Return<V1_3::ErrorStatus> ArmnnDriverImpl::prepareArmnnModel_1_3(
     }
 
     NotifyCallbackAndCheck(cb, V1_3::ErrorStatus::NONE, preparedModel.release());
+
+    ALOGV("ArmnnDriverImpl::prepareModel cache timing = %lld µs", std::chrono::duration_cast<std::chrono::microseconds>
+         (std::chrono::system_clock::now() - prepareModelTimepoint).count());
+
+
     return V1_3::ErrorStatus::NONE;
 }
 
@@ -399,6 +407,7 @@ Return<V1_3::ErrorStatus> ArmnnDriverImpl::prepareModelFromCache_1_3(
     const android::sp<V1_3::IPreparedModelCallback>& cb)
 {
     ALOGV("ArmnnDriverImpl::prepareModelFromCache_1_3()");
+    std::chrono::time_point<std::chrono::system_clock> modelFromCacheTimepoint = std::chrono::system_clock::now();
 
     if (token.size() != ANEURALNETWORKS_BYTE_SIZE_OF_CACHE_TOKEN)
     {
@@ -652,6 +661,11 @@ Return<V1_3::ErrorStatus> ArmnnDriverImpl::prepareModelFromCache_1_3(
                                                            true));
 
     NotifyCallbackAndCheck(cb, V1_3::ErrorStatus::NONE, preparedModel.release());
+
+    ALOGV("ArmnnDriverImpl::prepareModelFromCache timing = %lld µs",
+          std::chrono::duration_cast<std::chrono::microseconds>
+          (std::chrono::system_clock::now() - modelFromCacheTimepoint).count());
+
     return V1_3::ErrorStatus::NONE;
 }
 
diff --git a/ArmnnDriverImpl.cpp b/ArmnnDriverImpl.cpp
index 89fa54fc..927c6bdd 100644
--- a/ArmnnDriverImpl.cpp
+++ b/ArmnnDriverImpl.cpp
@@ -23,6 +23,7 @@
 
 #include <ValidateHal.h>
 #include <log/log.h>
+#include <chrono>
 
 using namespace std;
 using namespace android;
@@ -70,6 +71,8 @@ Return<V1_0::ErrorStatus> ArmnnDriverImpl<HalPolicy>::prepareModel(
 {
     ALOGV("ArmnnDriverImpl::prepareModel()");
 
+    std::chrono::time_point<std::chrono::system_clock> prepareModelTimepoint = std::chrono::system_clock::now();
+
     if (cb.get() == nullptr)
     {
         ALOGW("ArmnnDriverImpl::prepareModel: Invalid callback passed to prepareModel");
@@ -234,6 +237,9 @@ Return<V1_0::ErrorStatus> ArmnnDriverImpl<HalPolicy>::prepareModel(
     }
     NotifyCallbackAndCheck(cb, V1_0::ErrorStatus::NONE, preparedModel);
 
+    ALOGV("ArmnnDriverImpl::prepareModel cache timing = %lld µs", std::chrono::duration_cast<std::chrono::microseconds>
+         (std::chrono::system_clock::now() - prepareModelTimepoint).count());
+
     return V1_0::ErrorStatus::NONE;
 }