Test timings

lib/iris/tests/__init__.py

@@ -37,6 +37,7 @@
 import codecs
 import collections
 import contextlib
+import datetime
 import difflib
 import filecmp
 import functools
@@ -219,7 +220,7 @@ def get_data_path(relative_path):
     return data_path
 
 
-class IrisTest(unittest.TestCase):
+class IrisTest_nometa(unittest.TestCase):
     """A subclass of unittest.TestCase which provides Iris specific testing functionality."""
 
     _assertion_counts = collections.defaultdict(int)
@@ -853,10 +854,84 @@ def assertArrayShapeStats(self, result, shape, mean, std_dev, rtol=1e-6):
         self.assertArrayAllClose(result.data.std(), std_dev, rtol=rtol)
 
 
+# An environment variable controls whether test timings are output.
+#
+# NOTE: to run tests with timing output, nosetests cannot be used.
+# At present, that includes not using "python setup.py test"
+# The typically best way is like this :
+#    $ export IRIS_TEST_TIMINGS=1
+#    $ python -m unittest discover -s iris.tests 
+# and commonly adding ...
+#    | grep "TIMING TEST" >iris_test_output.txt
+#
+_PRINT_TEST_TIMINGS = bool(int(os.environ.get('IRIS_TEST_TIMINGS', 0)))
+
+
+def _method_path(meth):
+    cls = meth.im_class
+    return '.'.join([cls.__module__, cls.__name__, meth.__name__])
+
+
+def _testfunction_timing_decorator(fn):
+    # Function decorator for making a testcase print its execution time.
+    @functools.wraps(fn)
+    def inner(*args, **kwargs):
+        start_time = datetime.datetime.now()
+        try:
+            result = fn(*args, **kwargs)
+        finally:
+            end_time = datetime.datetime.now()
+            elapsed_time = (end_time - start_time).total_seconds()
+            msg = '\n  TEST TIMING -- "{}" took : {:12.6f} sec.'
+            name = _method_path(fn)
+            print(msg.format(name, elapsed_time))
+        return result
+    return inner
+
+
+def iristest_timing_decorator(cls):
+    # Class decorator to make all "test_.." functions print execution timings.
+    if _PRINT_TEST_TIMINGS:
+        # NOTE: 'dir' scans *all* class properties, including inherited ones.
+        attr_names = dir(cls)
+        for attr_name in attr_names:
+            attr = getattr(cls, attr_name)
+            if callable(attr) and attr_name.startswith('test'):
+                attr = _testfunction_timing_decorator(attr)
+                setattr(cls, attr_name, attr)
+    return cls
+
+
+class _TestTimingsMetaclass(type):
+    # An alternative metaclass for IrisTest subclasses, which makes
+    # them print execution timings for all the testcases.
+    # This is equivalent to applying the @iristest_timing_decorator to
+    # every test class that inherits from IrisTest.
+    # NOTE: however, it means you *cannot* specify a different metaclass for
+    # your test class inheriting from IrisTest.
+    # See below for how to solve that where needed.
+    def __new__(cls, clsname, base_classes, attrs):
+        result = type.__new__(cls, clsname, base_classes, attrs)
+        if _PRINT_TEST_TIMINGS:
+            result = iristest_timing_decorator(result)
+        return result
+
+
+class IrisTest(six.with_metaclass(_TestTimingsMetaclass, IrisTest_nometa)):
+    # Derive the 'ordinary' IrisTest from IrisTest_nometa, but add the
+    # metaclass that enables test timings output.
+    # This means that all subclasses also get the timing behaviour.
+    # However, if a different metaclass is *wanted* for an IrisTest subclass,
+    # this would cause a metaclass conflict.
+    # Instead, you can inherit from IrisTest_nometa and apply the
+    # @iristest_timing_decorator explicitly to your new testclass.
+    pass
+
+
 get_result_path = IrisTest.get_result_path
 
 
-class GraphicsTest(IrisTest):
+class GraphicsTestMixin(object):
 
     # nose directive: dispatch tests concurrently.
     _multiprocess_can_split_ = True
@@ -879,6 +954,15 @@ def tearDown(self):
         _lock.release()
 
 
