Merge pull request #3254 from cpennington/timer-logging

[EV-63] Add the ability to log timing information to local logs for c…

playbooks/callback_plugins/datadog_tasks_timing.py

-import os
-import datetime
-import time
-import logging
-import datadog
-import sys
-
-logging.basicConfig(level=logging.INFO, stream=sys.stdout)
-logging.getLogger("requests").setLevel(logging.WARNING)
-logging.getLogger("dd").setLevel(logging.WARNING)
-logger = logging.getLogger(__name__)
-
-"""
-Originally written by 'Jharrod LaFon'
-#https://github.com/jlafon/ansible-profile/blob/master/callback_plugins/profile_tasks.py
-
-"""
-
-
-class CallbackModule(object):
-
-    """
-    Ansible plugin get the time of each task and total time
-    to run the complete playbook
-    """
-    def __init__(self):
-        self.stats = {}
-        self.current_task = None
-        self.playbook_name = None
-        self.datadog_api_key = os.getenv('DATADOG_API_KEY')
-        self.datadog_api_initialized = False
-
-        if self.datadog_api_key:
-            datadog.initialize(api_key=self.datadog_api_key,
-                               app_key=None)
-            self.datadog_api_initialized = True
-
-    def clean_tag_value(self, value):
-        return value.replace(" | ", ".").replace(" ", "-").lower()
-
-    def playbook_on_play_start(self, pattern):
-            self.playbook_name, _ = os.path.splitext(
-                os.path.basename(self.play.playbook.filename)
-            )
-
-    def playbook_on_task_start(self, name, is_conditional):
-        """
-        Logs the start of each task
-        """
-
-        if self.current_task is not None:
-            # Record the running time of the last executed task
-            self.stats[self.current_task] = (time.time(), time.time() - self.stats[self.current_task])
-
-        # Record the start time of the current task
-        self.current_task = name
-        self.stats[self.current_task] = time.time()
-
-    def playbook_on_stats(self, stats):
-        """
-        Prints the timing of each task and total time to
-        run the complete playbook
-        """
-        # Record the timing of the very last task, we use it here, because we
-        # don't have stop task function by default
-        if self.current_task is not None:
-            self.stats[self.current_task] = (time.time(), time.time() - self.stats[self.current_task])
-
-        # Sort the tasks by their running time
-        results = sorted(self.stats.items(),
-                         key=lambda value: value[1][1], reverse=True)
-
-        # Total time to run the complete playbook
-        total_seconds = sum([x[1][1] for x in self.stats.items()])
-          
-        # send the metric to datadog
-        if self.datadog_api_initialized:
-            datadog_tasks_metrics = []
-            for name, points in results:
-                datadog_tasks_metrics.append({'metric': 'edx.ansible.task_duration',
-                                              'date_happened': points[0],
-                                              'points': points[1],
-                                              'tags': ['task:{0}'.format(self.clean_tag_value(name)),
-                                                       'playbook:{0}'.format(self.clean_tag_value(self.playbook_name))
-                                                       ]
-                                              }
-                                             )
-            try:
-                datadog.api.Metric.send(datadog_tasks_metrics)
-                datadog.api.Metric.send(metric="edx.ansible.playbook_duration",
-                                        date_happened=time.time(),
-                                        points=total_seconds,
-                                        tags=["playbook:{0}".format(self.clean_tag_value(self.playbook_name))]
-                                        )
-            except Exception as ex:
-                logger.error(ex.message)
-
-        # Log the time of each task
-        for name, elapsed in results[:10]:
-            logger.info(
-                "{0:-<80}{1:->8}".format(
-                    '{0} '.format(name),
-                    ' {0:.02f}s'.format(elapsed[1]),
-                )
-            )
-
-        logger.info("\nPlaybook {0} finished: {1}, {2} total tasks.  {3} elapsed. \n".format(
-                self.playbook_name,
-                time.asctime(),
-                len(self.stats.items()),
-                datetime.timedelta(seconds=(int(total_seconds)))
-                )
-          )

playbooks/callback_plugins/task_timing.py

