Merge "Timing metrics: pxe boot and iscsi deploy driver"

ironic/drivers/modules/agent_base_vendor.py

@@ -20,6 +20,7 @@ import ast
 import collections
 import time
 
+from ironic_lib import metrics_utils
 from oslo_log import log
 from oslo_utils import excutils
 from oslo_utils import strutils
@@ -47,6 +48,8 @@ from ironic import objects
 
 LOG = log.getLogger(__name__)
 
+METRICS = metrics_utils.get_metrics_logger(__name__)
+
 # This contains a nested dictionary containing the post clean step
 # hooks registered for each clean step of every interface.
 # Every key of POST_CLEAN_STEP_HOOKS is an interface and its value
@@ -81,6 +84,7 @@ def _get_client():
     return client
 
 
+@METRICS.timer('post_clean_step_hook')
 def post_clean_step_hook(interface, step):
     """Decorator method for adding a post clean step hook.
 
@@ -205,6 +209,7 @@ def _get_completed_cleaning_command(task, commands):
         return last_command
 
 
+@METRICS.timer('log_and_raise_deployment_error')
 def log_and_raise_deployment_error(task, msg):
     """Helper method to log the error and raise exception."""
     LOG.error(msg)
@@ -246,6 +251,7 @@ class AgentDeployMixin(object):
 
         """
 
+    @METRICS.timer('AgentDeployMixin._refresh_clean_steps')
     def _refresh_clean_steps(self, task):
         """Refresh the node's cached clean steps from the booted agent.
 
@@ -302,6 +308,7 @@ class AgentDeployMixin(object):
         LOG.debug('Refreshed agent clean step cache for node %(node)s: '
                   '%(steps)s', {'node': node.uuid, 'steps': steps})
 
+    @METRICS.timer('AgentDeployMixin.continue_cleaning')
     def continue_cleaning(self, task, **kwargs):
         """Start the next cleaning step if the previous one is complete.
 
@@ -435,6 +442,7 @@ class AgentDeployMixin(object):
             LOG.error(msg)
             return manager_utils.cleaning_error_handler(task, msg)
 
+    @METRICS.timer('AgentDeployMixin.heartbeat')
     def heartbeat(self, task, callback_url):
         """Process a heartbeat.
 
@@ -513,6 +521,7 @@ class AgentDeployMixin(object):
             elif node.provision_state in (states.DEPLOYING, states.DEPLOYWAIT):
                 deploy_utils.set_failed_state(task, last_error)
 
+    @METRICS.timer('AgentDeployMixin.reboot_and_finish_deploy')
     def reboot_and_finish_deploy(self, task):
         """Helper method to trigger reboot on the node and finish deploy.
 
@@ -587,6 +596,7 @@ class AgentDeployMixin(object):
         task.process_event('done')
         LOG.info(_LI('Deployment to node %s done'), task.node.uuid)
 
+    @METRICS.timer('AgentDeployMixin.prepare_instance_to_boot')
     def prepare_instance_to_boot(self, task, root_uuid, efi_sys_uuid):
         """Prepares instance to boot.
 
@@ -611,6 +621,7 @@ class AgentDeployMixin(object):
             msg = _('Failed to continue agent deployment.')
             log_and_raise_deployment_error(task, msg)
 
+    @METRICS.timer('AgentDeployMixin.configure_local_boot')
     def configure_local_boot(self, task, root_uuid=None,
                              efi_system_part_uuid=None):
         """Helper method to configure local boot on the node.
@@ -698,6 +709,7 @@ class BaseAgentVendor(AgentDeployMixin, base.VendorInterface):
                                                     'payload version: %s')
                                                   % version)
 
+    @METRICS.timer('BaseAgentVendor.heartbeat')
     @base.passthru(['POST'])
     @task_manager.require_exclusive_lock
     def heartbeat(self, task, **kwargs):
@@ -721,6 +733,7 @@ class BaseAgentVendor(AgentDeployMixin, base.VendorInterface):
 
         super(BaseAgentVendor, self).heartbeat(task, callback_url)
 
+    @METRICS.timer('BaseAgentVendor.lookup')
     @base.driver_passthru(['POST'], async=False)
     def lookup(self, context, **kwargs):
         """Find a matching node for the agent.

ironic/drivers/modules/iscsi_deploy.py

@@ -16,6 +16,7 @@
 import os
 
 from ironic_lib import disk_utils
+from ironic_lib import metrics_utils
 from ironic_lib import utils as ironic_utils
 from oslo_config import cfg
 from oslo_log import log as logging
@@ -36,6 +37,8 @@ from ironic.drivers.modules import image_cache
 
 LOG = logging.getLogger(__name__)
 
+METRICS = metrics_utils.get_metrics_logger(__name__)
+
 # NOTE(rameshg87): This file now registers some of opts in pxe group.
 # This is acceptable for now as a future refactoring into
 # separate boot and deploy interfaces is planned, and moving config
@@ -128,6 +131,7 @@ def _save_disk_layout(node, i_info):
     node.save()
 
 
+@METRICS.timer('check_image_size')
 def check_image_size(task):
     """Check if the requested image is larger than the root partition size.
 