+class GraphicsTest(GraphicsTestMixin, IrisTest):
+    pass
+
+
+class GraphicsTest_nometa(GraphicsTestMixin, IrisTest_nometa):
+    # Graphicstest without the metaclass providing test timings.
+    pass
+
+
 class TestGribMessage(IrisTest):
     def assertGribMessageContents(self, filename, contents):
         """

lib/iris/tests/test_cell.py

@@ -1,4 +1,4 @@
-# (C) British Crown Copyright 2010 - 2015, Met Office
+# (C) British Crown Copyright 2010 - 2017, Met Office
 #
 # This file is part of Iris.
 #
@@ -22,15 +22,13 @@
 # import iris tests first so that some things can be initialised before importing anything else
 import iris.tests as tests
 
-import unittest
-
 import numpy as np
 
 import iris.coords
 from iris.coords import Cell
 
 
-class TestCells(unittest.TestCase):
+class TestCells(tests.IrisTest):
     def setUp(self):
         self.cell1 = iris.coords.Cell(3, [2, 4])
         self.cell2 = iris.coords.Cell(360., [350., 370.])

lib/iris/tests/test_cf.py

@@ -1,4 +1,4 @@
-# (C) British Crown Copyright 2010 - 2016, Met Office
+# (C) British Crown Copyright 2010 - 2017, Met Office
 #
 # This file is part of Iris.
 #
@@ -25,14 +25,12 @@
 # import iris tests first so that some things can be initialised before importing anything else
 import iris.tests as tests
 
-import unittest
-
 import iris
 import iris.fileformats.cf as cf
 from iris.tests import mock
 
 
-class TestCaching(unittest.TestCase):
+class TestCaching(tests.IrisTest):
     def test_cached(self):
         # Make sure attribute access to the underlying netCDF4.Variable
         # is cached.

lib/iris/tests/test_coding_standards.py

@@ -1,4 +1,4 @@
-# (C) British Crown Copyright 2013 - 2016, Met Office
+# (C) British Crown Copyright 2013 - 2017, Met Office
 #
 # This file is part of Iris.
 #
@@ -18,14 +18,17 @@
 from __future__ import (absolute_import, division, print_function)
 from six.moves import (filter, input, map, range, zip)  # noqa
 
+# import iris tests first so that some things can be initialised before
+# importing anything else
+import iris.tests as tests
+
 from datetime import datetime
 from fnmatch import fnmatch
 from glob import glob
 from itertools import chain
 import os
 import re
 import subprocess
-import unittest
 
 import pep8
 
@@ -170,7 +173,7 @@ def get_file_results(self):
                      self).get_file_results()
 
 
-class TestCodeFormat(unittest.TestCase):
+class TestCodeFormat(tests.IrisTest):
     def test_pep8_conformance(self):
         #
         #    Tests the iris codebase against the "pep8" tool.
@@ -218,7 +221,7 @@ def test_pep8_conformance(self):
                           '{}'.format('\n  '.join(unexpectedly_good)))
 
 
-class TestLicenseHeaders(unittest.TestCase):
+class TestLicenseHeaders(tests.IrisTest):
     @staticmethod
     def years_of_license_in_file(fh):
         """
@@ -345,7 +348,7 @@ def test_license_headers(self):
             raise ValueError('There were license header failures. See stdout.')
 
 
-class TestFutureImports(unittest.TestCase):
+class TestFutureImports(tests.IrisTest):
     excluded = (
         '*/iris/fileformats/_old_pp_packing.py',
         '*/iris/fileformats/_pyke_rules/__init__.py',
@@ -406,4 +409,4 @@ def test_future_imports(self):
 
 
 if __name__ == '__main__':
-    unittest.main()
+    tests.main()

lib/iris/tests/test_coord_api.py

@@ -1,4 +1,4 @@
-# (C) British Crown Copyright 2010 - 2016, Met Office
+# (C) British Crown Copyright 2010 - 2017, Met Office
 #
 # This file is part of Iris.
 #
@@ -22,7 +22,6 @@
 # import iris tests first so that some things can be initialised before importing anything else
 import iris.tests as tests
 
-import unittest
 from xml.dom.minidom import Document
 import logging
 
@@ -40,7 +39,7 @@
 logger = logging.getLogger('tests')
 
 
-class TestLazy(unittest.TestCase):
+class TestLazy(tests.IrisTest):
     def setUp(self):
         # Start with a coord with LazyArray points.
         shape = (3, 4)
@@ -107,7 +106,7 @@ def test_lazy_shared_data(self):
 
 
 @tests.skip_data
-class TestCoordSlicing(unittest.TestCase):
+class TestCoordSlicing(tests.IrisTest):
     def setUp(self):
         cube = iris.tests.stock.realistic_4d()
         self.lat = cube.coord('grid_latitude')
@@ -278,7 +277,7 @@ def test_AuxCoord_str(self):
                           ('coord_api', 'str_repr', 'aux_time_str.txt'))
 
 
-class TestAuxCoordCreation(unittest.TestCase):
+class TestAuxCoordCreation(tests.IrisTest):
     def test_basic(self):
         a = iris.coords.AuxCoord(np.arange(10), 'air_temperature',
                                  units='kelvin')