+from datetime import datetime, timedelta
+import json
+import logging
+import os
+from os.path import splitext, basename, exists, dirname
+import sys
+import time
+
+try:
+    from ansible.plugins.callback import CallbackBase
+except ImportError:
+    # Support Ansible 1.9.x
+    CallbackBase = object
+
+import datadog
+
+logging.basicConfig(level=logging.INFO, stream=sys.stdout)
+logging.getLogger("requests").setLevel(logging.WARNING)
+logging.getLogger("dd").setLevel(logging.WARNING)
+LOGGER = logging.getLogger(__name__)
+
+"""
+Originally written by 'Jharrod LaFon'
+#https://github.com/jlafon/ansible-profile/blob/master/callback_plugins/profile_tasks.py
+
+"""
+
+ANSIBLE_TIMER_LOG = os.environ.get('ANSIBLE_TIMER_LOG')
+
+
+class Timestamp(object):
+    """
+    A class for capturing start, end and duration for an action.
+    """
+    def __init__(self):
+        self.start = datetime.utcnow()
+        self.end = None
+
+    def stop(self):
+        """
+        Record the end time of the timed period.
+        """
+        self.end = datetime.utcnow()
+
+    @property
+    def duration(self):
+        """
+        Return the duration that this Timestamp covers.
+        """
+        return self.end - self.start
+
+
+# This class only has a single method (which would ordinarily make it a
+# candidate to be turned into a function). However, the TimingLoggers are
+# instanciated once when ansible starts up, and then called for every play.
+class TimingLogger(object):
+    """
+    Base-class for logging timing about ansible tasks and plays.
+    """
+    def log_play(self, playbook_name, playbook_timestamp, results):
+        """
+        Record the timing results of an ansible play.
+
+        Arguments:
+            playbook_name: the name of the playbook being logged.
+            playbook_timestamp (Timestamp): the timestamps measuring how
+                long the play took.
+            results (dict(string -> Timestamp)): a dict mapping task names
+                to Timestamps that measure how long each task took.
+        """
+        pass
+
+
+class DatadogTimingLogger(TimingLogger):
+    """
+    Record ansible task and play timing to Datadog.
+
+    Requires that the environment variable DATADOG_API_KEY be set in order
+    to log any data.
+    """
+    def __init__(self):
+        super(DatadogTimingLogger, self).__init__()
+
+        self.datadog_api_key = os.getenv('DATADOG_API_KEY')
+        self.datadog_api_initialized = False
+
+        if self.datadog_api_key:
+            datadog.initialize(
+                api_key=self.datadog_api_key,
+                app_key=None
+            )
+            self.datadog_api_initialized = True
+
+    def clean_tag_value(self, value):
+        """
+        Remove any characters that aren't allowed in Datadog tags.
+
+        Arguments:
+            value: the string to be cleaned.
+        """
+        return value.replace(" | ", ".").replace(" ", "-").lower()
+
+    def log_play(self, playbook_name, playbook_timestamp, results):
+        if not self.datadog_api_initialized:
+            return
+
+        datadog_tasks_metrics = []
+        for name, timestamp in results.items():
+            datadog_tasks_metrics.append({
+                'metric': 'edx.ansible.task_duration',
+                'date_happened': time.mktime(timestamp.start.timetuple()),
+                'points': timestamp.duration.total_seconds(),
+                'tags': [
+                    'task:{0}'.format(self.clean_tag_value(name)),
+                    'playbook:{0}'.format(self.clean_tag_value(playbook_name))
+                ]
+            })
+        try:
+            datadog.api.Metric.send(datadog_tasks_metrics)
+            datadog.api.Metric.send(
+                metric="edx.ansible.playbook_duration",
+                date_happened=time.mktime(playbook_timestamp.start.timetuple()),
+                points=playbook_timestamp.duration.total_seconds(),
+                tags=["playbook:{0}".format(self.clean_tag_value(playbook_name))]
+            )
+        except Exception:
+            LOGGER.exception("Failed to log timing data to datadog")
+
+
+class JsonTimingLogger(TimingLogger):
+    """
+    Record task and play timing to a local file in a JSON format.
+
+    Requires that the environment variable ANSIBLE_TIMER_LOG be set in order
+    to log any data. This specifies the file that timing data should be logged
+    to. That variable can include strftime interpolation variables,
+    which will be replaced with the start time of the play.
+    """
+    def log_play(self, playbook_name, playbook_timestamp, results):
+        # N.B. This is intended to provide a consistent interface and message
+        # format across all of Open edX tooling, so it deliberately eschews
+        # standard python logging infrastructure.
+        if ANSIBLE_TIMER_LOG is None:
+            return
+
+        messages = []
+        for name, timestamp in results.items():
+            messages.append({
+                'task': name,
+                'playbook': playbook_name,
+                'started_at': timestamp.start.isoformat(),
+                'ended_at': timestamp.end.isoformat(),
+                'duration': timestamp.duration.total_seconds(),
+            })
+
+        messages.append({
+            'playbook': playbook_name,
+            'started_at': playbook_timestamp.start.isoformat(),
+            'ended_at': playbook_timestamp.end.isoformat(),
+            'duration': playbook_timestamp.duration.total_seconds(),
+        })
+
+        log_path = playbook_timestamp.start.strftime(ANSIBLE_TIMER_LOG)
+
+        try:
+            if not exists(dirname(log_path)):
+                os.makedirs(dirname(log_path))
+
+            with open(log_path, 'a') as outfile:
+                for log_message in messages:
+                    json.dump(
+                        log_message,
+                        outfile,
+                        separators=(',', ':'),
+                        sort_keys=True,
+                    )
+                    outfile.write('\n')
+        except Exception:
+            LOGGER.exception("Unable to write json timing log messages")
+
+
+class LoggingTimingLogger(TimingLogger):
+    """
+    Log timing information for the play and the top 10 tasks to stdout.
+    """
+    def log_play(self, playbook_name, playbook_timestamp, results):
+
+        # Sort the tasks by their running time
+        sorted_results = sorted(
+            results.items(),
+            key=lambda (task, timestamp): timestamp.duration,
+            reverse=True
+        )
+
+        for name, timestamp in sorted_results[:10]:
+            LOGGER.info(
+                "{0:-<80}{1:->8}".format(
+                    '{0} '.format(name),
+                    ' {0:.02f}s'.format(timestamp.duration.total_seconds()),
+                )
+            )
+
+        LOGGER.info(
+            "\nPlaybook %s finished: %s, %d total tasks.  %s elapsed. \n",
+            playbook_name,
+            playbook_timestamp.end,
+            len(results),
+            playbook_timestamp.duration,
+        )
+
+
+class CallbackModule(CallbackBase):
+
+    """
+    Ansible plugin get the time of each task and total time
+    to run the complete playbook
+    """
+    def __init__(self):
+        self.stats = {}
+        self.current_task = None
+        self.playbook_name = None
+        self.playbook_timestamp = None
+        self.play = None
+
+        self.loggers = [
+            DatadogTimingLogger(),
+            LoggingTimingLogger(),
+            JsonTimingLogger(),
+        ]
+
+    def v2_playbook_on_play_start(self, play):
+        self.play = play
+        super(CallbackModule, self).v2_playbook_on_play_start(play)
+
+    def playbook_on_play_start(self, pattern):
+        """
+        Record the start of a play.
+        """
+        self.playbook_name, _ = splitext(
+            basename(self.play.playbook.filename)
+        )
+        self.playbook_timestamp = Timestamp()
+
+    def playbook_on_task_start(self, name, is_conditional):
+        """
+        Logs the start of each task
+        """
+
+        if self.current_task is not None:
+            # Record the running time of the last executed task
+            self.stats[self.current_task].stop()
+
+        # Record the start time of the current task
+        self.current_task = name
+        self.stats[self.current_task] = Timestamp()
+
+    def playbook_on_stats(self, stats):
+        """
+        Prints the timing of each task and total time to
+        run the complete playbook
+        """
+        # Record the timing of the very last task, we use it here, because we
+        # don't have stop task function by default
+        if self.current_task is not None:
+            self.stats[self.current_task].stop()
+
+        self.playbook_timestamp.stop()
+
+        for logger in self.loggers:
+            logger.log_play(
+                self.playbook_name,
+                self.playbook_timestamp,
+                self.stats,
+            )