Merge lp:~ev/ubuntu-ci-services-itself/time-sorted-tests into lp:ubuntu-ci-services-itself

[Evan]

Shave two minutes off test execution. Add a small program to print sorted test execution time.

The kinds of things one discovers while on a ten hour flight. This branch knocks our worst case test time under ./run-tests from 2 minutes 12 seconds to 10 seconds. A few tests were setting up nonexistent hosts to talk to, then waiting for the socket timeout:

trunk:
Ran 289 tests in 133.913s
Ran 289 tests in 132.474s
Ran 289 tests in 132.500s

time-sorted-tests:
Ran 289 tests in 10.384s
Ran 289 tests in 10.727s
Ran 289 tests in 10.676s

It also adds a small tested program to sort the tests by their execution time, which was helpful in identifying long running tests. We should run this periodically (say as part of the MP review toolbelt) to ensure that our ability to iterate quickly isn't slowed by our growing test coverage.

[PS Jenkins bot (ps-jenkins)]

PASSED: Continuous integration, rev:410
http://s-jenkins.ubuntu-ci:8080/job/uci-engine-ci/441/
Executed test runs:

Click here to trigger a rebuild:
http://s-jenkins.ubuntu-ci:8080/job/uci-engine-ci/441/rebuild

review: Approve (continuous-integration)

[Chris Johnston (cjohnston)]

Took the tarmac time for me running it locally from 4:14 to 2:49... I like
that. :-) faster == better

I'm not a huge fan of the commenting for the mocks.. We don't do those
types of comments elsewhere, but thats just my thoughts..

 review approve

review: Approve

[Andy Doan (doanac)]

The whole "bin" idea is quite interesting. I've been thinking there are a few scripts we have that should get moved there.

review: Approve

=== added directory 'bin'
=== added file 'bin/test_time_sorted_tests.py'
--- bin/test_time_sorted_tests.py	1970-01-01 00:00:00 +0000
+++ bin/test_time_sorted_tests.py	2014-03-17 02:09:01 +0000
@@ -0,0 +1,32 @@
+import time_sorted_tests
+import unittest
+import tempfile
+import os
+import sys
+import mock
+
+
+data = '''ticket.tests.test_read_api.TicketReadAPITest.test_get_ticket_steps_detail ...  OK (0.049 secs)
+ticket.tests.test_read_api.TicketReadAPITest.test_get_ticket_update_status_api ... OK (0.046 secs)'''
+
+
+class T(unittest.TestCase):
+    def test_gen_timings(self):
+        t = time_sorted_tests.gen_timings(data)
+        t = t.next()
+        self.assertEqual(t[0], 'ticket.tests.test_read_api.TicketReadAPITest.test_get_ticket_steps_detail')
+        self.assertEqual(t[1], 0.049)
+
+    def test_gen_timings_bad_data(self):
+        t = time_sorted_tests.gen_timings(data + '\noutput from test.')
+        # Iterate through all the data.
+        [x for x in t]
+
+    def test_sort_timings(self):
+        t = time_sorted_tests.gen_timings(data)
+        s = time_sorted_tests.sort_timings(t)
+        self.assertEqual(s[0][1], 0.046)
+        self.assertEqual(s[1][1], 0.049)
+
+if __name__ == '__main__':
+    unittest.main()

=== added file 'bin/time_sorted_tests.py'
--- bin/time_sorted_tests.py	1970-01-01 00:00:00 +0000
+++ bin/time_sorted_tests.py	2014-03-17 02:09:01 +0000
@@ -0,0 +1,67 @@
+#!/usr/bin/env python
+import os
+import sys
+import re
+import subprocess
+
+
+# test_name ... OK (0.1 secs)
+pattern = re.compile('^(.*) \.\.\. .*\((.*) secs\)$')
+
+
+def gen_timings(output):
+    '''Filter out the test names and timing data into tuples.'''
+    for line in output.split('\n'):
+        try:
+            test_name, seconds = re.match(pattern, line).groups()
+        except AttributeError:
+            continue
+        seconds = float(seconds)
+        yield test_name, seconds
+
+
+def sort_timings(timings):
+    '''Sort the timings based on the second value in the tuple, the time in
+    seconds.'''
+    return sorted(timings, cmp=lambda x, y: cmp(x[1], y[1]))
+
+
+def run_tests(args, test_command=['./run-tests']):
+    '''Call ./run-tests with any arguments passed to this program. Return
+    stderr'''
+    cmd = test_command + args
+    # Drop stderr. The text output from tests is not needed here.
+    with open('/dev/null', 'a') as devnull:
+        kwargs = {'stdout': subprocess.PIPE, 'stderr': devnull}
+        p = subprocess.Popen(cmd, **kwargs)
+    try:
+        return p.communicate()[0]
+    except KeyboardInterrupt:
+        # Clean up the subprocess when we've interrupted this script.
+        if p.pid:
+            # Terminate.
+            os.kill(p.pid, 15)
+        return None
+
+
+def print_timings(timings):
+    for test_name, seconds in timings:
+        print '%s: %s' % (test_name, seconds)
+
+
+def print_total_timing(timings):
+    total = sum([x[1] for x in timings])
+    output = 'Total test time: %.2f seconds' % total
+    print
+    print '-' * len(output)
+    print output
+
+
+if __name__ == '__main__':
+    output = run_tests(sys.argv[1:])
+    if output is None:
+        sys.exit(0)
+    timings = gen_timings(output)
+    sorted_timings = sort_timings(timings)
+    print_timings(sorted_timings)
+    print_total_timing(sorted_timings)

