Arm backend: Measure and show time per model during testing

This will add time logs during testing so it will be easier to track
what part of the flow take time and for what models.

Signed-off-by: Zingo Andersen <[email protected]>
Change-Id: I5e124bf5e15a7c252df77089e83044d96b9ade4e

Author: zingo

backends/arm/test/test_model.py

@@ -7,6 +7,7 @@
 import os
 import subprocess
 import sys
+import time
 
 
 def get_args():
@@ -199,12 +200,17 @@ def run_elf_with_fvp(script_path: str, elf_file: str, target: str, timeout: int)
 
 
 if __name__ == "__main__":
-
+    total_start_time = time.perf_counter()
     args = get_args()
     script_path = os.path.join("backends", "arm", "scripts")
 
     if args.build_libs:
+        start_time = time.perf_counter()
         build_libs(args.test_output, script_path)
+        end_time = time.perf_counter()
+        print(
+            f"[Test model: {end_time - start_time:.2f} s] Build needed executorch libs"
+        )
 
     if args.model:
         model_name = args.model.split(" ")[0].split(";")[0]
@@ -217,6 +223,7 @@ def run_elf_with_fvp(script_path: str, elf_file: str, target: str, timeout: int)
             args.test_output, f"{model_name}_arm_delegate_{args.target}"
         )
 
+        start_time = time.perf_counter()
         pte_file = build_pte(
             args.test_output,
             model_name,
@@ -226,13 +233,17 @@ def run_elf_with_fvp(script_path: str, elf_file: str, target: str, timeout: int)
             output,
             args.no_intermediate,
         )
-        print(f"PTE file created: {pte_file} ")
+        end_time = time.perf_counter()
+        print(
+            f"[Test model: {end_time - start_time:.2f} s] PTE file created: {pte_file}"
+        )
 
         if "ethos-u" in args.target:
             elf_build_path = os.path.join(
                 output, f"{model_name}_arm_delegate_{args.target}"
             )
 
+            start_time = time.perf_counter()
             elf_file = build_ethosu_runtime(
                 args.test_output,
                 script_path,
@@ -243,7 +254,18 @@ def run_elf_with_fvp(script_path: str, elf_file: str, target: str, timeout: int)
                 args.extra_flags,
                 elf_build_path,
             )
-            print(f"ELF file created: {elf_file} ")
+            end_time = time.perf_counter()
+            print(
+                f"[Test model: {end_time - start_time:.2f} s] ELF file created: {elf_file}"
+            )
 
+            start_time = time.perf_counter()
             run_elf_with_fvp(script_path, elf_file, args.target, args.timeout)
-        print(f"Model: {model_name} on {args.target} -> PASS")
+            end_time = time.perf_counter()
+            print(
+                f"[Test model: {end_time - start_time:.2f} s] Tested elf on FVP {elf_file}"
+            )
+        total_end_time = time.perf_counter()
+        print(
+            f"[Test model: {total_end_time - total_start_time:.2f} s total] Model: {model_name} on {args.target} -> PASS"
+        )