From 2564eb3af937127aeab4c8a6b7c928e0bed582c7 Mon Sep 17 00:00:00 2001
From: Zack Cerza <zack@redhat.com>
Date: Tue, 2 Feb 2016 16:28:00 -0700
Subject: [PATCH] Add teuthology.timer

Signed-off-by: Zack Cerza <zack@redhat.com>
---
 teuthology/test/test_timer.py |  83 +++++++++++++++++++++++++
 teuthology/timer.py           | 114 ++++++++++++++++++++++++++++++++++
 2 files changed, 197 insertions(+)
 create mode 100644 teuthology/test/test_timer.py
 create mode 100644 teuthology/timer.py

diff --git a/teuthology/test/test_timer.py b/teuthology/test/test_timer.py
new file mode 100644
index 0000000000..6034d8abe7
--- /dev/null
+++ b/teuthology/test/test_timer.py
@@ -0,0 +1,83 @@
+from teuthology import timer
+
+from mock import MagicMock, patch
+from time import time
+
+
+class TestTimer(object):
+    def test_data_empty(self):
+        self.timer = timer.Timer()
+        assert self.timer.data == dict()
+
+    def test_data_one_mark(self):
+        self.timer = timer.Timer()
+        # Avoid failing if ~1ms elapses between these two calls
+        self.timer.precision = 2
+        self.timer.mark()
+        assert len(self.timer.data['marks']) == 1
+        assert self.timer.data['marks'][0]['interval'] == 0
+        assert self.timer.data['marks'][0]['message'] == ''
+
+    def test_data_five_marks(self):
+        self.timer = timer.Timer()
+        for i in range(5):
+            self.timer.mark(str(i))
+        assert len(self.timer.data['marks']) == 5
+        assert [m['message'] for m in self.timer.data['marks']] == \
+            ['0', '1', '2', '3', '4']
+
+    def test_intervals(self):
+        fake_time = MagicMock()
+        with patch('teuthology.timer.time.time', fake_time):
+            self.timer = timer.Timer()
+            now = start_time = fake_time.return_value = time()
+            intervals = [0, 1, 1, 2, 3, 5, 8]
+            for i in intervals:
+                now += i
+                fake_time.return_value = now
+                self.timer.mark(str(i))
+
+        summed_intervals = map(lambda x: sum(intervals[:x + 1]),
+                               range(len(intervals)))
+        result_intervals = [m['interval'] for m in self.timer.data['marks']]
+        assert result_intervals == summed_intervals
+        assert self.timer.data['start'] == \
+            self.timer.get_datetime_string(start_time)
+        assert self.timer.data['end'] == \
+            self.timer.get_datetime_string(start_time + summed_intervals[-1])
+        assert [m['message'] for m in self.timer.data['marks']] == \
+            map(str, intervals)
+        assert self.timer.data['elapsed'] == summed_intervals[-1]
+
+    def test_write(self):
+        _path = '/path'
+        _safe_dump = MagicMock(name='safe_dump')
+        with patch('teuthology.timer.yaml.safe_dump', _safe_dump):
+            with patch('teuthology.timer.file') as _file:
+                _file.return_value = MagicMock(spec=file)
+                self.timer = timer.Timer(path=_path)
+                assert self.timer.path == _path
+                self.timer.write()
+                _file.assert_called_once_with(_path, 'w')
+                _safe_dump.assert_called_once_with(
+                    dict(),
+                    _file.return_value.__enter__.return_value,
+                    default_flow_style=False,
+                )
+
+    def test_sync(self):
+        _path = '/path'
+        _safe_dump = MagicMock(name='safe_dump')
+        with patch('teuthology.timer.yaml.safe_dump', _safe_dump):
+            with patch('teuthology.timer.file') as _file:
+                _file.return_value = MagicMock(spec=file)
+                self.timer = timer.Timer(path=_path, sync=True)
+                assert self.timer.path == _path
+                assert self.timer.sync is True
+                self.timer.mark()
+                _file.assert_called_once_with(_path, 'w')
+                _safe_dump.assert_called_once_with(
+                    self.timer.data,
+                    _file.return_value.__enter__.return_value,
+                    default_flow_style=False,
+                )
diff --git a/teuthology/timer.py b/teuthology/timer.py
new file mode 100644
index 0000000000..6214856826
--- /dev/null
+++ b/teuthology/timer.py
@@ -0,0 +1,114 @@
+import logging
+import time
+import yaml
+
+from datetime import datetime
+
+log = logging.getLogger(__name__)
+
+
+class Timer(object):
+    """
+    A class that records timing data.
+
+    It was created in order to record time intervals between the execution of
+    different tasks' enter and exit methods.
+    """
+    # How many decimal places to use for time intervals
+    precision = 3
+    # The format to use for date-time strings
+    datetime_format = '%Y-%m-%d_%H:%M:%S'
+
+    def __init__(self, path=None, sync=False):
+        """
+        :param path:       A path to a file to be written when self.write() is
+                           called. The file will contain self.data in yaml
+                           format.
+        :param sync:       Whether or not to call self.write() from within
+                           self.mark()
+        """
+        if sync and not path:
+            raise ValueError(
+                "When providing sync=True, a path must be specified!")
+        self.path = path
+        self.sync = sync
+        self.marks = list()
+        self.start_time = None
+        self.start_string = None
+
+    def mark(self, message=''):
+        """
+        Create a time mark
+
+        If necessary, call self._mark_start() to begin time-keeping. Then,
+        create a new entry in self.marks with the message provided, along with
+        the time elapsed in seconds since time-keeping began.
+        """
+        if self.start_time is None:
+            self._mark_start(message)
+        interval = round(time.time() - self.start_time, self.precision)
+        mark = dict(
+            interval=interval,
+            message=message,
+        )
+        self.marks.append(mark)
+        if self.sync:
+            self.write()
+
+    def _mark_start(self, message):
+        """
+        Create the initial time mark
+        """
+        self.start_time = time.time()
+        self.start_string = self.get_datetime_string(self.start_time)
+
+    def get_datetime_string(self, time):
+        """
+        Return a human-readable timestamp in UTC
+
+        :param time: Time in seconds; like from time.time()
+        """
+        _datetime = datetime.utcfromtimestamp(time)
+        return datetime.strftime(
+            _datetime,
+            self.datetime_format,
+        )
+
+    @property
+    def data(self):
+        """
+        Return an object similar to::
+
+            {'start': '2016-02-02_23:19:51',
+             'elapsed': 10.65,
+             'end': '2016-02-02_23:20:01',
+             'marks': [
+                 {'message': 'event 1', 'interval': 0.0},
+                 {'message': 'event 2', 'interval': 8.58},
+                 {'message': 'event 3', 'interval': 10.65}
+             ],
+             }
+
+        'start' and 'end' times are in UTC.
+        """
+        if not self.start_string:
+            return dict()
+        if len(self.marks) <= 1:
+            end_interval = 0
+        else:
+            end_interval = self.marks[-1]['interval']
+        end_time = self.start_time + end_interval
+        result = dict(
+            start=self.start_string,
+            marks=self.marks,
+            end=self.get_datetime_string(end_time),
+            elapsed=end_interval,
+        )
+        return result
+
+    def write(self):
+        try:
+            with file(self.path, 'w') as f:
+                yaml.safe_dump(self.data, f, default_flow_style=False)
+        except Exception:
+            log.exception("Failed to write timing.yaml !")
-- 
2.39.5