Refactor performance measurements

Change 'Inference runtime' to measure CPU cycles for the
Tensorflow Lite Micro interpreter.Invoke() call.

Add 'Operator(s) runtime' print that prints a summary for
cycles spent on all operators during an inference. (This is
equivalent to the old reported 'Inference runtime')

Move prints out of the EndEvent() function in ArmProfiler as
it otherwise interferes with the inference cycle measurement.

Change-Id: Ie11b5abb5b12a3bcf5a67841f04834d05dfd796d

2 files changed, 17 insertions, 2 deletions

diff --git a/applications/inference_process/include/inference_process.hpp b/applications/inference_process/include/inference_process.hpp
index 9635884..fc54ae0 100644
--- a/applications/inference_process/include/inference_process.hpp
+++ b/applications/inference_process/include/inference_process.hpp
@@ -52,6 +52,7 @@ struct InferenceJob {
     std::vector<DataPtr> input;
     std::vector<DataPtr> output;
     std::vector<DataPtr> expectedOutput;
+    uint64_t cpuCycles{0};
     size_t numBytesToPrint;
     void *externalContext;
 
diff --git a/applications/inference_process/src/inference_process.cpp b/applications/inference_process/src/inference_process.cpp
index 264c4ba..29254c7 100644
--- a/applications/inference_process/src/inference_process.cpp
+++ b/applications/inference_process/src/inference_process.cpp
@@ -21,6 +21,7 @@
 #include "tensorflow/lite/micro/micro_error_reporter.h"
 #include "tensorflow/lite/micro/micro_interpreter.h"
 #include "tensorflow/lite/micro/micro_profiler.h"
+#include "tensorflow/lite/micro/micro_time.h"
 #include "tensorflow/lite/schema/schema_generated.h"
 
 #include "arm_profiler.hpp"
@@ -150,15 +151,20 @@ bool InferenceProcess::runJob(InferenceJob &job) {
         return true;
     }
 
+    // Get the current cycle counter value
+    uint32_t cpuCyclesBegin = tflite::GetCurrentTimeTicks();
+
     // Run the inference
     status = interpreter.Invoke();
+
+    // Calculate nbr of CPU cycles for the Invoke call
+    job.cpuCycles = tflite::GetCurrentTimeTicks() - cpuCyclesBegin;
+
     if (status != kTfLiteOk) {
         LOG_ERR("Invoke failed for inference: job=%s", job.name.c_str());
         return true;
     }
 
-    LOG("Inference runtime: %" PRIu64 " cycles\n", profiler.GetTotalTicks());
-
     // Copy output data from TFLu arena to job descriptor
     if (copyOfm(job, interpreter)) {
         return true;
@@ -171,8 +177,16 @@ bool InferenceProcess::runJob(InferenceJob &job) {
         return true;
     }
 
+    LOG_INFO("\n");
     LOG_INFO("Finished running job: %s", job.name.c_str());
 
+    profiler.ReportResults();
+
+    LOG("\n");
+    LOG("Operator(s) total: %" PRIu64 " CPU cycles\n\n", profiler.GetTotalTicks());
+
+    LOG("Inference runtime: %" PRIu64 " CPU cycles total\n\n", job.cpuCycles);
+
     return false;
 }