diff --git a/pavelib/assets.py b/pavelib/assets.py
index 269b6b0a9a411761ff7c091bc5feb07a540d977f..7765585078b5e9bfbad6701765d332bd1d86639d 100644
--- a/pavelib/assets.py
+++ b/pavelib/assets.py
@@ -17,6 +17,7 @@ from watchdog.events import PatternMatchingEventHandler
from .utils.envs import Env
from .utils.cmd import cmd, django_cmd
+from .utils.timer import timed
from openedx.core.djangoapps.theming.paver_helpers import get_theme_paths
@@ -383,6 +384,7 @@ def coffeescript_files():
@task
@no_help
+@timed
def compile_coffeescript(*files):
"""
Compile CoffeeScript to JavaScript.
@@ -403,6 +405,7 @@ def compile_coffeescript(*files):
('debug', 'd', 'Debug mode'),
('force', '', 'Force full compilation'),
])
+@timed
def compile_sass(options):
"""
Compile Sass to CSS. If command is called without any arguments, it will
@@ -682,6 +685,7 @@ def execute_compile_sass(args):
('theme-dirs=', '-td', 'The themes dir containing all themes (defaults to None)'),
('themes=', '-t', 'The themes to add sass watchers for (defaults to None)'),
])
+@timed
def watch_assets(options):
"""
Watch for changes to asset files, and regenerate js/css
@@ -730,6 +734,7 @@ def watch_assets(options):
'pavelib.prereqs.install_node_prereqs',
)
@consume_args
+@timed
def update_assets(args):
"""
Compile CoffeeScript and Sass, then collect static assets.
diff --git a/pavelib/bok_choy.py b/pavelib/bok_choy.py
index a8d5048e8f4d72b552969b22df09602889fb570d..30c150978cc07bc06435d0528879daabc5f51f88 100644
--- a/pavelib/bok_choy.py
+++ b/pavelib/bok_choy.py
@@ -7,6 +7,7 @@ from pavelib.utils.test.suites.bokchoy_suite import BokChoyTestSuite, Pa11yCrawl
from pavelib.utils.envs import Env
from pavelib.utils.test.utils import check_firefox_version
from pavelib.utils.passthrough_opts import PassthroughTask
+from pavelib.utils.timer import timed
from optparse import make_option
import os
@@ -86,6 +87,7 @@ def parse_bokchoy_opts(options, passthrough_options=None):
@needs('pavelib.prereqs.install_prereqs')
@cmdopts(BOKCHOY_OPTS)
@PassthroughTask
+@timed
def test_bokchoy(options, passthrough_options):
"""
Run acceptance tests that use the bok-choy framework.
@@ -116,6 +118,7 @@ def test_bokchoy(options, passthrough_options):
@needs('pavelib.prereqs.install_prereqs')
@cmdopts(BOKCHOY_OPTS)
@PassthroughTask
+@timed
def test_a11y(options, passthrough_options):
"""
Run accessibility tests that use the bok-choy framework.
@@ -142,6 +145,7 @@ def test_a11y(options, passthrough_options):
@needs('pavelib.prereqs.install_prereqs')
@cmdopts(BOKCHOY_OPTS)
@PassthroughTask
+@timed
def perf_report_bokchoy(options, passthrough_options):
"""
Generates a har file for with page performance info.
@@ -164,6 +168,7 @@ def perf_report_bokchoy(options, passthrough_options):
),
])
@PassthroughTask
+@timed
def pa11ycrawler(options, passthrough_options):
"""
Runs pa11ycrawler against the demo-test-course to generates accessibility
@@ -220,6 +225,7 @@ def parse_coverage(report_dir, coveragerc):
@task
+@timed
def bokchoy_coverage():
"""
Generate coverage reports for bok-choy tests
@@ -231,6 +237,7 @@ def bokchoy_coverage():
@task
+@timed
def a11y_coverage():
"""
Generate coverage reports for a11y tests. Note that this coverage report
@@ -246,6 +253,7 @@ def a11y_coverage():
@task
+@timed
def pa11ycrawler_coverage():
"""
Generate coverage reports for bok-choy tests
diff --git a/pavelib/docs.py b/pavelib/docs.py
index 0b10b61286db98561c90048e7f58093e3d2452db..b96580714aed297c1936d10d9a0099f49264685d 100644
--- a/pavelib/docs.py
+++ b/pavelib/docs.py
@@ -7,6 +7,8 @@ import sys
from paver.easy import cmdopts, needs, sh, task
+from .utils.timer import timed
+
DOC_PATHS = {
"dev": "docs/en_us/developers",
@@ -64,6 +66,7 @@ def doc_path(options, allow_default=True):
("type=", "t", "Type of docs to compile"),
("verbose", "v", "Display verbose output"),
])
+@timed
def build_docs(options):
"""
Invoke sphinx 'make build' to generate docs.
diff --git a/pavelib/i18n.py b/pavelib/i18n.py
index a79b9f79c8eb871d660849f4cc0758cdbb481261..326f31ac7080b9d237cb255fcbb69b3241e60ccb 100644
--- a/pavelib/i18n.py
+++ b/pavelib/i18n.py
@@ -10,6 +10,7 @@ from path import Path as path
from paver.easy import task, cmdopts, needs, sh
from .utils.cmd import django_cmd
+from .utils.timer import timed
try:
from pygments.console import colorize
@@ -28,6 +29,7 @@ DEFAULT_SETTINGS = 'devstack'
@cmdopts([
("verbose", "v", "Sets 'verbose' to True"),
])
+@timed
def i18n_extract(options):
"""
Extract localizable strings from sources
@@ -42,6 +44,7 @@ def i18n_extract(options):
@task
+@timed
def i18n_fastgenerate():
"""
Compile localizable strings from sources without re-extracting strings first.
@@ -51,6 +54,7 @@ def i18n_fastgenerate():
@task
@needs("pavelib.i18n.i18n_extract")
+@timed
def i18n_generate():
"""
Compile localizable strings from sources, extracting strings first.
@@ -60,6 +64,7 @@ def i18n_generate():
@task
@needs("pavelib.i18n.i18n_extract")
+@timed
def i18n_generate_strict():
"""
Compile localizable strings from sources, extracting strings first.
@@ -70,6 +75,7 @@ def i18n_generate_strict():
@task
@needs("pavelib.i18n.i18n_extract")
+@timed
def i18n_dummy():
"""
Simulate international translation by generating dummy strings
@@ -85,6 +91,7 @@ def i18n_dummy():
@task
+@timed
def i18n_validate_gettext():
"""
Make sure GNU gettext utilities are available
@@ -107,6 +114,7 @@ def i18n_validate_gettext():
@task
+@timed
def i18n_validate_transifex_config():
"""
Make sure config file with username/password exists
@@ -130,6 +138,7 @@ def i18n_validate_transifex_config():
@task
@needs("pavelib.i18n.i18n_validate_transifex_config")
+@timed
def i18n_transifex_push():
"""
Push source strings to Transifex for translation
@@ -139,6 +148,7 @@ def i18n_transifex_push():
@task
@needs("pavelib.i18n.i18n_validate_transifex_config")
+@timed
def i18n_transifex_pull():
"""
Pull translated strings from Transifex
@@ -147,6 +157,7 @@ def i18n_transifex_pull():
@task
+@timed
def i18n_rtl():
"""
Pull all RTL translations (reviewed AND unreviewed) from Transifex
@@ -164,6 +175,7 @@ def i18n_rtl():
@task
+@timed
def i18n_ltr():
"""
Pull all LTR translations (reviewed AND unreviewed) from Transifex
@@ -188,6 +200,7 @@ def i18n_ltr():
"pavelib.i18n.i18n_dummy",
"pavelib.i18n.i18n_generate_strict",
)
+@timed
def i18n_robot_pull():
"""
Pull source strings, generate po and mo files, and validate
@@ -215,6 +228,7 @@ def i18n_robot_pull():
@task
+@timed
def i18n_clean():
"""
Clean the i18n directory of artifacts
@@ -227,6 +241,7 @@ def i18n_clean():
"pavelib.i18n.i18n_extract",
"pavelib.i18n.i18n_transifex_push",
)
+@timed
def i18n_robot_push():
"""
Extract new strings, and push to transifex
@@ -239,6 +254,7 @@ def i18n_robot_push():
"pavelib.i18n.i18n_validate_transifex_config",
"pavelib.i18n.i18n_generate",
)
+@timed
def i18n_release_push():
"""
Push release-specific resources to Transifex.
@@ -251,6 +267,7 @@ def i18n_release_push():
@needs(
"pavelib.i18n.i18n_validate_transifex_config",
)
+@timed
def i18n_release_pull():
"""
Pull release-specific translations from Transifex.
diff --git a/pavelib/js_test.py b/pavelib/js_test.py
index 058ffebe837bef17c8b5a6dc303d89d01ea351f3..7102d7471fda9430caeabbe33ecff40460a04ecd 100644
--- a/pavelib/js_test.py
+++ b/pavelib/js_test.py
@@ -5,6 +5,7 @@ import sys
from paver.easy import task, cmdopts, needs
from pavelib.utils.test.suites import JsTestSuite
from pavelib.utils.envs import Env
+from pavelib.utils.timer import timed
__test__ = False # do not collect
@@ -22,6 +23,7 @@ __test__ = False # do not collect
('skip-clean', 'C', 'skip cleaning repository before running tests'),
('skip_clean', None, 'deprecated in favor of skip-clean'),
], share_with=["pavelib.utils.tests.utils.clean_reports_dir"])
+@timed
def test_js(options):
"""
Run the JavaScript tests
@@ -58,6 +60,7 @@ def test_js(options):
("suite=", "s", "Test suite to run"),
("coverage", "c", "Run test under coverage"),
])
+@timed
def test_js_run(options):
"""
Run the JavaScript tests and print results to the console
@@ -71,6 +74,7 @@ def test_js_run(options):
("suite=", "s", "Test suite to run"),
("port=", "p", "Port to run test server on"),
])
+@timed
def test_js_dev(options):
"""
Run the JavaScript tests in your default browsers
diff --git a/pavelib/paver_tests/test_timer.py b/pavelib/paver_tests/test_timer.py
new file mode 100644
index 0000000000000000000000000000000000000000..742e6a34a37022879af0c99817512565569c7225
--- /dev/null
+++ b/pavelib/paver_tests/test_timer.py
@@ -0,0 +1,188 @@
+"""
+Tests of the pavelib.utils.timer module.
+"""
+
+from datetime import datetime, timedelta
+from mock import patch, MagicMock
+from unittest import TestCase
+
+from pavelib.utils import timer
+
+
+@timer.timed
+def identity(*args, **kwargs):
+ """
+ An identity function used as a default task to test the timing of.
+ """
+ return args, kwargs
+
+
+MOCK_OPEN = MagicMock(spec=open)
+
+
+@patch.dict('pavelib.utils.timer.__builtins__', open=MOCK_OPEN)
+class TimedDecoratorTests(TestCase):
+ """
+ Tests of the pavelib.utils.timer:timed decorator.
+ """
+ def setUp(self):
+ super(TimedDecoratorTests, self).setUp()
+
+ patch_dumps = patch.object(timer.json, 'dump', autospec=True)
+ self.mock_dump = patch_dumps.start()
+ self.addCleanup(patch_dumps.stop)
+
+ patch_makedirs = patch.object(timer.os, 'makedirs', autospec=True)
+ self.mock_makedirs = patch_makedirs.start()
+ self.addCleanup(patch_makedirs.stop)
+
+ patch_datetime = patch.object(timer, 'datetime', autospec=True)
+ self.mock_datetime = patch_datetime.start()
+ self.addCleanup(patch_datetime.stop)
+
+ patch_exists = patch.object(timer, 'exists', autospec=True)
+ self.mock_exists = patch_exists.start()
+ self.addCleanup(patch_exists.stop)
+
+ MOCK_OPEN.reset_mock()
+
+ def get_log_messages(self, task=identity, args=None, kwargs=None, raises=None):
+ """
+ Return all timing messages recorded during the execution of ``task``.
+ """
+ if args is None:
+ args = []
+ if kwargs is None:
+ kwargs = {}
+
+ if raises is None:
+ task(*args, **kwargs)
+ else:
+ self.assertRaises(raises, task, *args, **kwargs)
+
+ return [
+ call[0][0] # log_message
+ for call in self.mock_dump.call_args_list
+ ]
+
+ @patch.object(timer, 'PAVER_TIMER_LOG', '/tmp/some-log')
+ def test_times(self):
+ start = datetime(2016, 7, 20, 10, 56, 19)
+ end = start + timedelta(seconds=35.6)
+
+ self.mock_datetime.utcnow.side_effect = [start, end]
+
+ messages = self.get_log_messages()
+ self.assertEquals(len(messages), 1)
+
+ # I'm not using assertDictContainsSubset because it is
+ # removed in python 3.2 (because the arguments were backwards)
+ # and it wasn't ever replaced by anything *headdesk*
+ self.assertIn('duration', messages[0])
+ self.assertEquals(35.6, messages[0]['duration'])
+
+ self.assertIn('started_at', messages[0])
+ self.assertEquals(start.isoformat(' '), messages[0]['started_at'])
+
+ self.assertIn('ended_at', messages[0])
+ self.assertEquals(end.isoformat(' '), messages[0]['ended_at'])
+
+ @patch.object(timer, 'PAVER_TIMER_LOG', None)
+ def test_no_logs(self):
+ messages = self.get_log_messages()
+ self.assertEquals(len(messages), 0)
+
+ @patch.object(timer, 'PAVER_TIMER_LOG', '/tmp/some-log')
+ def test_arguments(self):
+ messages = self.get_log_messages(args=(1, 'foo'), kwargs=dict(bar='baz'))
+ self.assertEquals(len(messages), 1)
+
+ # I'm not using assertDictContainsSubset because it is
+ # removed in python 3.2 (because the arguments were backwards)
+ # and it wasn't ever replaced by anything *headdesk*
+ self.assertIn('args', messages[0])
+ self.assertEquals([repr(1), repr('foo')], messages[0]['args'])
+ self.assertIn('kwargs', messages[0])
+ self.assertEquals({'bar': repr('baz')}, messages[0]['kwargs'])
+
+ @patch.object(timer, 'PAVER_TIMER_LOG', '/tmp/some-log')
+ def test_task_name(self):
+ messages = self.get_log_messages()
+ self.assertEquals(len(messages), 1)
+
+ # I'm not using assertDictContainsSubset because it is
+ # removed in python 3.2 (because the arguments were backwards)
+ # and it wasn't ever replaced by anything *headdesk*
+ self.assertIn('task', messages[0])
+ self.assertEquals('pavelib.paver_tests.test_timer.identity', messages[0]['task'])
+
+ @patch.object(timer, 'PAVER_TIMER_LOG', '/tmp/some-log')
+ def test_exceptions(self):
+
+ @timer.timed
+ def raises():
+ """
+ A task used for testing exception handling of the timed decorator.
+ """
+ raise Exception('The Message!')
+
+ messages = self.get_log_messages(task=raises, raises=Exception)
+ self.assertEquals(len(messages), 1)
+
+ # I'm not using assertDictContainsSubset because it is
+ # removed in python 3.2 (because the arguments were backwards)
+ # and it wasn't ever replaced by anything *headdesk*
+ self.assertIn('exception', messages[0])
+ self.assertEquals("Exception: The Message!", messages[0]['exception'])
+
+ @patch.object(timer, 'PAVER_TIMER_LOG', '/tmp/some-log-%Y-%m-%d-%H-%M-%S.log')
+ def test_date_formatting(self):
+ start = datetime(2016, 7, 20, 10, 56, 19)
+ end = start + timedelta(seconds=35.6)
+
+ self.mock_datetime.utcnow.side_effect = [start, end]
+
+ messages = self.get_log_messages()
+ self.assertEquals(len(messages), 1)
+
+ MOCK_OPEN.assert_called_once_with('/tmp/some-log-2016-07-20-10-56-19.log', 'a')
+
+ @patch.object(timer, 'PAVER_TIMER_LOG', '/tmp/some-log')
+ def test_nested_tasks(self):
+
+ @timer.timed
+ def parent():
+ """
+ A timed task that calls another task
+ """
+ identity()
+
+ parent_start = datetime(2016, 7, 20, 10, 56, 19)
+ parent_end = parent_start + timedelta(seconds=60)
+ child_start = parent_start + timedelta(seconds=10)
+ child_end = parent_end - timedelta(seconds=10)
+
+ self.mock_datetime.utcnow.side_effect = [parent_start, child_start, child_end, parent_end]
+
+ messages = self.get_log_messages(task=parent)
+ self.assertEquals(len(messages), 2)
+
+ # Child messages first
+ self.assertIn('duration', messages[0])
+ self.assertEquals(40, messages[0]['duration'])
+
+ self.assertIn('started_at', messages[0])
+ self.assertEquals(child_start.isoformat(' '), messages[0]['started_at'])
+
+ self.assertIn('ended_at', messages[0])
+ self.assertEquals(child_end.isoformat(' '), messages[0]['ended_at'])
+
+ # Parent messages after
+ self.assertIn('duration', messages[1])
+ self.assertEquals(60, messages[1]['duration'])
+
+ self.assertIn('started_at', messages[1])
+ self.assertEquals(parent_start.isoformat(' '), messages[1]['started_at'])
+
+ self.assertIn('ended_at', messages[1])
+ self.assertEquals(parent_end.isoformat(' '), messages[1]['ended_at'])
diff --git a/pavelib/prereqs.py b/pavelib/prereqs.py
index 262a3b243d20d9421706168cfff86c90735a699f..81ceb25fcfeccea2dda0510fe46e67e4f8fcabf4 100644
--- a/pavelib/prereqs.py
+++ b/pavelib/prereqs.py
@@ -11,6 +11,7 @@ import sys
from paver.easy import sh, task
from .utils.envs import Env
+from .utils.timer import timed
PREREQS_STATE_DIR = os.getenv('PREREQ_CACHE_DIR', Env.REPO_ROOT / '.prereqs_cache')
@@ -145,6 +146,7 @@ def python_prereqs_installation():
@task
+@timed
def install_node_prereqs():
"""
Installs Node prerequisites
@@ -168,6 +170,7 @@ PACKAGES_TO_UNINSTALL = [
@task
+@timed
def uninstall_python_packages():
"""
Uninstall Python packages that need explicit uninstallation.
@@ -235,6 +238,7 @@ def package_in_frozen(package_name, frozen_output):
@task
+@timed
def install_python_prereqs():
"""
Installs Python prerequisites.
@@ -268,6 +272,7 @@ def install_python_prereqs():
@task
+@timed
def install_prereqs():
"""
Installs Node and Python prerequisites
diff --git a/pavelib/quality.py b/pavelib/quality.py
index 3882969eda6745ff2b3d2e21aeff46b211eb721f..a37f717970e9faf287b594f8d827faa817f860e0 100644
--- a/pavelib/quality.py
+++ b/pavelib/quality.py
@@ -9,6 +9,7 @@ import re
from openedx.core.djangolib.markup import HTML
from .utils.envs import Env
+from .utils.timer import timed
ALL_SYSTEMS = 'lms,cms,common,openedx,pavelib'
@@ -38,6 +39,7 @@ def top_python_dirs(dirname):
@cmdopts([
("system=", "s", "System to act on"),
])
+@timed
def find_fixme(options):
"""
Run pylint on system code, only looking for fixme items.
@@ -82,6 +84,7 @@ def find_fixme(options):
("errors", "e", "Check for errors only"),
("limit=", "l", "limit for number of acceptable violations"),
])
+@timed
def run_pylint(options):
"""
Run pylint on system code. When violations limit is passed in,
@@ -197,6 +200,7 @@ def _pep8_violations(report_file):
@cmdopts([
("system=", "s", "System to act on"),
])
+@timed
def run_pep8(options): # pylint: disable=unused-argument
"""
Run pep8 on system code.
@@ -224,6 +228,7 @@ def run_pep8(options): # pylint: disable=unused-argument
@task
@needs('pavelib.prereqs.install_python_prereqs')
+@timed
def run_complexity():
"""
Uses radon to examine cyclomatic complexity.
@@ -262,6 +267,7 @@ def run_complexity():
@cmdopts([
("limit=", "l", "limit for number of acceptable violations"),
])
+@timed
def run_jshint(options):
"""
Runs jshint on static asset directories
@@ -306,6 +312,7 @@ def run_jshint(options):
@cmdopts([
("thresholds=", "t", "json containing limit for number of acceptable violations per rule"),
])
+@timed
def run_safelint(options):
"""
Runs safe_template_linter.py on the codebase
@@ -407,6 +414,7 @@ def run_safelint(options):
@task
@needs('pavelib.prereqs.install_python_prereqs')
+@timed
def run_safecommit_report():
"""
Runs safe-commit-linter.sh on the current branch.
@@ -580,6 +588,7 @@ def _get_safecommit_count(filename):
("compare-branch=", "b", "Branch to compare against, defaults to origin/master"),
("percentage=", "p", "fail if diff-quality is below this percentage"),
])
+@timed
def run_quality(options):
"""
Build the html diff quality reports, and print the reports to the console.
diff --git a/pavelib/servers.py b/pavelib/servers.py
index db4076ccf6da2aaedff3963359d42ee7f6529343..cf4711f728839c53ad102d06caeb6497ca11c074 100644
--- a/pavelib/servers.py
+++ b/pavelib/servers.py
@@ -10,6 +10,7 @@ from paver.easy import call_task, cmdopts, consume_args, needs, sh, task
from .assets import collect_assets
from .utils.cmd import django_cmd
from .utils.process import run_process, run_multi_processes
+from .utils.timer import timed
DEFAULT_PORT = {"lms": 8000, "studio": 8001}
@@ -244,6 +245,7 @@ def run_all_servers(options):
("settings=", "s", "Django settings"),
("fake-initial", None, "Fake the initial migrations"),
])
+@timed
def update_db(options):
"""
Migrates the lms and cms across all databases
@@ -261,6 +263,7 @@ def update_db(options):
@task
@needs('pavelib.prereqs.install_prereqs')
@consume_args
+@timed
def check_settings(args):
"""
Checks settings files.
diff --git a/pavelib/tests.py b/pavelib/tests.py
index ffcf7668fe25ace98d1da4317a60502bf33b5ec3..7660a4390b1abb04380361d4d327e74979d84bd0 100644
--- a/pavelib/tests.py
+++ b/pavelib/tests.py
@@ -7,6 +7,7 @@ import sys
from paver.easy import sh, task, cmdopts, needs, call_task
from pavelib.utils.test import suites
from pavelib.utils.envs import Env
+from pavelib.utils.timer import timed
from pavelib.utils.passthrough_opts import PassthroughTask
from optparse import make_option
@@ -55,6 +56,7 @@ __test__ = False # do not collect
('skip_clean', None, 'deprecated in favor of skip-clean'),
], share_with=['pavelib.utils.test.utils.clean_reports_dir'])
@PassthroughTask
+@timed
def test_system(options, passthrough_options):
"""
Run tests on our djangoapps for lms and cms
@@ -120,6 +122,7 @@ def test_system(options, passthrough_options):
("test_id=", None, "deprecated in favor of test-id"),
], share_with=['pavelib.utils.test.utils.clean_reports_dir'])
@PassthroughTask
+@timed
def test_lib(options, passthrough_options):
"""
Run tests for common/lib/ and pavelib/ (paver-tests)
@@ -184,6 +187,7 @@ def test_lib(options, passthrough_options):
("fail_fast", None, "deprecated in favor of fail-fast"),
])
@PassthroughTask
+@timed
def test_python(options, passthrough_options):
"""
Run all python tests
@@ -216,6 +220,7 @@ def test_python(options, passthrough_options):
),
])
@PassthroughTask
+@timed
def test(options, passthrough_options):
"""
Run all tests
@@ -239,7 +244,8 @@ def test(options, passthrough_options):
("compare-branch=", "b", "Branch to compare against, defaults to origin/master"),
("compare_branch=", None, "deprecated in favor of compare-branch"),
])
-def coverage(options):
+@timed
+def coverage():
"""
Build the html, xml, and diff coverage reports
"""
@@ -276,6 +282,7 @@ def coverage(options):
("compare-branch=", "b", "Branch to compare against, defaults to origin/master"),
("compare_branch=", None, "deprecated in favor of compare-branch"),
], share_with=['coverage'])
+@timed
def diff_coverage(options):
"""
Build the diff coverage reports
diff --git a/pavelib/utils/test/utils.py b/pavelib/utils/test/utils.py
index 769fe1738625b49a67b410f1f6ae98c7636eec2f..ea189c625d094626bfb295fe237c77fa32ebe3a1 100644
--- a/pavelib/utils/test/utils.py
+++ b/pavelib/utils/test/utils.py
@@ -3,6 +3,7 @@ Helper functions for test tasks
"""
from paver.easy import sh, task, cmdopts
from pavelib.utils.envs import Env
+from pavelib.utils.timer import timed
import os
import re
import subprocess
@@ -15,6 +16,7 @@ __test__ = False # do not collect
@task
+@timed
def clean_test_files():
"""
Clean fixture files used by tests and .pyc files
@@ -42,6 +44,7 @@ def clean_dir(directory):
('skip-clean', 'C', 'skip cleaning repository before running tests'),
('skip_clean', None, 'deprecated in favor of skip-clean'),
])
+@timed
def clean_reports_dir(options):
"""
Clean coverage files, to ensure that we don't use stale data to generate reports.
@@ -57,6 +60,7 @@ def clean_reports_dir(options):
@task
+@timed
def clean_mongo():
"""
Clean mongo test databases
diff --git a/pavelib/utils/timer.py b/pavelib/utils/timer.py
new file mode 100644
index 0000000000000000000000000000000000000000..9a521ec6879efdda99ca7bab776e5f6c7c6a0347
--- /dev/null
+++ b/pavelib/utils/timer.py
@@ -0,0 +1,80 @@
+"""
+Tools for timing paver tasks
+"""
+
+from datetime import datetime
+import json
+import logging
+import os
+from os.path import dirname, exists
+import sys
+import traceback
+import wrapt
+
+LOGGER = logging.getLogger(__file__)
+PAVER_TIMER_LOG = os.environ.get('PAVER_TIMER_LOG')
+
+
+@wrapt.decorator
+def timed(wrapped, instance, args, kwargs): # pylint: disable=unused-argument
+ """
+ Log execution time for a function to a log file.
+
+ Logging is only actually executed if the PAVER_TIMER_LOG environment variable
+ is set. That variable is expanded for the current user and current
+ environment variables. It also can have :meth:`~Datetime.strftime` format
+ identifiers which are substituted using the time when the task started.
+
+ For example, ``PAVER_TIMER_LOG='~/.paver.logs/%Y-%d-%m.log'`` will create a new
+ log file every day containing reconds for paver tasks run that day, and
+ will put those log files in the ``.paver.logs`` directory inside the users
+ home.
+
+ Must be earlier in the decorator stack than the paver task declaration.
+ """
+ start = datetime.utcnow()
+ exception_info = {}
+ try:
+ return wrapped(*args, **kwargs)
+ except Exception as exc: # pylint: disable=broad-except
+ exception_info = {
+ 'exception': "".join(traceback.format_exception_only(type(exc), exc)).strip()
+ }
+ raise
+ finally:
+ end = datetime.utcnow()
+
+ # 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 PAVER_TIMER_LOG is not None:
+
+ log_path = start.strftime(PAVER_TIMER_LOG)
+
+ log_message = {
+ 'python_version': sys.version,
+ 'task': "{}.{}".format(wrapped.__module__, wrapped.__name__),
+ 'args': [repr(arg) for arg in args],
+ 'kwargs': {key: repr(value) for key, value in kwargs.items()},
+ 'started_at': start.isoformat(' '),
+ 'ended_at': end.isoformat(' '),
+ 'duration': (end - start).total_seconds(),
+ }
+ log_message.update(exception_info)
+
+ try:
+ if not exists(dirname(log_path)):
+ os.makedirs(dirname(log_path))
+
+ with open(log_path, 'a') as outfile:
+ json.dump(
+ log_message,
+ outfile,
+ separators=(',', ':'),
+ sort_keys=True,
+ )
+ outfile.write('\n')
+ except OSError:
+ # Squelch OSErrors, because we expect them and they shouldn't
+ # interrupt the rest of the process.
+ LOGGER.exception("Unable to write timing logs")