xenapi: Added logging for sparse copy

After 300 seconds(default), logs how many bytes have been written
already, and how many are left, so as to be able to track progress of
the long running task.
Implements blueprint log-progress-of-sparse-copy

Change-Id: I289ab978ec4b31f1015c783111c01a460de33f09

2 files changed, 38 insertions, 2 deletions

diff --git a/nova/tests/virt/xenapi/test_vm_utils.py b/nova/tests/virt/xenapi/test_vm_utils.py
index 3f7de1521..f2a75d899 100644
--- a/nova/tests/virt/xenapi/test_vm_utils.py
+++ b/nova/tests/virt/xenapi/test_vm_utils.py
@@ -24,6 +24,7 @@ from nova.compute import flavors
 from nova import context
 from nova import db
 from nova import exception
+from nova.openstack.common import timeutils
 from nova import test
 from nova.tests.virt.xenapi import stubs
 from nova import utils
@@ -364,6 +365,26 @@ class ResizeHelpersTestCase(test.TestCase):
 
         vm_utils._resize_part_and_fs("fake", 0, 20, 10)
 
+    def test_log_progress_if_required(self):
+        self.mox.StubOutWithMock(vm_utils.LOG, "debug")
+        vm_utils.LOG.debug(_("Sparse copy in progress, "
+                             "%(complete_pct).2f%% complete. "
+                             "%(left) bytes left to copy"),
+                           {"complete_pct": 50.0, "left": 1})
+        current = timeutils.utcnow()
+        timeutils.set_time_override(current)
+        timeutils.advance_time_seconds(vm_utils.PROGRESS_INTERVAL_SECONDS + 1)
+        self.mox.ReplayAll()
+        vm_utils._log_progress_if_required(1, current, 2)
+
+    def test_log_progress_if_not_required(self):
+        self.mox.StubOutWithMock(vm_utils.LOG, "debug")
+        current = timeutils.utcnow()
+        timeutils.set_time_override(current)
+        timeutils.advance_time_seconds(vm_utils.PROGRESS_INTERVAL_SECONDS - 1)
+        self.mox.ReplayAll()
+        vm_utils._log_progress_if_required(1, current, 2)
+
     def test_resize_part_and_fs_down_fails_disk_too_big(self):
         self.mox.StubOutWithMock(vm_utils, "_repair_filesystem")
         self.mox.StubOutWithMock(utils, 'execute')
diff --git a/nova/virt/xenapi/vm_utils.py b/nova/virt/xenapi/vm_utils.py
index fde075000..0c54dc1dd 100644
--- a/nova/virt/xenapi/vm_utils.py
+++ b/nova/virt/xenapi/vm_utils.py
@@ -46,6 +46,7 @@ from nova.openstack.common import excutils
 from nova.openstack.common import log as logging
 from nova.openstack.common import processutils
 from nova.openstack.common import strutils
+from nova.openstack.common import timeutils
 from nova import utils
 from nova.virt import configdrive
 from nova.virt.disk import api as disk
@@ -145,6 +146,7 @@ MBR_SIZE_SECTORS = 63
 MBR_SIZE_BYTES = MBR_SIZE_SECTORS * SECTOR_SIZE
 KERNEL_DIR = '/boot/guest'
 MAX_VDI_CHAIN_SIZE = 16
+PROGRESS_INTERVAL_SECONDS = 300
 
 
 class ImageType(object):
@@ -2138,9 +2140,20 @@ def _resize_part_and_fs(dev, start, old_sectors, new_sectors):
     utils.execute('tune2fs', '-j', partition_path, run_as_root=True)
 
 
+def _log_progress_if_required(left, last_log_time, virtual_size):
+    if timeutils.is_older_than(last_log_time, PROGRESS_INTERVAL_SECONDS):
+        last_log_time = timeutils.utcnow()
+        complete_pct = float(virtual_size - left) / virtual_size * 100
+        LOG.debug(_("Sparse copy in progress, "
+                    "%(complete_pct).2f%% complete. "
+                    "%(left) bytes left to copy"),
+            {"complete_pct": complete_pct, "left": left})
+    return last_log_time
+
+
 def _sparse_copy(src_path, dst_path, virtual_size, block_size=4096):
     """Copy data, skipping long runs of zeros to create a sparse file."""
-    start_time = time.time()
+    start_time = last_log_time = timeutils.utcnow()
     EMPTY_BLOCK = '\0' * block_size
     bytes_read = 0
     skipped_bytes = 0
@@ -2175,8 +2188,10 @@ def _sparse_copy(src_path, dst_path, virtual_size, block_size=4096):
 
                         data = src.read(min(block_size, left))
                         greenthread.sleep(0)
+                        last_log_time = _log_progress_if_required(
+                            left, last_log_time, virtual_size)
 
-    duration = time.time() - start_time
+    duration = timeutils.delta_seconds(start_time, timeutils.utcnow())
     compression_pct = float(skipped_bytes) / bytes_read * 100
 
     LOG.debug(_("Finished sparse_copy in %(duration).2f secs, "