Add timer for atomic actions

Execution time is now measured for atomic actions, so we have time
measuring for the whole benchmark and also detailed for each atomic
action.

Added the decorator atomic_action_timer and used it in nova, cinder
and keystone scenarios.

Partially implements: blueprint time-measuring-of-atomic-actions
(Part "I) Core" of time-measuring-of-atomic-actions)

Change-Id: I99571ef1221757784ce2b85889ad989fcae05bb2

rally/benchmark/base.py

@@ -33,6 +33,7 @@ class Scenario(object):
         self._admin_clients = admin_clients
         self._clients = clients
         self._idle_time = 0
+        self._atomic_actions_time = []
 
     @staticmethod
     def register():
@@ -131,3 +132,12 @@ class Scenario(object):
     def idle_time(self):
         """Returns duration of all sleep_between."""
         return self._idle_time
+
+    def _add_atomic_actions_time(self, name, duration):
+        """Adds the duration of an atomic action by its 'name'."""
+        self._atomic_actions_time.append(
+            {'action': name, 'duration': duration})
+
+    def atomic_actions_time(self):
+        """Returns the duration of each atomic action."""
+        return self._atomic_actions_time

rally/benchmark/runner.py

@@ -57,7 +57,8 @@ def _run_scenario_loop(args):
     finally:
         return {"time": timer.duration() - scenario.idle_time(),
                 "idle_time": scenario.idle_time(), "error": error,
-                "scenario_output": scenario_output}
+                "scenario_output": scenario_output,
+                "atomic_actions_time": scenario.atomic_actions_time()}
 
 
 class ScenarioRunner(object):

rally/benchmark/scenarios/cinder/utils.py

@@ -18,6 +18,7 @@ import string
 import time
 
 from rally.benchmark import base
+from rally.benchmark.scenarios import utils as scenario_utils
 from rally.benchmark import utils as bench_utils
 from rally import utils
 
@@ -37,6 +38,7 @@ def generate_volume_name(length=10):
 
 class CinderScenario(base.Scenario):
 
+    @scenario_utils.atomic_action_timer('cinder.create_volume')
     def _create_volume(self, size, **kwargs):
         """create one volume.
 
@@ -60,6 +62,7 @@ class CinderScenario(base.Scenario):
                                 timeout=600, check_interval=3)
         return volume
 
+    @scenario_utils.atomic_action_timer('cinder.delete_volume')
     def _delete_volume(self, volume):
         """Delete the given volume.
 

rally/benchmark/scenarios/keystone/utils.py

@@ -17,6 +17,7 @@ import random
 import string
 
 from rally.benchmark import base
+from rally.benchmark.scenarios import utils as scenario_utils
 
 # TODO(boris-42): Bind name to the uuid of benchmark.
 TEMP_TEMPLATE = "rally_k_"
@@ -37,6 +38,7 @@ class KeystoneScenario(base.Scenario):
        most of them are creating/deleting resources.
     """
 
+    @scenario_utils.atomic_action_timer('keystone.create_user')
     def _user_create(self, name_length=10, password=None, email=None,
                      **kwargs):
         """Creates keystone user with random name.
@@ -55,6 +57,7 @@ class KeystoneScenario(base.Scenario):
         return self.admin_clients("keystone").users.create(name, password,
                                                            email, **kwargs)
 
+    @scenario_utils.atomic_action_timer('keystone.delete_resource')
     def _resource_delete(self, resource):
         """"Delete keystone resource."""
         resource.delete()

rally/benchmark/scenarios/nova/utils.py

@@ -18,12 +18,14 @@ import string
 import time
 
 from rally.benchmark import base
+from rally.benchmark.scenarios import utils as scenario_utils
 from rally.benchmark import utils as bench_utils
 from rally import utils
 
 
 class NovaScenario(base.Scenario):
 
+    @scenario_utils.atomic_action_timer('nova.boot_server')
     def _boot_server(self, server_name, image_id, flavor_id, **kwargs):
         """Boots one server.
 
@@ -55,6 +57,7 @@ class NovaScenario(base.Scenario):
                                 timeout=600, check_interval=3)
         return server
 
+    @scenario_utils.atomic_action_timer('nova.reboot_server')
     def _reboot_server(self, server, soft=True):
         """Reboots the given server using hard or soft reboot.
 
