From 202ebc2d987c86984ba9cf8e8e36c32899baaa3b Mon Sep 17 00:00:00 2001 From: John Griffith Date: Wed, 6 Aug 2014 22:17:44 -0600 Subject: [PATCH] Add timer info for copy operations This is just an add of some useful info to monitor how much time we spend on various operations during clear volume and copy image_to_volume. Change-Id: Ie9d199769e63f5a91270e3fc2e5f58766d1bd41c --- cinder/image/image_utils.py | 33 ++++++++++++++++++++++++++++++++ cinder/tests/test_image_utils.py | 28 +++++++++++++++++++++++---- cinder/volume/utils.py | 28 +++++++++++++++++++++++++++ 3 files changed, 85 insertions(+), 4 deletions(-) diff --git a/cinder/image/image_utils.py b/cinder/image/image_utils.py index 1ef9e2876..bd631eac2 100644 --- a/cinder/image/image_utils.py +++ b/cinder/image/image_utils.py @@ -36,6 +36,7 @@ from cinder.openstack.common.gettextutils import _ from cinder.openstack.common import imageutils from cinder.openstack.common import log as logging from cinder.openstack.common import processutils +from cinder.openstack.common import timeutils from cinder.openstack.common import units from cinder import utils from cinder.volume import utils as volume_utils @@ -62,6 +63,7 @@ def qemu_img_info(path): def convert_image(source, dest, out_format, bps_limit=None): """Convert image to other format.""" + start_time = timeutils.utcnow() cmd = ('qemu-img', 'convert', '-O', out_format, source, dest) cgcmd = volume_utils.setup_blkio_cgroup(source, dest, bps_limit) if cgcmd: @@ -69,6 +71,23 @@ def convert_image(source, dest, out_format, bps_limit=None): cmd += ('-t', 'none') # required to enable ratelimit by blkio cgroup utils.execute(*cmd, run_as_root=True) + duration = timeutils.delta_seconds(start_time, timeutils.utcnow()) + + # NOTE(jdg): use a default of 1, mostly for unit test, but in + # some incredible event this is 0 (cirros image?) don't barf + if duration < 1: + duration = 1 + fsz_mb = os.stat(source).st_size / units.Mi + mbps = (fsz_mb / duration) + LOG.debug('Image conversion details: src %(src)s, size %(sz).2f MB, ' + 'duration %(duration).2f, destination %(dest)s', + {'src': source, + 'sz': fsz_mb, + 'duration': duration, + 'dest': dest}) + LOG.info(_('Converted %(sz).2f MB image at %(mbps).2f MB/s'), + {'sz': fsz_mb, 'mbps': mbps}) + def resize_image(source, size, run_as_root=False): """Changes the virtual size of the image.""" @@ -81,9 +100,23 @@ def fetch(context, image_service, image_id, path, _user_id, _project_id): # when it is added to glance. Right now there is no # auth checking in glance, so we assume that access was # checked before we got here. + start_time = timeutils.utcnow() with fileutils.remove_path_on_error(path): with open(path, "wb") as image_file: image_service.download(context, image_id, image_file) + duration = timeutils.delta_seconds(start_time, timeutils.utcnow()) + + # NOTE(jdg): use a default of 1, mostly for unit test, but in + # some incredible event this is 0 (cirros image?) don't barf + if duration < 1: + duration = 1 + fsz_mb = os.stat(image_file.name).st_size / units.Mi + mbps = (fsz_mb / duration) + LOG.debug('Image fetch details: dest %(dest)s, size %(sz).2f MB, ' + 'duration %(duration).2f sec', + {'dest:': image_file.name, 'sz': fsz_mb, 'duration': duration}) + LOG.info(_('Image download %(sz).2f MB at %(mbps).2f MB/s'), + {'sz': fsz_mb, 'mbps': mbps}) def fetch_verify_image(context, image_service, image_id, dest, diff --git a/cinder/tests/test_image_utils.py b/cinder/tests/test_image_utils.py index 32d842147..048b88f56 100644 --- a/cinder/tests/test_image_utils.py +++ b/cinder/tests/test_image_utils.py @@ -16,6 +16,7 @@ """Unit tests for image utils.""" import contextlib +import mock import mox import tempfile @@ -77,7 +78,12 @@ class TestUtils(test.TestCase): mox.VerifyAll() - def test_convert_image(self): + @mock.patch('os.stat') + def test_convert_image(self, mock_stat): + + class stat_result: + st_size = 1048576 + mox = self._mox mox.StubOutWithMock(utils, 'execute') @@ -251,7 +257,9 @@ class TestUtils(test.TestCase): self._mox.ReplayAll() - def test_fetch_to_raw(self): + @mock.patch('os.stat') + def test_fetch_to_raw(self, mock_stat): + SRC_INFO = ("image: qemu.qcow2\n" "file_format: qcow2 \n" "virtual_size: 50M (52428800 bytes)\n" @@ -263,6 +271,9 @@ class TestUtils(test.TestCase): "cluster_size: 65536\n" "disk_size: 196K (200704 bytes)\n") + class stat_result: + st_size = 1048576 + self._test_fetch_to_raw(src_inf=SRC_INFO, dest_inf=DST_INFO) image_utils.fetch_to_raw(context, self._image_service, @@ -270,7 +281,8 @@ class TestUtils(test.TestCase): mox.IgnoreArg()) self._mox.VerifyAll() - def test_fetch_to_raw_with_bps_limit(self): + @mock.patch('os.stat') + def test_fetch_to_raw_with_bps_limit(self, mock_stat): SRC_INFO = ("image: qemu.qcow2\n" "file_format: qcow2 \n" "virtual_size: 50M (52428800 bytes)\n" @@ -282,6 +294,9 @@ class TestUtils(test.TestCase): "cluster_size: 65536\n" "disk_size: 196K (200704 bytes)\n") + class stat_result: + st_size = 1048576 + self._test_fetch_to_raw(src_inf=SRC_INFO, dest_inf=DST_INFO, bps_limit=1048576) @@ -333,13 +348,18 @@ class TestUtils(test.TestCase): mox.IgnoreArg()) self._mox.VerifyAll() - def test_fetch_to_raw_on_error_not_convert_to_raw(self): + @mock.patch('os.stat') + def test_fetch_to_raw_on_error_not_convert_to_raw(self, mock_stat): + IMG_INFO = ("image: qemu.qcow2\n" "file_format: qcow2 \n" "virtual_size: 50M (52428800 bytes)\n" "cluster_size: 65536\n" "disk_size: 196K (200704 bytes)") + class stat_result: + st_size = 1048576 + self._test_fetch_to_raw(src_inf=IMG_INFO, dest_inf=IMG_INFO) self.assertRaises(exception.ImageUnacceptable, diff --git a/cinder/volume/utils.py b/cinder/volume/utils.py index eb9bcaf74..6a4f0740e 100644 --- a/cinder/volume/utils.py +++ b/cinder/volume/utils.py @@ -26,6 +26,7 @@ from cinder.openstack.common.gettextutils import _ from cinder.openstack.common import log as logging from cinder.openstack.common import processutils from cinder.openstack.common import strutils +from cinder.openstack.common import timeutils from cinder.openstack.common import units from cinder import rpc from cinder import utils @@ -108,6 +109,7 @@ def notify_about_snapshot_usage(context, snapshot, event_suffix, def setup_blkio_cgroup(srcpath, dstpath, bps_limit, execute=utils.execute): if not bps_limit: + LOG.debug('Not using bps rate limiting on volume copy') return None try: @@ -130,6 +132,8 @@ def setup_blkio_cgroup(srcpath, dstpath, bps_limit, execute=utils.execute): return None group_name = CONF.volume_copy_blkio_cgroup_name + LOG.debug('Setting rate limit to %s bps for blkio ' + 'group: %s' % (bps_limit, group_name)) try: execute('cgcreate', '-g', 'blkio:%s' % group_name, run_as_root=True) except processutils.ProcessExecutionError: @@ -211,7 +215,23 @@ def copy_volume(srcstr, deststr, size_in_m, blocksize, sync=False, cmd = cgcmd + cmd # Perform the copy + start_time = timeutils.utcnow() execute(*cmd, run_as_root=True) + duration = timeutils.delta_seconds(start_time, timeutils.utcnow()) + + # NOTE(jdg): use a default of 1, mostly for unit test, but in + # some incredible event this is 0 (cirros image?) don't barf + if duration < 1: + duration = 1 + mbps = (size_in_m / duration) + LOG.debug(('Volume copy details: src %(src)s, dest %(dest)s, ' + 'size %(sz).2f MB, duration %(duration).2f sec'), + {'src': srcstr, + 'dest': deststr, + 'sz': size_in_m, + 'duration': duration}) + LOG.info(_('Volume copy %(sz).2f MB at %(mbps).2f MB/s'), + {'sz': size_in_m, 'duration': mbps}) def clear_volume(volume_size, volume_path, volume_clear=None, @@ -246,7 +266,15 @@ def clear_volume(volume_size, volume_path, volume_clear=None, value=volume_clear) clear_cmd.append(volume_path) + start_time = timeutils.utcnow() utils.execute(*clear_cmd, run_as_root=True) + duration = timeutils.delta_seconds(start_time, timeutils.utcnow()) + + # NOTE(jdg): use a default of 1, mostly for unit test, but in + # some incredible event this is 0 (cirros image?) don't barf + if duration < 1: + duration = 1 + LOG.info(_('Elapsed time for clear volume: %.2f sec') % duration) def supports_thin_provisioning(): -- 2.45.2