From 17d34da9efab1e515b29755811b7ad7597aacb79 Mon Sep 17 00:00:00 2001
From: Jan Eilers <jan.eilers@arm.com>
Date: Wed, 8 Dec 2021 16:15:12 +0000
Subject: Add addition timing logging output

 * Adds ExecuteNetwork when building the delegate only
 * Adds timings to delegate subgraph creation
 * Adds executions times

Signed-off-by: Jan Eilers <jan.eilers@arm.com>
Change-Id: Ieff2f67ea8dbb6c2a708f8810e84a20485b7a631
---
 delegate/src/armnn_delegate.cpp | 19 +++++++++++++++++++
 1 file changed, 19 insertions(+)

(limited to 'delegate')

diff --git a/delegate/src/armnn_delegate.cpp b/delegate/src/armnn_delegate.cpp
index 0069b4fe0e..b18d234d69 100644
--- a/delegate/src/armnn_delegate.cpp
+++ b/delegate/src/armnn_delegate.cpp
@@ -40,6 +40,7 @@
 #include "Unpack.hpp"
 
 #include <armnnUtils/Filesystem.hpp>
+#include <armnn/utility/Timer.hpp>
 #include <flatbuffers/flatbuffers.h>
 #include <tensorflow/lite/context_util.h>
 #include <tensorflow/lite/schema/schema_generated.h>
@@ -281,6 +282,9 @@ ArmnnSubgraph* ArmnnSubgraph::Create(TfLiteContext* tfLiteContext,
                                      const TfLiteDelegateParams* parameters,
                                      const Delegate* delegate)
 {
+    const auto startTime = armnn::GetTimeNow();
+    ARMNN_LOG(info) << "ArmnnSubgraph creation";
+
     TfLiteIntArray* executionPlan;
     if (tfLiteContext->GetExecutionPlan(tfLiteContext, &executionPlan) != kTfLiteOk)
     {
@@ -308,6 +312,7 @@ ArmnnSubgraph* ArmnnSubgraph::Create(TfLiteContext* tfLiteContext,
     }
 
     // Parse TfLite delegate nodes to ArmNN
+    const auto parseStartTime = armnn::GetTimeNow();
     for (int i = 0; i < parameters->nodes_to_replace->size; ++i)
     {
         const int nodeIndex = parameters->nodes_to_replace->data[i];
@@ -325,6 +330,8 @@ ArmnnSubgraph* ArmnnSubgraph::Create(TfLiteContext* tfLiteContext,
             throw armnn::Exception(&"TfLiteArmnnDelegate: Unable to parse node: " [ nodeIndex]);
         }
     }
+    ARMNN_LOG(info) << "Parse nodes to ArmNN time: " << std::setprecision(2)
+                    << std::fixed << armnn::GetTimeDuration(parseStartTime).count() << " ms";
 
     // Add Output layer
     status = AddOutputLayer(delegateData, tfLiteContext, parameters->output_tensors, outputBindings);
@@ -337,10 +344,13 @@ ArmnnSubgraph* ArmnnSubgraph::Create(TfLiteContext* tfLiteContext,
     armnn::IOptimizedNetworkPtr optNet(nullptr, nullptr);
     try
     {
+        const auto optimizeStartTime = armnn::GetTimeNow();
         optNet = armnn::Optimize(*(delegateData.m_Network.get()),
                                  delegate->m_Options.GetBackends(),
                                  delegate->m_Runtime->GetDeviceSpec(),
                                  delegate->m_Options.GetOptimizerOptions());
+        ARMNN_LOG(info) << "Optimize ArmnnSubgraph time: " << std::setprecision(2)
+                        << std::fixed << armnn::GetTimeDuration(optimizeStartTime).count() << " ms";
     }
     catch (std::exception &ex)
     {
@@ -358,6 +368,7 @@ ArmnnSubgraph* ArmnnSubgraph::Create(TfLiteContext* tfLiteContext,
     const std::string serializeToDotFile = delegate->m_Options.GetSerializeToDot();
     if (!serializeToDotFile.empty())
     {
+        ARMNN_LOG(info) << "Writing graph to dot file: " << serializeToDotFile;
         fs::path filename = serializeToDotFile;
         std::fstream file(filename.c_str(), std::ios_base::out);
         optNet->SerializeToDot(file);
@@ -365,6 +376,8 @@ ArmnnSubgraph* ArmnnSubgraph::Create(TfLiteContext* tfLiteContext,
 
     try
     {
+        const auto loadStartTime = armnn::GetTimeNow();
+
         // Load graph into runtime
         std::string errorMessage;
         armnn::Status loadingStatus;
@@ -387,6 +400,9 @@ ArmnnSubgraph* ArmnnSubgraph::Create(TfLiteContext* tfLiteContext,
             // Network load failed.
             throw armnn::Exception("TfLiteArmnnDelegate: Network could not be loaded:" + errorMessage);
         }
+
+        ARMNN_LOG(info) << "Load ArmnnSubgraph time: " << std::setprecision(2)
+                        << std::fixed << armnn::GetTimeDuration(loadStartTime).count() << " ms";
     }
     catch (std::exception& ex)
     {
@@ -401,6 +417,9 @@ ArmnnSubgraph* ArmnnSubgraph::Create(TfLiteContext* tfLiteContext,
         delegate->m_Runtime->RegisterDebugCallback(networkId, delegate->m_Options.GetDebugCallbackFunction().value());
     }
 
+    ARMNN_LOG(info) << "Overall ArmnnSubgraph creation time: " << std::setprecision(2)
+                    << std::fixed << armnn::GetTimeDuration(startTime).count() << " ms\n";
+
     // Create a new SubGraph with networkId and runtime
     return new ArmnnSubgraph(networkId, delegate->m_Runtime.get(), inputBindings, outputBindings);
 }
-- 
cgit v1.2.1