@@ -71,6 +74,7 @@ class NovaScenario(base.Scenario):
                        update_resource=bench_utils.get_from_manager(),
                        timeout=600, check_interval=3)
 
+    @scenario_utils.atomic_action_timer('nova.start_server')
     def _start_server(self, server):
         """Starts the given server.
 
@@ -84,6 +88,7 @@ class NovaScenario(base.Scenario):
                        update_resource=bench_utils.get_from_manager(),
                        timeout=600, check_interval=2)
 
+    @scenario_utils.atomic_action_timer('nova.stop_server')
     def _stop_server(self, server):
         """Stop the given server.
 
@@ -97,6 +102,7 @@ class NovaScenario(base.Scenario):
                        update_resource=bench_utils.get_from_manager(),
                        timeout=600, check_interval=2)
 
+    @scenario_utils.atomic_action_timer('nova.rescue_server')
     def _rescue_server(self, server):
         """Rescue the given server.
 
@@ -111,6 +117,7 @@ class NovaScenario(base.Scenario):
                        update_resource=bench_utils.get_from_manager(),
                        timeout=600, check_interval=3)
 
+    @scenario_utils.atomic_action_timer('nova.unrescue_server')
     def _unrescue_server(self, server):
         """Unrescue the given server.
 
@@ -124,6 +131,7 @@ class NovaScenario(base.Scenario):
                        update_resource=bench_utils.get_from_manager(),
                        timeout=600, check_interval=3)
 
+    @scenario_utils.atomic_action_timer('nova.suspend_server')
     def _suspend_server(self, server):
         """Suspends the given server.
 
@@ -138,6 +146,7 @@ class NovaScenario(base.Scenario):
                        update_resource=bench_utils.get_from_manager(),
                        timeout=600, check_interval=3)
 
+    @scenario_utils.atomic_action_timer('nova.delete_server')
     def _delete_server(self, server):
         """Deletes the given server.
 
@@ -150,12 +159,14 @@ class NovaScenario(base.Scenario):
                        update_resource=bench_utils.get_from_manager(),
                        timeout=600, check_interval=3)
 
+    @scenario_utils.atomic_action_timer('nova.delete_all_servers')
     def _delete_all_servers(self):
         """Deletes all servers in current tenant."""
         servers = self.clients("nova").servers.list()
         for server in servers:
             self._delete_server(server)
 
+    @scenario_utils.atomic_action_timer('nova.delete_image')
     def _delete_image(self, image):
         """Deletes the given image.
 
@@ -168,6 +179,7 @@ class NovaScenario(base.Scenario):
                        update_resource=bench_utils.get_from_manager(),
                        timeout=600, check_interval=3)
 
+    @scenario_utils.atomic_action_timer('nova.create_image')
     def _create_image(self, server):
         """Creates an image of the given server
 
@@ -187,6 +199,7 @@ class NovaScenario(base.Scenario):
                                timeout=600, check_interval=3)
         return image
 
+    @scenario_utils.atomic_action_timer('nova.boot_servers')
     def _boot_servers(self, name_prefix, image_id, flavor_id,
                       requests, instances_amount=1, **kwargs):
         """Boots multiple servers.

rally/benchmark/scenarios/utils.py

@@ -14,8 +14,11 @@
 #    License for the specific language governing permissions and limitations
 #    under the License.
 
+import functools
 import jsonschema
 
+from rally import utils
+
 
 class ActionBuilder(object):
     """Builder class for mapping and creating action objects into
@@ -123,3 +126,18 @@ class ActionBuilder(object):
                                     binding['action'], times,
                                     *(binding['args'] + args), **dft_kwargs))
         return bound_actions
+
+
+def atomic_action_timer(name):
+    """Decorates methods of the Scenario class requiring a measure of execution
+     time. This provides duration in seconds of each atomic action.
+    """
+    def wrap(func):
+        @functools.wraps(func)
+        def func_atomic_actions(self, *args, **kwargs):
+            with utils.Timer() as timer:
+                f = func(self, *args, **kwargs)
+            self._add_atomic_actions_time(name, timer.duration())
+            return f
+        return func_atomic_actions
+    return wrap

tests/benchmark/scenarios/keystone/test_utils.py

@@ -16,6 +16,7 @@
 import mock
 
 from rally.benchmark.scenarios.keystone import utils
+from tests.benchmark.scenarios import test_utils
 from tests import test
 
 from tests import fakes
