Fix benchmark perf counter stats output (#13134)

* Fix benchmark_app commandline parsing

Object 'str' does not have a contains() method. Replaced by
"searchstring in object" query.

* Fix perf counter output and use consistent units

When ProfilingInfo was bound by pybind11, those entries turned into
Python timedelta objects. This caused two problems:

1. There was a division by 1000 to go to milliseconds. This caused a lot
   of precision lost, because `timedelta(microseconds=2300)/1000.0 =
   timedelta(2)` and `timedelta(microseconds=33) = timedelta(0)`.
2. When converting those timedelta objects to str, the output is in the
   form of (HH:MM:SS.XXXXXX). This is not very useful microsecond based
   performance counters.

This change simply reverts everything to printing plain microsecond
based integers.

* Align counter output to ms between Python/C++
This commit is contained in:
Nico Galoppo 2022-10-06 15:17:15 -07:00 committed by GitHub
parent 948e36896e
commit 6e791a021c
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 14 additions and 10 deletions

View File

@ -32,7 +32,7 @@ def parse_and_check_command_line():
"should explicitely set -hint option to none. This is not OpenVINO limitation " \ "should explicitely set -hint option to none. This is not OpenVINO limitation " \
"(those options can be used in OpenVINO together), but a benchmark_app UI rule.") "(those options can be used in OpenVINO together), but a benchmark_app UI rule.")
if args.report_type == "average_counters" and args.target_device.contains("MULTI"): if args.report_type == "average_counters" and "MULTI" in args.target_device:
raise Exception("only detailed_counters report type is supported for MULTI device") raise Exception("only detailed_counters report type is supported for MULTI device")
_, ext = os.path.splitext(args.path_to_model) _, ext = os.path.splitext(args.path_to_model)

View File

@ -64,11 +64,15 @@ class StatisticsReport:
total_cpu = timedelta() total_cpu = timedelta()
f.write(self.csv_separator.join(['layerName', 'execStatus', 'layerType', 'execType', 'realTime (ms)', 'cpuTime (ms)\n'])) f.write(self.csv_separator.join(['layerName', 'execStatus', 'layerType', 'execType', 'realTime (ms)', 'cpuTime (ms)\n']))
for pi in prof_info: for pi in prof_info:
f.write(self.csv_separator.join([pi.node_name, str(pi.status), pi.node_type, pi.exec_type, str(pi.real_time/1000.0), str(pi.cpu_time/1000.0)])) f.write(self.csv_separator.join([pi.node_name, str(pi.status), pi.node_type, pi.exec_type,
str((pi.real_time // timedelta(microseconds=1))/1000.0),
str((pi.cpu_time // timedelta(microseconds=1))/1000.0)]))
f.write('\n') f.write('\n')
total += pi.real_time total += pi.real_time
total_cpu += pi.cpu_time total_cpu += pi.cpu_time
f.write(self.csv_separator.join(['Total','','','',str(total/1000.0),str(total_cpu/1000.0)])) f.write(self.csv_separator.join(['Total','','','',
str((total // timedelta(microseconds=1))/1000.0),
str((total_cpu // timedelta(microseconds=1))/1000.0)]))
f.write('\n\n') f.write('\n\n')
def dump_performance_counters(self, prof_info_list): def dump_performance_counters(self, prof_info_list):

View File

@ -2,7 +2,7 @@
# SPDX-License-Identifier: Apache-2.0 # SPDX-License-Identifier: Apache-2.0
from collections import defaultdict from collections import defaultdict
import datetime from datetime import timedelta
from openvino.runtime import Core, Model, PartialShape, Dimension, Layout, Type, serialize from openvino.runtime import Core, Model, PartialShape, Dimension, Layout, Type, serialize
from openvino.preprocess import PrePostProcessor from openvino.preprocess import PrePostProcessor
@ -314,20 +314,20 @@ def print_perf_counters(perf_counts_list):
max_layer_name = 30 max_layer_name = 30
for ni in range(len(perf_counts_list)): for ni in range(len(perf_counts_list)):
perf_counts = perf_counts_list[ni] perf_counts = perf_counts_list[ni]
total_time = datetime.timedelta() total_time = timedelta()
total_time_cpu = datetime.timedelta() total_time_cpu = timedelta()
logger.info(f"Performance counts for {ni}-th infer request") logger.info(f"Performance counts for {ni}-th infer request")
for pi in perf_counts: for pi in perf_counts:
print(f"{pi.node_name[:max_layer_name - 4] + '...' if (len(pi.node_name) >= max_layer_name) else pi.node_name:<30}" print(f"{pi.node_name[:max_layer_name - 4] + '...' if (len(pi.node_name) >= max_layer_name) else pi.node_name:<30}"
f"{str(pi.status):<15}" f"{str(pi.status):<15}"
f"{'layerType: ' + pi.node_type:<30}" f"{'layerType: ' + pi.node_type:<30}"
f"{'realTime: ' + str(pi.real_time):<20}" f"{'realTime: ' + str((pi.real_time // timedelta(microseconds=1)) / 1000.0):<20}"
f"{'cpu: ' + str(pi.cpu_time):<20}" f"{'cpu: ' + str((pi.cpu_time // timedelta(microseconds=1)) / 1000.0):<20}"
f"{'execType: ' + pi.exec_type:<20}") f"{'execType: ' + pi.exec_type:<20}")
total_time += pi.real_time total_time += pi.real_time
total_time_cpu += pi.cpu_time total_time_cpu += pi.cpu_time
print(f'Total time: {total_time} microseconds') print(f'Total time: {(total_time // timedelta(microseconds=1)) / 1000.0} milliseconds')
print(f'Total CPU time: {total_time_cpu} microseconds\n') print(f'Total CPU time: {(total_time_cpu // timedelta(microseconds=1)) / 1000.0} milliseconds\n')
def get_command_line_arguments(argv): def get_command_line_arguments(argv):