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
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 @@
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 @@
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 @@
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;
}
diff --git a/lib/arm_profiler/include/arm_profiler.hpp b/lib/arm_profiler/include/arm_profiler.hpp
index 0b97e2e..0e6784d 100644
--- a/lib/arm_profiler/include/arm_profiler.hpp
+++ b/lib/arm_profiler/include/arm_profiler.hpp
@@ -31,6 +31,7 @@
uint32_t BeginEvent(const char *tag);
void EndEvent(uint32_t event_handle);
uint64_t GetTotalTicks() const;
+ void ReportResults() const;
private:
size_t max_events_;
diff --git a/lib/arm_profiler/src/arm_profiler.cpp b/lib/arm_profiler/src/arm_profiler.cpp
index c90eec2..7648584 100644
--- a/lib/arm_profiler/src/arm_profiler.cpp
+++ b/lib/arm_profiler/src/arm_profiler.cpp
@@ -50,8 +50,6 @@
void ArmProfiler::EndEvent(uint32_t event_handle) {
TFLITE_DCHECK(event_handle < max_events_);
end_ticks_[event_handle] = GetCurrentTimeTicks();
- tflite::GetMicroErrorReporter()->Report(
- "%s : cycle_cnt : %u cycles", tags_[event_handle], end_ticks_[event_handle] - start_ticks_[event_handle]);
}
uint64_t ArmProfiler::GetTotalTicks() const {
@@ -64,4 +62,12 @@
return ticks;
}
+void ArmProfiler::ReportResults() const {
+ tflite::GetMicroErrorReporter()->Report("Profiler report, CPU cycles per operator:");
+ for (size_t i = 0; i < num_events_; ++i) {
+ tflite::GetMicroErrorReporter()->Report(
+ "%s : cycle_cnt : %u cycles", tags_[i], end_ticks_[i] - start_ticks_[i]);
+ }
+}
+
} // namespace tflite