From 947e85fcea073ef7503315cc96a5c6b0e695fdcc Mon Sep 17 00:00:00 2001 From: Christian Date: Thu, 13 Oct 2022 18:07:43 +0200 Subject: [PATCH 01/17] timer report --- .../interface/abstract_spinnaker_base.py | 8 +- .../interface/provenance/fec_timer.py | 4 +- .../interface/provenance/provenance_reader.py | 21 ++- .../utilities/report_functions/__init__.py | 2 + .../report_functions/timer_report.py | 136 ++++++++++++++++++ 5 files changed, 165 insertions(+), 6 deletions(-) create mode 100644 spinn_front_end_common/utilities/report_functions/timer_report.py diff --git a/spinn_front_end_common/interface/abstract_spinnaker_base.py b/spinn_front_end_common/interface/abstract_spinnaker_base.py index b23d8d3160..431aae12c8 100644 --- a/spinn_front_end_common/interface/abstract_spinnaker_base.py +++ b/spinn_front_end_common/interface/abstract_spinnaker_base.py @@ -109,7 +109,7 @@ router_collision_potential_report, routing_table_from_machine_report, tags_from_machine_report, write_json_machine, write_json_placements, - write_json_routing_tables, drift_report) + write_json_routing_tables, write_timer_report, drift_report) from spinn_front_end_common.utilities.iobuf_extractor import IOBufExtractor from spinn_front_end_common.utilities.utility_objs import ExecutableType from spinn_front_end_common.utility_models import ( @@ -678,12 +678,14 @@ def _execute_machine_generator(self, allocator_data): else: return + FecTimer.start_category(TimerCategory.GET_MACHINE, True) with FecTimer("Machine generator", TimerWork.GET_MACHINE): machine, transceiver = machine_generator( bmp_details, board_version, auto_detect_bmp, scamp_connection_data, reset_machine) self._data_writer.set_transceiver(transceiver) self._data_writer.set_machine(machine) + FecTimer.end_category(TimerCategory.GET_MACHINE) def _get_known_machine(self, total_run_time=0.0): """ The python machine description object. @@ -1688,11 +1690,13 @@ def _execute_system_data_specification(self): Runs, times and logs the execute_system_data_specs if required """ + FecTimer.start_category(TimerCategory.DATA_GENERATION, True) with FecTimer( "Execute system data specification", TimerWork.OTHER) as timer: if timer.skip_if_virtual_board(): return None execute_system_data_specs() + FecTimer.end_category(TimerCategory.DATA_GENERATION) def _execute_load_system_executable_images(self): """ @@ -2161,6 +2165,7 @@ def _do_run(self, n_machine_time_steps, n_sync_steps): # reraise exception raise run_e + def _recover_from_error(self, exception): """ :param Exception exception: @@ -2375,6 +2380,7 @@ def stop(self): # shut down the machine properly self._shutdown() + write_timer_report() self.write_finished_file() # No matching FecTimer.end_category as shutdown stops timer diff --git a/spinn_front_end_common/interface/provenance/fec_timer.py b/spinn_front_end_common/interface/provenance/fec_timer.py index 7056bc4095..718331c775 100644 --- a/spinn_front_end_common/interface/provenance/fec_timer.py +++ b/spinn_front_end_common/interface/provenance/fec_timer.py @@ -234,10 +234,10 @@ def start_category(cls, category, machine_on=None): :type machine_on: None or bool """ cls._previous.append(cls._category) - if cls._category != category: - cls._change_category(category) if machine_on is not None: cls._machine_on = machine_on + if cls._category != category: + cls._change_category(category) @classmethod def end_category(cls, category): diff --git a/spinn_front_end_common/interface/provenance/provenance_reader.py b/spinn_front_end_common/interface/provenance/provenance_reader.py index cb12669d80..a3f560e3c7 100644 --- a/spinn_front_end_common/interface/provenance/provenance_reader.py +++ b/spinn_front_end_common/interface/provenance/provenance_reader.py @@ -183,9 +183,24 @@ def get_timer_provenance(self, algorithm): FROM timer_provenance WHERE algorithm LIKE ? """ - return "\n".join( - f"{row[0]}: {row[1]}" - for row in self.run_query(query, [algorithm])) + return self.run_query(query) + + def get_all_timer_provenance(self): + """ + Gets the all timer provenance item(s) from the last run + + :return: + A possibly multiline string with for each row which matches the + like a line ``algorithm: value`` + :rtype: str + """ + query = """ + SELECT algorithm, sum(time_taken), count(*) + FROM timer_provenance + GROUP BY algorithm + ORDER BY min(timer_id) + """ + return self.run_query(query) def get_run_times(self): """ diff --git a/spinn_front_end_common/utilities/report_functions/__init__.py b/spinn_front_end_common/utilities/report_functions/__init__.py index 2a28071ecc..62f0df6f7a 100644 --- a/spinn_front_end_common/utilities/report_functions/__init__.py +++ b/spinn_front_end_common/utilities/report_functions/__init__.py @@ -26,6 +26,7 @@ from .routing_table_from_machine_report import ( routing_table_from_machine_report) from .real_tags_report import tags_from_machine_report +from .timer_report import write_timer_report from .write_json_machine import write_json_machine from .write_json_placements import write_json_placements from .write_json_routing_tables import write_json_routing_tables @@ -47,4 +48,5 @@ "write_json_machine", "write_json_placements", "write_json_routing_tables", + "write_timer_report", "drift_report"] diff --git a/spinn_front_end_common/utilities/report_functions/timer_report.py b/spinn_front_end_common/utilities/report_functions/timer_report.py new file mode 100644 index 0000000000..9fc3639b8a --- /dev/null +++ b/spinn_front_end_common/utilities/report_functions/timer_report.py @@ -0,0 +1,136 @@ +# Copyright (c) 2017-2019 The University of Manchester +# +# This program is free software: you can redistribute it and/or modify +# it under the terms of the GNU General Public License as published by +# the Free Software Foundation, either version 3 of the License, or +# (at your option) any later version. +# +# This program is distributed in the hope that it will be useful, +# but WITHOUT ANY WARRANTY; without even the implied warranty of +# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +# GNU General Public License for more details. +# +# You should have received a copy of the GNU General Public License +# along with this program. If not, see . + +import logging +import os +from spinn_utilities.config_holder import get_config_float +from spinn_utilities.log import FormatAdapter +from spinn_front_end_common.data import FecDataView +from spinn_front_end_common.interface.provenance import ( + ProvenanceReader, TimerCategory, TimerWork) + +logger = FormatAdapter(logging.getLogger(__name__)) + +#: converter between joules to kilowatt hours +JOULES_TO_KILOWATT_HOURS = 3600000 + +# report file name +TIMER_FILENAME = "timer_report.rpt" + +def write_timer_report( + report_path=None, provenance_path=None, algorithm_report_percent=None, + algorithm_report_ms=None): + """ Writes the timer report. + + Only provides parameters if using this standalone + + :param report_path: Where to write the report if not using the default + :type report_path: None or str + :param provenance_path: Where the provenance sqlite3 files is located if + not using the default. + :type provenance_path: None or str + :param algorithm_report_percent: Percentage of total time and algorithm must take + to be shown. Or None to use cfg if available or default + :type algorithm_report_percent; None or float + :param algorithm_report_ms: Time in ms which algorithm must take + to be shown. Or None to use cfg if available or default + :type algorithm_report_ms: None or float + + =None, cutoff_value + + :rtype: None + """ + if report_path is None: + run_dir = FecDataView.get_run_dir_path() + if not run_dir.endswith("run_1"): + logger.warning( + "timer report does not currently work well after a reset") + report_path = os.path.join(run_dir, TIMER_FILENAME) + + # create report + reader = ProvenanceReader(provenance_data_path=provenance_path) + with open(report_path, "w", encoding="utf-8") as f: + __write_timer_report( + f, reader, algorithm_report_percent, algorithm_report_ms) + + +def __write_timer_report(f, reader, algorithm_report_percent, algorithm_report_ms): + """ Write time report into the file + + :param ~io.TextIOBase f: file writer + :param ProvenanceReader reader: + """ + f.write("Summary timer report\n-------------------\n\n") + + total = __report_category_sums(f, reader) + __report_works_sums(f, reader) + __report_algorithms( + f, reader, total, algorithm_report_percent, algorithm_report_ms) + + +def __report_category_sums(f, reader): + total_on = 0 + total_off = 0 + f.write(f"category_name time_on time_off\n") + for category in TimerCategory: + on, off = reader.get_category_timer_sums(category) + total_on += on + total_off += off + f.write(f"{category.category_name:18} {on:10.3f}ms {off:10.3f}ms \n") + f.write(f"\nIn total the script took {(total_on + total_off):10.2f} " + f"of which the machine was on for {total_on:10.2f}\n\n") + return total_on + total_off + + +def __report_works_sums(f, reader): + f.write(f"work type time\n") + for work in TimerWork: + time = reader.get_timer_sum_by_work(work) + f.write(f"{work.work_name:18} {time:10.3f}ms\n") + f.write(f"\n\n") + + +def __report_algorithms( + f, reader, total, algorithm_report_ratio, algorithm_report_ms): + if algorithm_report_ratio is None: + try: + algorithm_report_ratio = get_config_float( + "report", "algorithm_report_percent") + except Exception: + logger.warning("No algorithm_report_ratio so using 1%") + algorithm_report_ratio = 0.01 + + if algorithm_report_ms is None: + try: + algorithm_report_ms = get_config_float( + "report", "algorithm_report_ms") + except Exception: + logger.warning("No algorithm_report_ms so using 10ms") + algorithm_report_ms = 10 + + cutoff = total * algorithm_report_ratio + if cutoff < algorithm_report_ms: + f.write(f"algorithms which ran for longer than {algorithm_report_ratio}" + f" of the total time\n") + else: + cutoff = algorithm_report_ms + f.write(f"algorithms which ran for longer than {cutoff}ms\n") + data = reader.get_all_timer_provenance() + f.write(f"algorithms which ran for longer than {cutoff}ms\n") + f.write("Name total_time n_runs\n") + for name, time, count in data: + if time > cutoff: + f.write(f"{name:35} {time:10.3f} {count}\n") + f.write(f"\n\n") From b0e7d4ea54d6b8843995aae73f6d833a19817e99 Mon Sep 17 00:00:00 2001 From: Christian Date: Fri, 14 Oct 2022 09:09:10 +0200 Subject: [PATCH 02/17] timer report cfg flag --- .../interface/abstract_spinnaker_base.py | 7 +- .../interface/spinnaker.cfg | 7 ++ .../report_functions/timer_report.py | 68 +++++++++++-------- 3 files changed, 53 insertions(+), 29 deletions(-) diff --git a/spinn_front_end_common/interface/abstract_spinnaker_base.py b/spinn_front_end_common/interface/abstract_spinnaker_base.py index 431aae12c8..71724a0ec0 100644 --- a/spinn_front_end_common/interface/abstract_spinnaker_base.py +++ b/spinn_front_end_common/interface/abstract_spinnaker_base.py @@ -2352,6 +2352,11 @@ def __close_allocation_controller(self): self._machine_allocation_controller.close() self._machine_allocation_controller = None + def _report_timer_report(self): + # No FecTimer as shutdown has closed the timer! + if get_config_bool("Reports", "write_timer_report"): + write_timer_report() + def stop(self): """ End running of the simulation. @@ -2380,7 +2385,7 @@ def stop(self): # shut down the machine properly self._shutdown() - write_timer_report() + self._report_timer_report() self.write_finished_file() # No matching FecTimer.end_category as shutdown stops timer diff --git a/spinn_front_end_common/interface/spinnaker.cfg b/spinn_front_end_common/interface/spinnaker.cfg index e0c55e9602..6a5be2c8ce 100644 --- a/spinn_front_end_common/interface/spinnaker.cfg +++ b/spinn_front_end_common/interface/spinnaker.cfg @@ -82,6 +82,13 @@ write_router_compression_with_bitfield_report = True write_drift_report_start = False write_drift_report_end = False +write_timer_report = True +timer_report_to_stdout = False +# ratio of single Algorithm to total time to report algorithm +timer_report_ratio = 0.01 +# min time to report algorithm even if less than ratio +timer_report_ms = 1000 + max_reports_kept = 10 max_application_binaries_kept = 10 remove_errored_folders = False diff --git a/spinn_front_end_common/utilities/report_functions/timer_report.py b/spinn_front_end_common/utilities/report_functions/timer_report.py index 9fc3639b8a..3ee6cd9d44 100644 --- a/spinn_front_end_common/utilities/report_functions/timer_report.py +++ b/spinn_front_end_common/utilities/report_functions/timer_report.py @@ -15,7 +15,8 @@ import logging import os -from spinn_utilities.config_holder import get_config_float +import sys +from spinn_utilities.config_holder import get_config_bool, get_config_float from spinn_utilities.log import FormatAdapter from spinn_front_end_common.data import FecDataView from spinn_front_end_common.interface.provenance import ( @@ -30,8 +31,8 @@ TIMER_FILENAME = "timer_report.rpt" def write_timer_report( - report_path=None, provenance_path=None, algorithm_report_percent=None, - algorithm_report_ms=None): + report_path=None, provenance_path=None, timer_report_ratio=None, + timer_report_ms=None, timer_report_to_stdout=None): """ Writes the timer report. Only provides parameters if using this standalone @@ -41,12 +42,12 @@ def write_timer_report( :param provenance_path: Where the provenance sqlite3 files is located if not using the default. :type provenance_path: None or str - :param algorithm_report_percent: Percentage of total time and algorithm must take + :param timer_report_ratio: Percentage of total time and algorithm must take to be shown. Or None to use cfg if available or default - :type algorithm_report_percent; None or float - :param algorithm_report_ms: Time in ms which algorithm must take + :type timer_report_ratio; None or float + :param timer_report_ms: Time in ms which algorithm must take to be shown. Or None to use cfg if available or default - :type algorithm_report_ms: None or float + :type timer_report_ms: None or float =None, cutoff_value @@ -60,13 +61,25 @@ def write_timer_report( report_path = os.path.join(run_dir, TIMER_FILENAME) # create report + if timer_report_to_stdout is None: + #try: + timer_report_to_stdout = get_config_bool( + "Reports", "timer_report_to_stdout") + #except Exception: + # logger.warning("No timer_report_to_stdout found so using False") + # timer_report_to_stdout = False + reader = ProvenanceReader(provenance_data_path=provenance_path) - with open(report_path, "w", encoding="utf-8") as f: + if timer_report_to_stdout: __write_timer_report( - f, reader, algorithm_report_percent, algorithm_report_ms) + sys.stdout, reader, timer_report_ratio, timer_report_ms) + else: + with open(report_path, "w", encoding="utf-8") as f: + __write_timer_report( + f, reader, timer_report_ratio, timer_report_ms) -def __write_timer_report(f, reader, algorithm_report_percent, algorithm_report_ms): +def __write_timer_report(f, reader, timer_report_ratio, timer_report_ms): """ Write time report into the file :param ~io.TextIOBase f: file writer @@ -77,7 +90,7 @@ def __write_timer_report(f, reader, algorithm_report_percent, algorithm_report_m total = __report_category_sums(f, reader) __report_works_sums(f, reader) __report_algorithms( - f, reader, total, algorithm_report_percent, algorithm_report_ms) + f, reader, total, timer_report_ratio, timer_report_ms) def __report_category_sums(f, reader): @@ -103,33 +116,32 @@ def __report_works_sums(f, reader): def __report_algorithms( - f, reader, total, algorithm_report_ratio, algorithm_report_ms): - if algorithm_report_ratio is None: + f, reader, total, timer_report_ratio, timer_report_ms): + if timer_report_ratio is None: try: - algorithm_report_ratio = get_config_float( - "report", "algorithm_report_percent") + timer_report_ratio = get_config_float( + "Reports", "timer_report_ratio") except Exception: - logger.warning("No algorithm_report_ratio so using 1%") - algorithm_report_ratio = 0.01 + logger.warning("No timer_report_ratio so using 1%") + timer_report_ratio = 0.01 - if algorithm_report_ms is None: + if timer_report_ms is None: try: - algorithm_report_ms = get_config_float( - "report", "algorithm_report_ms") + timer_report_ms = get_config_float( + "Reports", "timer_report_ms") except Exception: - logger.warning("No algorithm_report_ms so using 10ms") - algorithm_report_ms = 10 + logger.warning("No timer_report_ms so using 10ms") + timer_report_ms = 1000 - cutoff = total * algorithm_report_ratio - if cutoff < algorithm_report_ms: - f.write(f"algorithms which ran for longer than {algorithm_report_ratio}" + cutoff = total * timer_report_ratio + if cutoff < timer_report_ms: + f.write(f"algorithms which ran for longer than {timer_report_ratio}" f" of the total time\n") else: - cutoff = algorithm_report_ms + cutoff = timer_report_ms f.write(f"algorithms which ran for longer than {cutoff}ms\n") data = reader.get_all_timer_provenance() - f.write(f"algorithms which ran for longer than {cutoff}ms\n") - f.write("Name total_time n_runs\n") + f.write("Name total_time n_runs\n") for name, time, count in data: if time > cutoff: f.write(f"{name:35} {time:10.3f} {count}\n") From 557c7fe919ca2785b3d3ef349edf0c3c8bf2938a Mon Sep 17 00:00:00 2001 From: Christian Date: Fri, 14 Oct 2022 09:55:08 +0200 Subject: [PATCH 03/17] flake8 --- .../interface/abstract_spinnaker_base.py | 1 - .../utilities/report_functions/timer_report.py | 17 +++++++++-------- 2 files changed, 9 insertions(+), 9 deletions(-) diff --git a/spinn_front_end_common/interface/abstract_spinnaker_base.py b/spinn_front_end_common/interface/abstract_spinnaker_base.py index 71724a0ec0..5d1df3c009 100644 --- a/spinn_front_end_common/interface/abstract_spinnaker_base.py +++ b/spinn_front_end_common/interface/abstract_spinnaker_base.py @@ -2165,7 +2165,6 @@ def _do_run(self, n_machine_time_steps, n_sync_steps): # reraise exception raise run_e - def _recover_from_error(self, exception): """ :param Exception exception: diff --git a/spinn_front_end_common/utilities/report_functions/timer_report.py b/spinn_front_end_common/utilities/report_functions/timer_report.py index 3ee6cd9d44..ce13d43504 100644 --- a/spinn_front_end_common/utilities/report_functions/timer_report.py +++ b/spinn_front_end_common/utilities/report_functions/timer_report.py @@ -30,6 +30,7 @@ # report file name TIMER_FILENAME = "timer_report.rpt" + def write_timer_report( report_path=None, provenance_path=None, timer_report_ratio=None, timer_report_ms=None, timer_report_to_stdout=None): @@ -62,12 +63,12 @@ def write_timer_report( # create report if timer_report_to_stdout is None: - #try: + try: timer_report_to_stdout = get_config_bool( "Reports", "timer_report_to_stdout") - #except Exception: - # logger.warning("No timer_report_to_stdout found so using False") - # timer_report_to_stdout = False + except Exception: + logger.warning("No timer_report_to_stdout found so using False") + timer_report_to_stdout = False reader = ProvenanceReader(provenance_data_path=provenance_path) if timer_report_to_stdout: @@ -96,7 +97,7 @@ def __write_timer_report(f, reader, timer_report_ratio, timer_report_ms): def __report_category_sums(f, reader): total_on = 0 total_off = 0 - f.write(f"category_name time_on time_off\n") + f.write("category_name time_on time_off\n") for category in TimerCategory: on, off = reader.get_category_timer_sums(category) total_on += on @@ -108,11 +109,11 @@ def __report_category_sums(f, reader): def __report_works_sums(f, reader): - f.write(f"work type time\n") + f.write("work type time\n") for work in TimerWork: time = reader.get_timer_sum_by_work(work) f.write(f"{work.work_name:18} {time:10.3f}ms\n") - f.write(f"\n\n") + f.write("\n\n") def __report_algorithms( @@ -145,4 +146,4 @@ def __report_algorithms( for name, time, count in data: if time > cutoff: f.write(f"{name:35} {time:10.3f} {count}\n") - f.write(f"\n\n") + f.write("\n\n") From 0113b7de3e99d5e53ffc554b65837e01fd2c6544 Mon Sep 17 00:00:00 2001 From: Christian Date: Fri, 14 Oct 2022 10:04:25 +0200 Subject: [PATCH 04/17] docs --- .../report_functions/timer_report.py | 31 +++++++++++++++---- 1 file changed, 25 insertions(+), 6 deletions(-) diff --git a/spinn_front_end_common/utilities/report_functions/timer_report.py b/spinn_front_end_common/utilities/report_functions/timer_report.py index ce13d43504..84a9b2b8c3 100644 --- a/spinn_front_end_common/utilities/report_functions/timer_report.py +++ b/spinn_front_end_common/utilities/report_functions/timer_report.py @@ -44,14 +44,13 @@ def write_timer_report( not using the default. :type provenance_path: None or str :param timer_report_ratio: Percentage of total time and algorithm must take - to be shown. Or None to use cfg if available or default - :type timer_report_ratio; None or float + to be shown. Or None to use cfg if available or default + :type timer_report_ratio: None or float :param timer_report_ms: Time in ms which algorithm must take - to be shown. Or None to use cfg if available or default + to be shown. Or None to use cfg if available or default :type timer_report_ms: None or float - - =None, cutoff_value - + :param timer_report_to_stdout: Flag to say output should go to the terminal. + Or None to use cfg if available or default :rtype: None """ if report_path is None: @@ -85,6 +84,8 @@ def __write_timer_report(f, reader, timer_report_ratio, timer_report_ms): :param ~io.TextIOBase f: file writer :param ProvenanceReader reader: + :type timer_report_ratio: None or float + :type timer_report_ms: None or float """ f.write("Summary timer report\n-------------------\n\n") @@ -95,6 +96,11 @@ def __write_timer_report(f, reader, timer_report_ratio, timer_report_ms): def __report_category_sums(f, reader): + """ + + :param ~io.TextIOBase f: file writer + :param ProvenanceReader reader: + """ total_on = 0 total_off = 0 f.write("category_name time_on time_off\n") @@ -109,6 +115,11 @@ def __report_category_sums(f, reader): def __report_works_sums(f, reader): + """ + + :param ~io.TextIOBase f: file writer + :param ProvenanceReader reader: + """ f.write("work type time\n") for work in TimerWork: time = reader.get_timer_sum_by_work(work) @@ -118,6 +129,14 @@ def __report_works_sums(f, reader): def __report_algorithms( f, reader, total, timer_report_ratio, timer_report_ms): + """ Write time report into the file + + :param ~io.TextIOBase f: file writer + :param ProvenanceReader reader: + :param float total: + :type timer_report_ratio: None or float + :type timer_report_ms: None or float + """ if timer_report_ratio is None: try: timer_report_ratio = get_config_float( From d86f2faf311a9e8e85a5b2b01460c8047db28c4e Mon Sep 17 00:00:00 2001 From: Christian Date: Fri, 14 Oct 2022 10:08:42 +0200 Subject: [PATCH 05/17] fix view --- spinn_front_end_common/interface/provenance/db.sql | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/spinn_front_end_common/interface/provenance/db.sql b/spinn_front_end_common/interface/provenance/db.sql index 1a83071739..ec8ee3ea18 100644 --- a/spinn_front_end_common/interface/provenance/db.sql +++ b/spinn_front_end_common/interface/provenance/db.sql @@ -42,7 +42,7 @@ CREATE TABLE IF NOT EXISTS timer_provenance( skip_reason STRING); CREATE VIEW IF NOT EXISTS full_timer_view AS - SELECT timer_id, category, algorithm, work, machine_on, timer_provenance.time_taken, n_run, n_loop + SELECT timer_id, category, algorithm, work, machine_on, timer_provenance.time_taken, n_run, n_loop, skip_reason FROM timer_provenance ,category_timer_provenance WHERE timer_provenance.category_id = category_timer_provenance.category_id ORDER BY timer_id; From c2994a485fcaf05e6d21cd352fbd89eee4bf4da9 Mon Sep 17 00:00:00 2001 From: Christian Date: Fri, 14 Oct 2022 10:15:17 +0200 Subject: [PATCH 06/17] flake 8 --- .../utilities/report_functions/timer_report.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/spinn_front_end_common/utilities/report_functions/timer_report.py b/spinn_front_end_common/utilities/report_functions/timer_report.py index 84a9b2b8c3..849175bb62 100644 --- a/spinn_front_end_common/utilities/report_functions/timer_report.py +++ b/spinn_front_end_common/utilities/report_functions/timer_report.py @@ -49,7 +49,8 @@ def write_timer_report( :param timer_report_ms: Time in ms which algorithm must take to be shown. Or None to use cfg if available or default :type timer_report_ms: None or float - :param timer_report_to_stdout: Flag to say output should go to the terminal. + :param timer_report_to_stdout: + Flag to say output should go to the terminal. Or None to use cfg if available or default :rtype: None """ From 1ed307939a5cd3f54f7746f1f06366adc8f7da4f Mon Sep 17 00:00:00 2001 From: Christian Date: Fri, 14 Oct 2022 15:23:12 +0200 Subject: [PATCH 07/17] testing/demo timer_report stand alone --- .../report_functions/timer_report.py | 14 ++-- unittests/.gitignore | 3 +- unittests/utilities/.gitignore | 4 ++ unittests/utilities/test_timer_report.py | 65 ++++++++++++++++++ unittests/utilities/timer.sqlite3 | Bin 0 -> 24576 bytes 5 files changed, 81 insertions(+), 5 deletions(-) create mode 100644 unittests/utilities/.gitignore create mode 100644 unittests/utilities/test_timer_report.py create mode 100644 unittests/utilities/timer.sqlite3 diff --git a/spinn_front_end_common/utilities/report_functions/timer_report.py b/spinn_front_end_common/utilities/report_functions/timer_report.py index 849175bb62..748d159821 100644 --- a/spinn_front_end_common/utilities/report_functions/timer_report.py +++ b/spinn_front_end_common/utilities/report_functions/timer_report.py @@ -17,6 +17,7 @@ import os import sys from spinn_utilities.config_holder import get_config_bool, get_config_float +from spinn_utilities.exceptions import SpiNNUtilsException from spinn_utilities.log import FormatAdapter from spinn_front_end_common.data import FecDataView from spinn_front_end_common.interface.provenance import ( @@ -55,10 +56,15 @@ def write_timer_report( :rtype: None """ if report_path is None: - run_dir = FecDataView.get_run_dir_path() - if not run_dir.endswith("run_1"): - logger.warning( - "timer report does not currently work well after a reset") + try: + run_dir = FecDataView.get_run_dir_path() + if not run_dir.endswith("run_1"): + logger.warning( + "timer report does not currently work well after a reset") + except SpiNNUtilsException: + run_dir = os.path.curdir + logger.warning(f"no report_path so writing to {run_dir}") + report_path = os.path.join(run_dir, TIMER_FILENAME) # create report diff --git a/unittests/.gitignore b/unittests/.gitignore index 67b7da1d72..d653e10d14 100644 --- a/unittests/.gitignore +++ b/unittests/.gitignore @@ -1,3 +1,4 @@ TEMP application_generated_data_files -reports \ No newline at end of file +reports +timer_report.rpt \ No newline at end of file diff --git a/unittests/utilities/.gitignore b/unittests/utilities/.gitignore new file mode 100644 index 0000000000..d653e10d14 --- /dev/null +++ b/unittests/utilities/.gitignore @@ -0,0 +1,4 @@ +TEMP +application_generated_data_files +reports +timer_report.rpt \ No newline at end of file diff --git a/unittests/utilities/test_timer_report.py b/unittests/utilities/test_timer_report.py new file mode 100644 index 0000000000..f0f7b5095a --- /dev/null +++ b/unittests/utilities/test_timer_report.py @@ -0,0 +1,65 @@ +# Copyright (c) 2017-2019 The University of Manchester +# +# This program is free software: you can redistribute it and/or modify +# it under the terms of the GNU General Public License as published by +# the Free Software Foundation, either version 3 of the License, or +# (at your option) any later version. +# +# This program is distributed in the hope that it will be useful, +# but WITHOUT ANY WARRANTY; without even the implied warranty of +# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +# GNU General Public License for more details. +# +# You should have received a copy of the GNU General Public License +# along with this program. If not, see . + +import os.path +import unittest +from spinn_utilities.config_holder import set_config +from spinn_utilities.exceptions import InvalidDirectory +from spinn_front_end_common.interface.config_setup import unittest_setup +from spinn_front_end_common.utilities.report_functions.timer_report import\ + write_timer_report +from spinn_front_end_common.data.fec_data_writer import FecDataWriter + + +class TestTimerReport(unittest.TestCase): + + def setUp(cls): + unittest_setup() + + def test_no_params(self): + try: + write_timer_report() + failed = False + except Exception as ex: + self.assertIn("no such DB", str(ex)) + failed = True + self.assertTrue(failed) + + def test_db_only(self): + # make sure there is not run_dir_path so falls back on default + writer = FecDataWriter.setup() + try: + writer.set_run_dir_path("THIS DIRECTORY DOES NOT EXIST") + except InvalidDirectory: + pass + db_path = os.path.join(os.path.dirname(__file__), "timer.sqlite3") + write_timer_report(provenance_path=db_path) + + def test_all_param(self): + db_path = os.path.join(os.path.dirname(__file__), "timer.sqlite3") + report_path = os.path.join(os.path.dirname(__file__), "TEMP") + write_timer_report(report_path=report_path, provenance_path=db_path, + timer_report_ratio=0.5, timer_report_ms=5, + timer_report_to_stdout=False) + + def test_to_screen(self): + db_path = os.path.join(os.path.dirname(__file__), "timer.sqlite3") + report_path = os.path.join(os.path.dirname(__file__), "TEMP") + write_timer_report(provenance_path=db_path, + timer_report_to_stdout=True) + + +if __name__ == '__main__': + unittest.main() diff --git a/unittests/utilities/timer.sqlite3 b/unittests/utilities/timer.sqlite3 new file mode 100644 index 0000000000000000000000000000000000000000..a4481cb5dd46235c0d5148e7800d88c95dcffeee GIT binary patch literal 24576 zcmeHPYiu0V72fr0ymodsJQ4#=;%iLeICdP23C@FbckOH(H-7Fq2{w;qygRlh*`3+U z%qDRmRSC3|A8lGlRY>V0P}))`qE#QXLRCd0pit2Ys8SlCKvC6JEmTNUyivb<@60}C zy+!<~s`jpA@8h0x?!DhV=eu`y&z$(guxcq}RyQ)TMS49;JzlRTOo+!*wa?@6)Zx#0 zT#6Sp&Ko>?tIqyZE_%PnOW5chJK{%6ZDZUMcr9?Z|HdWlcqtwN0fB%(Kp-Fx5C{ka z1Oftq{}lvony8hQwYJtDJ#bJ}4q0kOF%qS(24d03WR&a~itZ(ab`ps<5Io}1;po65 zNy?ToryC1hL{8&bwdONjw1>i+7TNY zA+x!3I#K9{HSFCPjYWyMU(F^AMK*Pfs3sZRJv_`>$70)~G15O}k4{Y;jnzoYIy>uc zVKZ?VbiFN}ovX<;MLs4q)%8&(Yb3IUeo)b5Eva-<3yaRat9Wh&D0q(r1EkA=*#@Z4 z)ZpV7xmCLJ8fuDc%a6QFzgVsUs4J_brclUx^N=Oaq?No~caIetYHX+{BmKkC$|G6J zy3bp|u!lw`qk~xC@z~HvBsN8MMW;w)_vF~nC@hXdM<=^VR7iX>HZ(d&M#m7_X{p>g@DRF?7rWXGPF?p6*f|Ma6{nkZ5!#Wf%9i^EPSVDT0@ z6dnu?gf4uG!<{c_M=e;_8+?~?Z(Z=+z*B*H0(xMJ|L^|ee$~He$=M|jEE&fY`v;AW zHqJM0Xsl~E)A0Rx2iT5`rd|%zW(!rze>)|k(iRz4a?l3aN&fiLza@+4moWq9aq9w zPqXClN3z+piWpEqbzn(NF=F@+W8v)SpIx^xbfj}DL_69ciUtZL*_};+gNJoF1u+u0 z{TIVrR28Mbm zI*Gt_8v9jiR#nm|lB|q4U!3OhUS?D)!L$NzpKK7{*C8h)f0B|Z~+ zN29T_wYwWCG`Qe1nrhBtYzXlri}rav4K02G$vkhA%q(my3+$=6;EuKHpw&jT*y2(d7Y5;FFM(cmJ+Y+& zl7m!|3Ka*OxnNpKh72tdbJ;VDNv~K7-7(fP2BK(sZf<^E8_f360Sy{*cAm_rnhZLalPSL|_7GZ*U90dlaV#>DW*twBU?E9vBwzgQ7UD7l{8F)n|f-Viuv|nEoAxL6MC34<@743 z^tMQ<^l^G=VACWIL$k02G5UM^OnH>=gI2=U;^bOj)$3Nmb{`m9q5xscW-gPVaJm>i zRM9#$jNQi8bF;_T3fKp0Cmj23yLWR8%SUb7*L;zm$*zO6cVmmBOW-R+6WdT0*^^Js8=!={%ZKwJ z`_S6uu;0sEUpCbw;4kWh!*co`U;V-Qz@Cm}6c#L=RDAa1PG_I}LT7h9{%uINpHD@p z(UKzv^D}PqWoohJ!oKq$$Rn0>Y9^PqaO?x0+Y3uvYxDx$E^d4+b}ke_6d=6}0jp&xf^XAAQYn~pk@@L&S##k=*40|b!9R6MV zQfJ=95HV{u;rww0iCVal`X#0AdrwaVs32vIafibY;;!yP zM>*w|Pc=_`h;MfsUgn4CLApponyKJS#g6wboAJJK-Vb}SLktpL{fPSpQ5hv>KFI;Ac`}sBK7OCfpgYkXY-0IHbZsTQQSS| z;dpB zma$Jy9h4}c)aJK#h9CI6$Y0nJhMPXid~{7M?T4ytSJLuAJeQ>h>LS$6&?~aYZI{+S zZlJ_8j#pS4w#O*=e#O}sL(jo8;2v$&(CFYAwj3@X6pMS1y>96$I^q`ThT2iZ;@95A zXSOoeuDEMyTs={8;I*J%RIrq1b-9!N$^DQ#^6+NYj9Q26L=}`Sm3_E zt$}@k2?&UXKtLcM5D*9m1Ox&C0fB%(Kp-Fx5D5IAA+QoTBkhvU>xs|jESfz_Qu-k+ z-1{EQe!Hfs37I0zw0Wm5#VwspLkcmN6J*6pjCs)#Rl!jGEyXd5?G?6i3 z=jI>*Ff2bwQ{BG10=X88XsbiWsC@i8&B&N2?|93r$T&?+uRsC>QyoFR4aI?Hh##Gx zsgB=jMW#a!?Rb%7h^r6tzLD9`F4g-yr3T~=XmUbJGx8Z$)7H{SUxJL|x6dp`>OwPZ zbWk4hvux2OWGk$+mEtt-Fg)29N1}MsawHa%D6|c*99??-zYR(F!DGSJzLgfF`{XpdZJG-LD|HmyEg)@T4{}=iHi{5f3^8azW z$iKZ0P2~UQGq6SeKkg59()dOG{}z7xugL$;-&!E@|8XH_+I~@%|Icoar`P`t{`)<_ z=YtR8xBtQ5Ir!cG3jyMP1|N!tKtLcM5D*9m1Ox&C0fB%(Kp-Fx5D5I|5ojC4o#C`{ zj(^e0IX9n+k_zMFJE%~Ll&nxQtl|$=B{joPmmvQglNN==!4~O=Kc=K|T1wU|RHsSq zS1gp%L7lX+``_=WRNBFC^b=ek1)!ksz5#x8JNiTQmTUb{R(GMye#KvwD%5EhfIV7g z$3Jf9vuax5m4uwqJw=7F-bX=<=ih(h@_r~pr~DY){iHwh g-}Kjg407w~6zu9itWX9me^4~=oeNhjof&!VUjT?rRsaA1 literal 0 HcmV?d00001 From a437528880fbf419d65169147d0a1fdaeda38089 Mon Sep 17 00:00:00 2001 From: Christian Date: Fri, 14 Oct 2022 15:57:37 +0200 Subject: [PATCH 08/17] flake8 --- unittests/utilities/test_timer_report.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/unittests/utilities/test_timer_report.py b/unittests/utilities/test_timer_report.py index f0f7b5095a..de54feeb69 100644 --- a/unittests/utilities/test_timer_report.py +++ b/unittests/utilities/test_timer_report.py @@ -15,7 +15,6 @@ import os.path import unittest -from spinn_utilities.config_holder import set_config from spinn_utilities.exceptions import InvalidDirectory from spinn_front_end_common.interface.config_setup import unittest_setup from spinn_front_end_common.utilities.report_functions.timer_report import\ @@ -56,7 +55,6 @@ def test_all_param(self): def test_to_screen(self): db_path = os.path.join(os.path.dirname(__file__), "timer.sqlite3") - report_path = os.path.join(os.path.dirname(__file__), "TEMP") write_timer_report(provenance_path=db_path, timer_report_to_stdout=True) From 2fa7c6f28603d9227d809b1775167fefa54bfbb9 Mon Sep 17 00:00:00 2001 From: Christian Date: Fri, 14 Oct 2022 16:37:05 +0200 Subject: [PATCH 09/17] close category even if not run --- spinn_front_end_common/interface/abstract_spinnaker_base.py | 1 + 1 file changed, 1 insertion(+) diff --git a/spinn_front_end_common/interface/abstract_spinnaker_base.py b/spinn_front_end_common/interface/abstract_spinnaker_base.py index 5d1df3c009..8a7a6d43a4 100644 --- a/spinn_front_end_common/interface/abstract_spinnaker_base.py +++ b/spinn_front_end_common/interface/abstract_spinnaker_base.py @@ -1694,6 +1694,7 @@ def _execute_system_data_specification(self): with FecTimer( "Execute system data specification", TimerWork.OTHER) as timer: if timer.skip_if_virtual_board(): + FecTimer.end_category(TimerCategory.DATA_GENERATION) return None execute_system_data_specs() FecTimer.end_category(TimerCategory.DATA_GENERATION) From 7d6a96f9a10818ec45c2576a88fec347a96dbeae Mon Sep 17 00:00:00 2001 From: Christian Date: Fri, 14 Oct 2022 17:15:32 +0200 Subject: [PATCH 10/17] stop rat looking at files created during tests --- .ratexcludes | 2 ++ 1 file changed, 2 insertions(+) diff --git a/.ratexcludes b/.ratexcludes index 8acb1c02ea..4708f2f046 100644 --- a/.ratexcludes +++ b/.ratexcludes @@ -17,3 +17,5 @@ **/PACMAN/** **/DataSpecification/** **/spalloc/** +TEMP +**/timer_report.rpt From 02b543d6ec7faec05b9f44238b7329cc140c25d1 Mon Sep 17 00:00:00 2001 From: Christian Date: Fri, 14 Oct 2022 17:24:17 +0200 Subject: [PATCH 11/17] better (rat excluded) user defined rpt file --- .ratexcludes | 2 +- unittests/utilities/.gitignore | 4 +--- unittests/utilities/test_timer_report.py | 2 +- 3 files changed, 3 insertions(+), 5 deletions(-) diff --git a/.ratexcludes b/.ratexcludes index 4708f2f046..56bd12fccf 100644 --- a/.ratexcludes +++ b/.ratexcludes @@ -17,5 +17,5 @@ **/PACMAN/** **/DataSpecification/** **/spalloc/** -TEMP +**/my_timer.rpt **/timer_report.rpt diff --git a/unittests/utilities/.gitignore b/unittests/utilities/.gitignore index d653e10d14..0dc1eb5562 100644 --- a/unittests/utilities/.gitignore +++ b/unittests/utilities/.gitignore @@ -1,4 +1,2 @@ -TEMP -application_generated_data_files -reports +my_timer.rpt timer_report.rpt \ No newline at end of file diff --git a/unittests/utilities/test_timer_report.py b/unittests/utilities/test_timer_report.py index de54feeb69..003ba43292 100644 --- a/unittests/utilities/test_timer_report.py +++ b/unittests/utilities/test_timer_report.py @@ -48,7 +48,7 @@ def test_db_only(self): def test_all_param(self): db_path = os.path.join(os.path.dirname(__file__), "timer.sqlite3") - report_path = os.path.join(os.path.dirname(__file__), "TEMP") + report_path = os.path.join(os.path.dirname(__file__), "my_timer.rpt") write_timer_report(report_path=report_path, provenance_path=db_path, timer_report_ratio=0.5, timer_report_ms=5, timer_report_to_stdout=False) From c06a48a5feaf8cc4247518c63fec8c0c11253979 Mon Sep 17 00:00:00 2001 From: "Christian Y. Brenninkmeijer" Date: Mon, 17 Oct 2022 11:16:39 +0100 Subject: [PATCH 12/17] fix query --- .../interface/provenance/provenance_reader.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/spinn_front_end_common/interface/provenance/provenance_reader.py b/spinn_front_end_common/interface/provenance/provenance_reader.py index a3f560e3c7..e3a71eee1e 100644 --- a/spinn_front_end_common/interface/provenance/provenance_reader.py +++ b/spinn_front_end_common/interface/provenance/provenance_reader.py @@ -183,7 +183,7 @@ def get_timer_provenance(self, algorithm): FROM timer_provenance WHERE algorithm LIKE ? """ - return self.run_query(query) + return self.run_query(query, [algorithm]) def get_all_timer_provenance(self): """ From add24567442dc899d52ea0f2be82a6e15d94e3cf Mon Sep 17 00:00:00 2001 From: "Christian Y. Brenninkmeijer" Date: Mon, 17 Oct 2022 11:55:16 +0100 Subject: [PATCH 13/17] move report to timestamp dir and expose path --- .../report_functions/timer_report.py | 20 +++++++++++-------- 1 file changed, 12 insertions(+), 8 deletions(-) diff --git a/spinn_front_end_common/utilities/report_functions/timer_report.py b/spinn_front_end_common/utilities/report_functions/timer_report.py index 748d159821..05f29b4ebb 100644 --- a/spinn_front_end_common/utilities/report_functions/timer_report.py +++ b/spinn_front_end_common/utilities/report_functions/timer_report.py @@ -55,17 +55,17 @@ def write_timer_report( Or None to use cfg if available or default :rtype: None """ + run_dir = FecDataView.get_run_dir_path() + if not run_dir.endswith("run_1"): + logger.warning( + "timer report does not currently work well after a reset") + if report_path is None: try: - run_dir = FecDataView.get_run_dir_path() - if not run_dir.endswith("run_1"): - logger.warning( - "timer report does not currently work well after a reset") + report_path = timer_report_file() except SpiNNUtilsException: - run_dir = os.path.curdir - logger.warning(f"no report_path so writing to {run_dir}") - - report_path = os.path.join(run_dir, TIMER_FILENAME) + report_path = os.path.join(os.path.curdir, TIMER_FILENAME) + logger.warning(f"no report_path so writing to {report_path}") # create report if timer_report_to_stdout is None: @@ -85,6 +85,10 @@ def write_timer_report( __write_timer_report( f, reader, timer_report_ratio, timer_report_ms) +def timer_report_file(): + report_dir = FecDataView.get_timestamp_dir_path() + return os.path.join(report_dir, TIMER_FILENAME) + def __write_timer_report(f, reader, timer_report_ratio, timer_report_ms): """ Write time report into the file From ca69dd61bf7e22133f87f84532ae983f2884c7f9 Mon Sep 17 00:00:00 2001 From: "Christian Y. Brenninkmeijer" Date: Mon, 17 Oct 2022 12:18:41 +0100 Subject: [PATCH 14/17] fix for no path in view --- .../utilities/report_functions/timer_report.py | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/spinn_front_end_common/utilities/report_functions/timer_report.py b/spinn_front_end_common/utilities/report_functions/timer_report.py index 05f29b4ebb..d3297fa322 100644 --- a/spinn_front_end_common/utilities/report_functions/timer_report.py +++ b/spinn_front_end_common/utilities/report_functions/timer_report.py @@ -55,10 +55,14 @@ def write_timer_report( Or None to use cfg if available or default :rtype: None """ - run_dir = FecDataView.get_run_dir_path() - if not run_dir.endswith("run_1"): - logger.warning( - "timer report does not currently work well after a reset") + try: + run_dir = FecDataView.get_run_dir_path() + if not run_dir.endswith("run_1"): + logger.warning( + "timer report does not currently work well after a reset") + except SpiNNUtilsException: + # Only to do a temporary warning so ignore + pass if report_path is None: try: From 8e76fbdba696c3d909c242347ab73c5a7229b8b1 Mon Sep 17 00:00:00 2001 From: "Christian Y. Brenninkmeijer" Date: Mon, 17 Oct 2022 12:41:46 +0100 Subject: [PATCH 15/17] The report_dir_path is toed 2 blank lines --- .../utilities/report_functions/timer_report.py | 1 + 1 file changed, 1 insertion(+) diff --git a/spinn_front_end_common/utilities/report_functions/timer_report.py b/spinn_front_end_common/utilities/report_functions/timer_report.py index d3297fa322..2d3a89101f 100644 --- a/spinn_front_end_common/utilities/report_functions/timer_report.py +++ b/spinn_front_end_common/utilities/report_functions/timer_report.py @@ -89,6 +89,7 @@ def write_timer_report( __write_timer_report( f, reader, timer_report_ratio, timer_report_ms) + def timer_report_file(): report_dir = FecDataView.get_timestamp_dir_path() return os.path.join(report_dir, TIMER_FILENAME) From 3e1965c84cb36d759f4abafd167be70dcb7e7f6f Mon Sep 17 00:00:00 2001 From: "Christian Y. Brenninkmeijer" Date: Mon, 17 Oct 2022 13:24:41 +0100 Subject: [PATCH 16/17] put back extected text output for this call --- .../interface/provenance/provenance_reader.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/spinn_front_end_common/interface/provenance/provenance_reader.py b/spinn_front_end_common/interface/provenance/provenance_reader.py index e3a71eee1e..eedccfb48b 100644 --- a/spinn_front_end_common/interface/provenance/provenance_reader.py +++ b/spinn_front_end_common/interface/provenance/provenance_reader.py @@ -232,7 +232,9 @@ def get_run_time_of_BufferExtractor(self): like %BufferExtractor description_name: value :rtype: str """ - return self.get_timer_provenance("%BufferExtractor") + return "\n".join( + f"{row[0]}: {row[1]}" + for row in self.get_timer_provenance("%BufferExtractor")) def get_provenance_for_router(self, x, y): """ From 81b693fd7e7cd2e20b6cab5a2a542f858ea91b73 Mon Sep 17 00:00:00 2001 From: "Christian Y. Brenninkmeijer" Date: Mon, 17 Oct 2022 13:46:27 +0100 Subject: [PATCH 17/17] revert changes --- .../interface/provenance/provenance_reader.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/spinn_front_end_common/interface/provenance/provenance_reader.py b/spinn_front_end_common/interface/provenance/provenance_reader.py index eedccfb48b..b78a10df71 100644 --- a/spinn_front_end_common/interface/provenance/provenance_reader.py +++ b/spinn_front_end_common/interface/provenance/provenance_reader.py @@ -183,7 +183,9 @@ def get_timer_provenance(self, algorithm): FROM timer_provenance WHERE algorithm LIKE ? """ - return self.run_query(query, [algorithm]) + return "\n".join( + f"{row[0]}: {row[1]}" + for row in self.run_query(query, [algorithm])) def get_all_timer_provenance(self): """ @@ -232,9 +234,7 @@ def get_run_time_of_BufferExtractor(self): like %BufferExtractor description_name: value :rtype: str """ - return "\n".join( - f"{row[0]}: {row[1]}" - for row in self.get_timer_provenance("%BufferExtractor")) + return self.get_timer_provenance("%BufferExtractor") def get_provenance_for_router(self, x, y): """