diff --git a/.ratexcludes b/.ratexcludes index 8acb1c02ea..56bd12fccf 100644 --- a/.ratexcludes +++ b/.ratexcludes @@ -17,3 +17,5 @@ **/PACMAN/** **/DataSpecification/** **/spalloc/** +**/my_timer.rpt +**/timer_report.rpt diff --git a/spinn_front_end_common/interface/abstract_spinnaker_base.py b/spinn_front_end_common/interface/abstract_spinnaker_base.py index f11fac6a12..968616a47e 100644 --- a/spinn_front_end_common/interface/abstract_spinnaker_base.py +++ b/spinn_front_end_common/interface/abstract_spinnaker_base.py @@ -110,7 +110,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 ( @@ -679,12 +679,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,14 @@ def _execute_system_data_specification(self): Runs, times and logs the execute_system_data_specs if required """ + FecTimer.start_category(TimerCategory.DATA_GENERATION) 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) def _execute_load_system_executable_images(self): """ @@ -2347,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. @@ -2375,6 +2385,7 @@ def stop(self): # shut down the machine properly self._shutdown() + 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/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; 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..b78a10df71 100644 --- a/spinn_front_end_common/interface/provenance/provenance_reader.py +++ b/spinn_front_end_common/interface/provenance/provenance_reader.py @@ -187,6 +187,23 @@ def get_timer_provenance(self, algorithm): f"{row[0]}: {row[1]}" for row in self.run_query(query, [algorithm])) + 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): """ Gets the algorithm running times from the last run. If an algorithm is 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/__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..2d3a89101f --- /dev/null +++ b/spinn_front_end_common/utilities/report_functions/timer_report.py @@ -0,0 +1,184 @@ +# 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 +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 ( + 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, timer_report_ratio=None, + timer_report_ms=None, timer_report_to_stdout=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 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 + :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. + Or None to use cfg if available or default + :rtype: 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") + except SpiNNUtilsException: + # Only to do a temporary warning so ignore + pass + + if report_path is None: + try: + report_path = timer_report_file() + except SpiNNUtilsException: + 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: + 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) + if timer_report_to_stdout: + __write_timer_report( + 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 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 + + :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") + + total = __report_category_sums(f, reader) + __report_works_sums(f, reader) + __report_algorithms( + f, reader, total, 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") + 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): + """ + + :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) + f.write(f"{work.work_name:18} {time:10.3f}ms\n") + f.write("\n\n") + + +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( + "Reports", "timer_report_ratio") + except Exception: + logger.warning("No timer_report_ratio so using 1%") + timer_report_ratio = 0.01 + + if timer_report_ms is None: + try: + timer_report_ms = get_config_float( + "Reports", "timer_report_ms") + except Exception: + logger.warning("No timer_report_ms so using 10ms") + timer_report_ms = 1000 + + 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 = timer_report_ms + f.write(f"algorithms which ran for longer than {cutoff}ms\n") + data = reader.get_all_timer_provenance() + 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("\n\n") 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..0dc1eb5562 --- /dev/null +++ b/unittests/utilities/.gitignore @@ -0,0 +1,2 @@ +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 new file mode 100644 index 0000000000..003ba43292 --- /dev/null +++ b/unittests/utilities/test_timer_report.py @@ -0,0 +1,63 @@ +# 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.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__), "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) + + def test_to_screen(self): + db_path = os.path.join(os.path.dirname(__file__), "timer.sqlite3") + 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 0000000000..a4481cb5dd Binary files /dev/null and b/unittests/utilities/timer.sqlite3 differ