Arm backend: Measure and show time per model during testing (pytorch#12128)

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.


cc @digantdesai @freddan80 @per @oscarandersson8218

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

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"
+        )