@@ -146,6 +150,7 @@ def check_image_size(task):
         raise exception.InstanceDeployFailure(msg)
 
 
+@METRICS.timer('cache_instance_image')
 def cache_instance_image(ctx, node):
     """Fetch the instance's image from Glance
 
@@ -171,6 +176,7 @@ def cache_instance_image(ctx, node):
     return (uuid, image_path)
 
 
+@METRICS.timer('destroy_images')
 def destroy_images(node_uuid):
     """Delete instance's image file.
 
@@ -181,6 +187,7 @@ def destroy_images(node_uuid):
     InstanceImageCache().clean_up()
 
 
+@METRICS.timer('get_deploy_info')
 def get_deploy_info(node, address, iqn, port=None, lun='1'):
     """Returns the information required for doing iSCSI deploy in a dictionary.
 
@@ -234,6 +241,7 @@ def get_deploy_info(node, address, iqn, port=None, lun='1'):
     return params
 
 
+@METRICS.timer('continue_deploy')
 def continue_deploy(task, **kwargs):
     """Resume a deployment upon getting POST data from deploy ramdisk.
 
@@ -305,6 +313,7 @@ def continue_deploy(task, **kwargs):
     return uuid_dict_returned
 
 
+@METRICS.timer('do_agent_iscsi_deploy')
 def do_agent_iscsi_deploy(task, agent_client):
     """Method invoked when deployed with the agent ramdisk.
 
@@ -374,6 +383,7 @@ def _get_boot_mode(node):
     return "bios"
 
 
+@METRICS.timer('validate')
 def validate(task):
     """Validates the pre-requisites for iSCSI deploy.
 
@@ -396,6 +406,7 @@ def validate(task):
 
 class AgentDeployMixin(agent_base_vendor.AgentDeployMixin):
 
+    @METRICS.timer('AgentDeployMixin.continue_deploy')
     @task_manager.require_exclusive_lock
     def continue_deploy(self, task):
         """Method invoked when deployed using iSCSI.
@@ -427,6 +438,7 @@ class ISCSIDeploy(AgentDeployMixin, base.DeployInterface):
     def get_properties(self):
         return {}
 
+    @METRICS.timer('ISCSIDeploy.validate')
     def validate(self, task):
         """Validate the deployment information for the task's node.
 
@@ -445,6 +457,7 @@ class ISCSIDeploy(AgentDeployMixin, base.DeployInterface):
         # broken down into separate boot and deploy implementations.
         validate(task)
 
+    @METRICS.timer('ISCSIDeploy.deploy')
     @task_manager.require_exclusive_lock
     def deploy(self, task):
         """Start deployment of the task's node.
@@ -465,6 +478,7 @@ class ISCSIDeploy(AgentDeployMixin, base.DeployInterface):
 
         return states.DEPLOYWAIT
 
+    @METRICS.timer('ISCSIDeploy.tear_down')
     @task_manager.require_exclusive_lock
     def tear_down(self, task):
         """Tear down a previous deployment on the task's node.
@@ -484,6 +498,7 @@ class ISCSIDeploy(AgentDeployMixin, base.DeployInterface):
         task.driver.network.unconfigure_tenant_networks(task)
         return states.DELETED
 
+    @METRICS.timer('ISCSIDeploy.prepare')
     @task_manager.require_exclusive_lock
     def prepare(self, task):
         """Prepare the deployment environment for this task's node.
@@ -514,6 +529,7 @@ class ISCSIDeploy(AgentDeployMixin, base.DeployInterface):
             deploy_opts = deploy_utils.build_agent_options(node)
             task.driver.boot.prepare_ramdisk(task, deploy_opts)
 
+    @METRICS.timer('ISCSIDeploy.clean_up')
     def clean_up(self, task):
         """Clean up the deployment environment for the task's node.
 
@@ -531,6 +547,7 @@ class ISCSIDeploy(AgentDeployMixin, base.DeployInterface):
     def take_over(self, task):
         pass
 
+    @METRICS.timer('ISCSIDeploy.get_clean_steps')
     def get_clean_steps(self, task):
         """Get the list of clean steps from the agent.
 
@@ -546,6 +563,7 @@ class ISCSIDeploy(AgentDeployMixin, base.DeployInterface):
                 'erase_devices': CONF.deploy.erase_devices_priority})
         return steps
 
+    @METRICS.timer('ISCSIDeploy.execute_clean_step')
     def execute_clean_step(self, task, step):
         """Execute a clean step asynchronously on the agent.
 
@@ -558,6 +576,7 @@ class ISCSIDeploy(AgentDeployMixin, base.DeployInterface):
         """
         return deploy_utils.agent_execute_clean_step(task, step)
 
+    @METRICS.timer('ISCSIDeploy.prepare_cleaning')
     def prepare_cleaning(self, task):
         """Boot into the agent to prepare for cleaning.
 