@@ -47,6 +48,12 @@ class KeystoneUtilsTestCase(test.TestCase):
 
 class KeystoneScenarioTestCase(test.TestCase):
 
+    def _test_atomic_action_timer(self, atomic_actions_time, name):
+        action_duration = test_utils.get_atomic_action_timer_value_by_name(
+            atomic_actions_time, name)
+        self.assertIsNotNone(action_duration)
+        self.assertIsInstance(action_duration, float)
+
     @mock.patch(UTILS + "generate_keystone_name")
     def test_user_create(self, mock_gen_name):
         name = "abc"
@@ -63,10 +70,15 @@ class KeystoneScenarioTestCase(test.TestCase):
         self.assertEqual(user, result)
         fake_keystone.users.create.assert_called_once_with(name, name,
                                                            name + "@rally.me")
+        self._test_atomic_action_timer(scenario.atomic_actions_time(),
+                                       'keystone.create_user')
 
     def test_user_delete(self):
         resource = fakes.FakeResource()
         resource.delete = mock.MagicMock()
 
-        utils.KeystoneScenario()._resource_delete(resource)
+        scenario = utils.KeystoneScenario()
+        scenario._resource_delete(resource)
         resource.delete.assert_called_once_with()
+        self._test_atomic_action_timer(scenario.atomic_actions_time(),
+                                       'keystone.delete_resource')

tests/benchmark/scenarios/nova/test_utils.py

@@ -19,6 +19,7 @@ from rally.benchmark.scenarios.nova import utils
 from rally.benchmark import utils as butils
 from rally import exceptions as rally_exceptions
 from rally.openstack.common.fixture import mockpatch
+from tests.benchmark.scenarios import test_utils
 from tests import fakes
 from tests import test
 
@@ -42,6 +43,12 @@ class NovaScenarioTestCase(test.TestCase):
         self.gfm = self.get_fm.mock
         self.useFixture(mockpatch.Patch('time.sleep'))
 
+    def _test_atomic_action_timer(self, atomic_actions_time, name):
+        action_duration = test_utils.get_atomic_action_timer_value_by_name(
+            atomic_actions_time, name)
+        self.assertIsNotNone(action_duration)
+        self.assertIsInstance(action_duration, float)
+
     def test_generate_random_name(self):
         for length in [8, 16, 32, 64]:
             name = utils.NovaScenario()._generate_random_name(length)
@@ -58,8 +65,8 @@ class NovaScenarioTestCase(test.TestCase):
     @mock.patch(NOVA_UTILS + '.NovaScenario.clients')
     def test__boot_server(self, mock_clients):
         mock_clients("nova").servers.create.return_value = self.server