@@ -336,7 +335,7 @@ def test_AuxCoord_fromcoord(self):
         self.assertIsNot(a.coord_system, b.coord_system)
 
 
-class TestDimCoordCreation(unittest.TestCase):
+class TestDimCoordCreation(tests.IrisTest):
     def test_basic(self):
         a = iris.coords.DimCoord(np.arange(10), 'air_temperature',
                                  units='kelvin')

lib/iris/tests/test_io_init.py

@@ -1,4 +1,4 @@
-# (C) British Crown Copyright 2010 - 2016, Met Office
+# (C) British Crown Copyright 2010 - 2017, Met Office
 #
 # This file is part of Iris.
 #
@@ -25,14 +25,13 @@
 # import iris tests first so that some things can be initialised before importing anything else
 import iris.tests as tests
 
-import unittest
 from io import BytesIO
 
 import iris.fileformats as iff
 import iris.io
 
 
-class TestDecodeUri(unittest.TestCase):
+class TestDecodeUri(tests.IrisTest):
     def test_decode_uri(self):
         tests = {
             '/data/local/someDir/PP/COLPEX/COLPEX_16a_pj001.pp': (

lib/iris/tests/test_plot.py

@@ -1,4 +1,4 @@
-# (C) British Crown Copyright 2010 - 2016, Met Office
+# (C) British Crown Copyright 2010 - 2017, Met Office
 #
 # This file is part of Iris.
 #
@@ -581,8 +581,10 @@ def override_with_decorated_methods(attr_dict, target_dict,
 
 
 @tests.skip_data
+@tests.iristest_timing_decorator
 class TestPcolorNoBounds(six.with_metaclass(CheckForWarningsMetaclass,
-                                            tests.GraphicsTest, SliceMixin)):
+                                            tests.GraphicsTest_nometa,
+                                            SliceMixin)):
     """
     Test the iris.plot.pcolor routine on a cube with coordinates
     that have no bounds.
@@ -595,8 +597,9 @@ def setUp(self):
 
 
 @tests.skip_data
+@tests.iristest_timing_decorator
 class TestPcolormeshNoBounds(six.with_metaclass(CheckForWarningsMetaclass,
-                                                tests.GraphicsTest,
+                                                tests.GraphicsTest_nometa,
                                                 SliceMixin)):
     """
     Test the iris.plot.pcolormesh routine on a cube with coordinates

lib/iris/tests/test_pp_module.py

@@ -1,4 +1,4 @@
-# (C) British Crown Copyright 2013 - 2015, Met Office
+# (C) British Crown Copyright 2013 - 2017, Met Office
 #
 # This file is part of Iris.
 #
@@ -98,7 +98,7 @@ def check_pp(self, pp_fields, reference_filename):
                 reference_fh.writelines(test_string)
 
 
-class TestPPHeaderDerived(unittest.TestCase):
+class TestPPHeaderDerived(tests.IrisTest):
 
     def setUp(self):
         self.pp = pp.PPField2()
@@ -338,7 +338,7 @@ def test_save_single(self):
         os.remove(temp_filename)
 
 
-class TestBitwiseInt(unittest.TestCase):
+class TestBitwiseInt(tests.IrisTest):
 
     def test_3(self):
         with mock.patch('warnings.warn') as warn:
@@ -447,7 +447,7 @@ def test_128(self):
         self.assertEqual(t.flag128, 1)
 
 
-class TestSplittableInt(unittest.TestCase):
+class TestSplittableInt(tests.IrisTest):
 
     def test_3(self):
         t = pp.SplittableInt(3)
@@ -546,15 +546,15 @@ def test_negative_number(self):
             self.assertEqual(str(err), 'Negative numbers not supported with splittable integers object')
 
 
-class TestSplittableIntEquality(unittest.TestCase):
+class TestSplittableIntEquality(tests.IrisTest):
     def test_not_implemented(self):
         class Terry(object): pass
         sin = pp.SplittableInt(0)
         self.assertIs(sin.__eq__(Terry()), NotImplemented)
         self.assertIs(sin.__ne__(Terry()), NotImplemented)
 
 
-class TestPPDataProxyEquality(unittest.TestCase):
+class TestPPDataProxyEquality(tests.IrisTest):
     def test_not_implemented(self):
         class Terry(object): pass
         pox = pp.PPDataProxy("john", "michael", "eric", "graham", "brian",
@@ -563,7 +563,7 @@ class Terry(object): pass
         self.assertIs(pox.__ne__(Terry()), NotImplemented)
 
 
-class TestPPFieldEquality(unittest.TestCase):
+class TestPPFieldEquality(tests.IrisTest):
     def test_not_implemented(self):
         class Terry(object): pass
         pox = pp.PPField3()