@@ -569,6 +588,7 @@ class ISCSIDeploy(AgentDeployMixin, base.DeployInterface):
         return deploy_utils.prepare_inband_cleaning(
             task, manage_boot=True)
 
+    @METRICS.timer('ISCSIDeploy.tear_down_cleaning')
     def tear_down_cleaning(self, task):
         """Clean up the PXE and DHCP files after cleaning.
 

ironic/drivers/modules/pxe.py

@@ -18,6 +18,7 @@ PXE Boot Interface
 import os
 import shutil
 
+from ironic_lib import metrics_utils
 from ironic_lib import utils as ironic_utils
 from oslo_config import cfg
 from oslo_log import log as logging
@@ -93,6 +94,8 @@ pxe_opts = [
 
 LOG = logging.getLogger(__name__)
 
+METRICS = metrics_utils.get_metrics_logger(__name__)
+
 CONF = cfg.CONF
 CONF.register_opts(pxe_opts, group='pxe')
 CONF.import_opt('deploy_callback_timeout', 'ironic.conductor.manager',
@@ -240,6 +243,7 @@ def _build_pxe_config_options(task, pxe_info):
     return pxe_options
 
 
+@METRICS.timer('validate_boot_option_for_uefi')
 def validate_boot_option_for_uefi(node):
     """In uefi boot mode, validate if the boot option is compatible.
 
@@ -263,6 +267,7 @@ def validate_boot_option_for_uefi(node):
             {'node_uuid': node.uuid})
 
 
+@METRICS.timer('validate_boot_option_for_trusted_boot')
 def validate_boot_parameters_for_trusted_boot(node):
     """Check if boot parameters are valid for trusted boot."""
     boot_mode = deploy_utils.get_boot_mode_for_deploy(node)
@@ -335,6 +340,7 @@ class PXEBoot(base.BootInterface):
         """
         return COMMON_PROPERTIES
 
+    @METRICS.timer('PXEBoot.validate')
     def validate(self, task):
         """Validate the PXE-specific info for booting deploy/instance images.
 
@@ -385,6 +391,7 @@ class PXEBoot(base.BootInterface):
             props = ['kernel', 'ramdisk']
         deploy_utils.validate_image_properties(task.context, d_info, props)
 
+    @METRICS.timer('PXEBoot.prepare_ramdisk')
     def prepare_ramdisk(self, task, ramdisk_params):
         """Prepares the boot of Ironic ramdisk using PXE.
 
@@ -441,6 +448,7 @@ class PXEBoot(base.BootInterface):
         # the image kernel and ramdisk (Or even require it).
         _cache_ramdisk_kernel(task.context, node, pxe_info)
 
+    @METRICS.timer('PXEBoot.clean_up_ramdisk')
     def clean_up_ramdisk(self, task):
         """Cleans up the boot of ironic ramdisk.
 
@@ -461,6 +469,7 @@ class PXEBoot(base.BootInterface):
         else:
             _clean_up_pxe_env(task, images_info)
 
+    @METRICS.timer('PXEBoot.prepare_instance')
     def prepare_instance(self, task):
         """Prepares the boot of instance.
 
@@ -525,6 +534,7 @@ class PXEBoot(base.BootInterface):
             pxe_utils.clean_up_pxe_config(task)
             deploy_utils.try_set_boot_device(task, boot_devices.DISK)
 
+    @METRICS.timer('PXEBoot.clean_up_instance')
     def clean_up_instance(self, task):
         """Cleans up the boot of instance.
 

ironic/tests/unit/drivers/modules/test_agent_base_vendor.py

@@ -957,9 +957,10 @@ class TestHeartbeat(AgentDeployMixinBaseTest):
                                   shared=False) as task:
             self.deploy.prepare_instance_to_boot(task, root_uuid,
                                                  efi_system_part_uuid)
-            configure_mock.assert_called_once_with(self.deploy, task,
+            configure_mock.assert_called_once_with(
-                                                   root_uuid,
+                self.deploy, task,
-                                                   efi_system_part_uuid)
+                root_uuid=root_uuid,
+                efi_system_part_uuid=efi_system_part_uuid)
             boot_option_mock.assert_called_once_with(task.node)
             prepare_instance_mock.assert_called_once_with(task.driver.boot,
                                                           task)
@@ -991,9 +992,10 @@ class TestHeartbeat(AgentDeployMixinBaseTest):
             self.assertRaises(exception.InstanceDeployFailure,
                               self.deploy.prepare_instance_to_boot, task,
                               root_uuid, efi_system_part_uuid)
-            configure_mock.assert_called_once_with(self.deploy, task,
+            configure_mock.assert_called_once_with(
-                                                   root_uuid,
+                self.deploy, task,
-                                                   efi_system_part_uuid)
+                root_uuid=root_uuid,
+                efi_system_part_uuid=efi_system_part_uuid)
             boot_option_mock.assert_called_once_with(task.node)
             self.assertFalse(prepare_mock.called)
             self.assertFalse(failed_state_mock.called)