openstack/nova
Code Issues Proposed changes

xenapi: Added logging for sparse copy

Browse Source 
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
This commit is contained in:
Aarti Kriplani
2013-03-22 09:54:35 +05:30
parent 17cbb833ab
commit 9694ea7fd5
2 changed files with 38 additions and 2 deletions
Download Patch File Download Diff File Expand all files Collapse all files

21
nova/tests/virt/xenapi/test_vm_utils.py
View File

@@ -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')

19
nova/virt/xenapi/vm_utils.py
View File

@@ -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, "