=== modified file 'branch-source-builder/bsbuilder/tests/test_upload.py'
--- branch-source-builder/bsbuilder/tests/test_upload.py	2014-03-10 22:11:05 +0000
+++ branch-source-builder/bsbuilder/tests/test_upload.py	2014-03-17 02:09:01 +0000
@@ -69,7 +69,8 @@
 
     @mock.patch('bsbuilder.upload_package.create_temp_dir')
     @mock.patch('__builtin__.open')
-    def test_get_source_files(self, open_mock, temp_dir_mock):
+    @mock.patch('bsbuilder.upload_package.get_url_contents')
+    def test_get_source_files(self, url_mock, open_mock, temp_dir_mock):
         temp_dir_mock.return_value = 'mock_location'
         open_mock.return_value = self._get_context_manager_mock()
         file_list = []
@@ -84,3 +85,4 @@
         self.assertEqual('/api/v1/fullsubticket/2/', result[0]['resource'])
         self.assertEqual('mock_location', result[0]['location'])
         self.assertItemsEqual(file_list, result[0]['files'])
+        url_mock.assert_called_with('https://swift.url/package_0.1.dsc')

=== modified file 'branch-source-builder/bsbuilder/tests/test_v1.py'
--- branch-source-builder/bsbuilder/tests/test_v1.py	2014-03-14 10:37:28 +0000
+++ branch-source-builder/bsbuilder/tests/test_v1.py	2014-03-17 02:09:01 +0000
@@ -30,7 +30,9 @@
         self.app = webtest.TestApp(wsgi.app, relative_to='.')
 
     @mock.patch('ci_utils.amqp_utils.get_config')
-    def testStatus(self, get_config):
+    # Don't actually try to talk to a Rabbit server.
+    @mock.patch('urllib2.build_opener')
+    def testStatus(self, build_opener, get_config):
         get_config.return_value = None
         resp = self.app.get('/api/v1/status', status=200)
         data = json.loads(resp.body)

=== modified file 'ci-utils/ci_utils/image_store/tests/test-image-store.py'
--- ci-utils/ci_utils/image_store/tests/test-image-store.py	2014-01-24 22:42:57 +0000
+++ ci-utils/ci_utils/image_store/tests/test-image-store.py	2014-03-17 02:09:01 +0000
@@ -15,11 +15,16 @@
 # along with this program.  If not, see <http://www.gnu.org/licenses/>.
 
 from ci_utils.image_store import ImageStore, ImageStoreException
+from keystoneclient.exceptions import AuthorizationFailure
 import unittest
+import mock
 
 
 class TestImageStore(unittest.TestCase):
-    def test_bad_auth(self):
+    # Do not attempt to talk to a keystone server.
+    @mock.patch('keystoneclient.httpclient.HTTPClient.authenticate',
+                side_effect=AuthorizationFailure())
+    def test_bad_auth(self, *args):
         auth_data = {
             'auth_url': 'https://keystone.canonistack.canonical.com:443/v2.0/',
             'auth_user': 'bad data',

=== modified file 'ci-utils/ci_utils/tests/test_amqp.py'
--- ci-utils/ci_utils/tests/test_amqp.py	2014-01-31 10:59:22 +0000
+++ ci-utils/ci_utils/tests/test_amqp.py	2014-03-17 02:09:01 +0000
@@ -65,10 +65,10 @@
         callback = mock.Mock()
         channel.wait.side_effect = socket.error()
         start = time.time()
-        retry_period = 2
+        retry_period = 0.1
         amqp_utils._run_forever(channel, 'foo', callback, retry_period)
-        # see if it was within 1/10 of a second of the retry_period
-        self.assertAlmostEqual(start + retry_period, time.time(), places=1)
+        # see if it was within 1/100 of a second of the retry_period
+        self.assertAlmostEqual(start + retry_period, time.time(), places=2)
 
 
 class TestProgressTrigger(unittest.TestCase):

=== modified file 'lander/lander/tests/test_archiver.py'
--- lander/lander/tests/test_archiver.py	2014-03-10 22:25:00 +0000
+++ lander/lander/tests/test_archiver.py	2014-03-17 02:09:01 +0000
@@ -18,6 +18,7 @@
 import os
 import sys
 import unittest
+import urllib2
 
 sys.path.append(os.path.join(os.path.dirname(__file__), '../../bin'))
 import lander_archiver
@@ -245,10 +246,16 @@
         self.assertEqual(-2, self.archiver())
 
     @mock.patch('lander_archiver.TicketApi')
-    def test_call_store_artifact_failure(self, ticket_api):
+    @mock.patch('urllib2.urlopen')
+    def test_call_store_artifact_failure(self, mock_urlopen, ticket_api):
         '''Verify __call__ returns -3 on a store artifact failure.'''
         config = {'username', 'user',
                   'password', 'pass'}
+
+        def side_effect(*args):
+            # Don't hang around waiting for the Jenkins server to never reply.
+            raise urllib2.URLError('Nope.')
+        mock_urlopen.side_effect = side_effect
         api_inst = mock.Mock()
         ticket_api.return_value = api_inst
         args = mock.Mock()