Timer report

.ratexcludes

@@ -17,3 +17,5 @@
 **/PACMAN/**
 **/DataSpecification/**
 **/spalloc/**
+**/my_timer.rpt
+**/timer_report.rpt

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
 

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;

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):

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

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

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"]

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 <http://www.gnu.org/licenses/>.
+
+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")

unittests/.gitignore

@@ -1,3 +1,4 @@
 TEMP
 application_generated_data_files
-reports
+reports
+timer_report.rpt

unittests/utilities/.gitignore

@@ -0,0 +1,2 @@
+my_timer.rpt
+timer_report.rpt

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 <http://www.gnu.org/licenses/>.
+
+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()