-        return_server = utils.NovaScenario()._boot_server('server_name',
+        nova_scenario = utils.NovaScenario()
-                                                          'image_id',
+        return_server = nova_scenario._boot_server('server_name', 'image_id',
                                                    'flavor_id')
         self.wait_for.mock.assert_called_once_with(self.server,
                                                    update_resource=self.gfm(),
@@ -68,9 +75,12 @@ class NovaScenarioTestCase(test.TestCase):
                                                    timeout=600)
         self.res_is.mock.assert_has_calls(mock.call('ACTIVE'))
         self.assertEqual(self.wait_for.mock(), return_server)
+        self._test_atomic_action_timer(nova_scenario.atomic_actions_time(),
+                                       'nova.boot_server')
 
     def test__suspend_server(self):
-        utils.NovaScenario()._suspend_server(self.server)
+        nova_scenario = utils.NovaScenario()
+        nova_scenario._suspend_server(self.server)
         self.server.suspend.assert_called_once_with()
         self.wait_for.mock.assert_called_once_with(self.server,
                                                    update_resource=self.gfm(),
@@ -78,11 +88,14 @@ class NovaScenarioTestCase(test.TestCase):
                                                    check_interval=3,
                                                    timeout=600)
         self.res_is.mock.assert_has_calls(mock.call('SUSPENDED'))
+        self._test_atomic_action_timer(nova_scenario.atomic_actions_time(),
+                                       'nova.suspend_server')
 
     @mock.patch(NOVA_UTILS + '.NovaScenario.clients')
     def test__create_image(self, mock_clients):
         mock_clients("nova").images.get.return_value = self.image
-        return_image = utils.NovaScenario()._create_image(self.server)
+        nova_scenario = utils.NovaScenario()
+        return_image = nova_scenario._create_image(self.server)
         self.wait_for.mock.assert_called_once_with(self.image,
                                                    update_resource=self.gfm(),
                                                    is_ready=self.res_is.mock(),
@@ -90,19 +103,25 @@ class NovaScenarioTestCase(test.TestCase):
                                                    timeout=600)
         self.res_is.mock.assert_has_calls(mock.call('ACTIVE'))
         self.assertEqual(self.wait_for.mock(), return_image)
+        self._test_atomic_action_timer(nova_scenario.atomic_actions_time(),
+                                       'nova.create_image')
 
     @mock.patch(BM_UTILS + ".is_none")
     def test__delete_server(self, mock_isnone):
-        utils.NovaScenario()._delete_server(self.server)
+        nova_scenario = utils.NovaScenario()
+        nova_scenario._delete_server(self.server)
         self.server.delete.assert_called_once_with()
         self.wait_for.mock.assert_called_once_with(self.server,
                                                    is_ready=mock_isnone,
                                                    update_resource=self.gfm(),
                                                    check_interval=3,
                                                    timeout=600)
+        self._test_atomic_action_timer(nova_scenario.atomic_actions_time(),
+                                       'nova.delete_server')
 
     def test__reboot_server(self):
-        utils.NovaScenario()._reboot_server(self.server)
+        nova_scenario = utils.NovaScenario()
+        nova_scenario._reboot_server(self.server)
         self.server.reboot.assert_called_once_with(reboot_type='SOFT')
         self.wait_for.mock.assert_called_once_with(self.server,
                                                    update_resource=self.gfm(),
@@ -110,9 +129,12 @@ class NovaScenarioTestCase(test.TestCase):
                                                    check_interval=3,
                                                    timeout=600)
         self.res_is.mock.assert_has_calls(mock.call('ACTIVE'))
+        self._test_atomic_action_timer(nova_scenario.atomic_actions_time(),
+                                       'nova.reboot_server')
 
     def test__start_server(self):
-        utils.NovaScenario()._start_server(self.server)
+        nova_scenario = utils.NovaScenario()
+        nova_scenario._start_server(self.server)
         self.server.start.assert_called_once_with()
         self.wait_for.mock.assert_called_once_with(self.server,
                                                    update_resource=self.gfm(),
@@ -120,9 +142,12 @@ class NovaScenarioTestCase(test.TestCase):
                                                    check_interval=2,
                                                    timeout=600)
         self.res_is.mock.assert_has_calls(mock.call('ACTIVE'))
+        self._test_atomic_action_timer(nova_scenario.atomic_actions_time(),
+                                       'nova.start_server')
 
     def test__stop_server(self):
-        utils.NovaScenario()._stop_server(self.server)
+        nova_scenario = utils.NovaScenario()
+        nova_scenario._stop_server(self.server)
         self.server.stop.assert_called_once_with()
         self.wait_for.mock.assert_called_once_with(self.server,
                                                    update_resource=self.gfm(),
@@ -130,9 +155,12 @@ class NovaScenarioTestCase(test.TestCase):
                                                    check_interval=2,
                                                    timeout=600)
         self.res_is.mock.assert_has_calls(mock.call('SHUTOFF'))
+        self._test_atomic_action_timer(nova_scenario.atomic_actions_time(),
+                                       'nova.stop_server')
 
     def test__rescue_server(self):
-        utils.NovaScenario()._rescue_server(self.server)
+        nova_scenario = utils.NovaScenario()
+        nova_scenario._rescue_server(self.server)
         self.server.rescue.assert_called_once_with()
         self.wait_for.mock.assert_called_once_with(self.server,
                                                    update_resource=self.gfm(),
@@ -140,9 +168,12 @@ class NovaScenarioTestCase(test.TestCase):
                                                    check_interval=3,
                                                    timeout=600)
         self.res_is.mock.assert_has_calls(mock.call('RESCUE'))
+        self._test_atomic_action_timer(nova_scenario.atomic_actions_time(),
+                                       'nova.rescue_server')
 
-    def test__unresque_server(self):
+    def test__unrescue_server(self):
-        utils.NovaScenario()._unrescue_server(self.server)
+        nova_scenario = utils.NovaScenario()
+        nova_scenario._unrescue_server(self.server)
         self.server.unrescue.assert_called_once_with()
         self.wait_for.mock.assert_called_once_with(self.server,
                                                    update_resource=self.gfm(),
@@ -150,13 +181,16 @@ class NovaScenarioTestCase(test.TestCase):
                                                    check_interval=3,
                                                    timeout=600)
         self.res_is.mock.assert_has_calls(mock.call('ACTIVE'))
+        self._test_atomic_action_timer(nova_scenario.atomic_actions_time(),
+                                       'nova.unrescue_server')
 
     @mock.patch(BM_UTILS + ".is_none")
     @mock.patch(NOVA_UTILS + '.NovaScenario.clients')
     def test__delete_all_servers(self, mock_clients, mock_isnone):
         mock_clients("nova").servers.list.return_value = [self.server,
                                                           self.server1]
-        utils.NovaScenario()._delete_all_servers()
+        nova_scenario = utils.NovaScenario()
+        nova_scenario._delete_all_servers()
         expected = [
             mock.call(self.server, is_ready=mock_isnone,
                       update_resource=self.gfm(),
@@ -166,9 +200,12 @@ class NovaScenarioTestCase(test.TestCase):
                       check_interval=3, timeout=600)
         ]
         self.assertEqual(expected, self.wait_for.mock.mock_calls)
+        self._test_atomic_action_timer(nova_scenario.atomic_actions_time(),
+                                       'nova.delete_all_servers')
 
     def test__delete_image(self):
-        utils.NovaScenario()._delete_image(self.image)
+        nova_scenario = utils.NovaScenario()
+        nova_scenario._delete_image(self.image)
         self.image.delete.assert_called_once_with()
         self.wait_for.mock.assert_called_once_with(self.image,
                                                    update_resource=self.gfm(),
@@ -176,12 +213,15 @@ class NovaScenarioTestCase(test.TestCase):
                                                    check_interval=3,
                                                    timeout=600)
         self.res_is.mock.assert_has_calls(mock.call('DELETED'))
+        self._test_atomic_action_timer(nova_scenario.atomic_actions_time(),
+                                       'nova.delete_image')
 
     @mock.patch(NOVA_UTILS + '.NovaScenario.clients')
     def test__boot_servers(self, mock_clients):
         mock_clients("nova").servers.list.return_value = [self.server,
                                                           self.server1]
-        utils.NovaScenario()._boot_servers('prefix', 'image', 'flavor', 2)
+        nova_scenario = utils.NovaScenario()
+        nova_scenario._boot_servers('prefix', 'image', 'flavor', 2)
         expected = [
             mock.call(self.server, is_ready=self.res_is.mock(),
                       update_resource=self.gfm(),
@@ -192,3 +232,5 @@ class NovaScenarioTestCase(test.TestCase):
         ]
         self.assertEqual(expected, self.wait_for.mock.mock_calls)
         self.res_is.mock.assert_has_calls(mock.call('ACTIVE'))
+        self._test_atomic_action_timer(nova_scenario.atomic_actions_time(),
+                                       'nova.boot_servers')

tests/benchmark/scenarios/test_utils.py

@@ -184,3 +184,10 @@ class ActionBuilderTestCase(test.TestCase):
         for i in range(3):
             mock_calls.append(mock.call('two', 'three', c=3, d=4))
         mock_action_two.assert_has_calls(mock_calls)
+
+
+def get_atomic_action_timer_value_by_name(atomic_actions_times, name):
+    for action_time in atomic_actions_times:
+        if action_time['action'] == name:
+            return action_time['duration']
+    return None

tests/benchmark/test_runner.py

@@ -85,7 +85,8 @@ class ScenarioTestCase(test.TestCase):
                                                  "active_users": active_users,
                                                  "timeout": 2})
                 expected = [{"time": 10, "idle_time": 0, "error": None,
-                             "scenario_output": None}
+                             "scenario_output": None,
+                             "atomic_actions_time": []}
                             for i in range(times)]
                 self.assertEqual(results, expected)
 
@@ -95,7 +96,8 @@ class ScenarioTestCase(test.TestCase):
                                                  "active_users": active_users,
                                                  "timeout": 2})
                 expected = [{"time": 10, "idle_time": 0, "error": None,
-                             "scenario_output": None}
+                             "scenario_output": None,
+                             "atomic_actions_time": []}
                             for i in range(active_users)]
                 self.assertEqual(results, expected)