From 9694ea7fd553efa250448b2e42fcd8a81a2fdbe5 Mon Sep 17 00:00:00 2001 From: Aarti Kriplani Date: Fri, 22 Mar 2013 09:54:35 +0530 Subject: 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 --- nova/tests/virt/xenapi/test_vm_utils.py | 21 +++++++++++++++++++++ nova/virt/xenapi/vm_utils.py | 19 +++++++++++++++++-- 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, " -- cgit