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

diff --git a/cinder/image/image_utils.py b/cinder/image/image_utils.py
index 1ef9e287662937407210a0a88c3a08281fb2af47..bd631eac2b65d332985d3ebb6bef2dae708dbc1d 100644 (file)
--- 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 32d8421473f48242c672a3babb43fbccfec77861..048b88f560184c8389fb02463e61967d0329b928 100644 (file)
--- 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 eb9bcaf7489ae366ec1f312d0938763e31664361..6a4f0740e23a0d131fbe30144b66b6937758f39f 100644 (file)
--- 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():