[CRIU] [PATCH 2/2] p.haul: add logging of fs migration progress

[Nikita Spiridonov]

Rework migration_stats, add logging of fs migration progress
for initial iteration, intermediate iterations and final fs
sync.

Signed-off-by: Nikita Spiridonov <nspiridonov at virtuozzo.com>
---
 phaul/iters.py  |   26 +++++++++++++-------------
 phaul/mstats.py |   41 ++++++++++++++++++++++++++++-------------
 2 files changed, 41 insertions(+), 26 deletions(-)

diff --git a/phaul/iters.py b/phaul/iters.py
index 89a7841..8adf4a2 100644
--- a/phaul/iters.py
+++ b/phaul/iters.py
@@ -100,17 +100,19 @@ class phaul_iter_worker:
 
 	def start_migration(self):
 
-		migration_stats = mstats.migration_stats()
 		prev_dstats = None
 		iter_index = 0
 
-		migration_stats.start()
+		migration_stats = mstats.migration_stats()
+		migration_stats.handle_start()
+
+		self.fs.set_work_dir(self.img.work_dir())
 
 		self.validate_cpu()
 
 		logging.info("Preliminary FS migration")
-		self.fs.set_work_dir(self.img.work_dir())
-		self.fs.start_migration()
+		fsstats = self.fs.start_migration()
+		migration_stats.handle_fs_start(fsstats)
 
 		logging.info("Checking for Dirty Tracking")
 		if self.__pre_dump == PRE_DUMP_AUTO_DETECT:
@@ -133,25 +135,25 @@ class phaul_iter_worker:
 			self.criu_connection.memory_tracking(False)
 
 		while self.__pre_dump:
-			logging.info("* Iteration %d", iter_index)
 
+			logging.info("* Iteration %d", iter_index)
 			self.target_host.start_iter(True)
 			self.img.new_image_dir()
 
 			logging.info("\tIssuing pre-dump command to service")
-
 			req = criu_req.make_predump_req(
 				self.pid, self.img, self.criu_connection, self.fs)
 			resp = self.criu_connection.send_req(req)
 			if not resp.success:
 				raise Exception("Pre-dump failed")
-
 			logging.info("\tPre-dump succeeded")
 
+			fsstats = self.fs.next_iteration()
+
 			self.target_host.end_iter()
 
 			dstats = criu_api.criu_get_dstats(self.img)
-			migration_stats.iteration(dstats)
+			migration_stats.handle_iteration(dstats, fsstats)
 
 			#
 			# Need to decide whether we do next iteration
@@ -180,8 +182,6 @@ class phaul_iter_worker:
 			prev_dstats = dstats
 			logging.info("\t> Proceed to next iteration")
 
-			self.fs.next_iteration()
-
 		#
 		# Finish with iterations -- do full dump, send images
 		# to target host and restore from them there
@@ -205,7 +205,7 @@ class phaul_iter_worker:
 		#
 
 		logging.info("Final FS and images sync")
-		self.fs.stop_migration()
+		fsstats = self.fs.stop_migration()
 		self.img.sync_imgs_to_target(self.target_host, self.htype,
 			self.connection.mem_sk)
 
@@ -225,7 +225,7 @@ class phaul_iter_worker:
 		self.htype.umount()
 
 		dstats = criu_api.criu_get_dstats(self.img)
-		migration_stats.iteration(dstats)
-		migration_stats.stop(self)
+		migration_stats.handle_iteration(dstats, fsstats)
+		migration_stats.handle_stop(self)
 		self.img.close()
 		self.criu_connection.close()
diff --git a/phaul/mstats.py b/phaul/mstats.py
index d1b276d..793e84f 100644
--- a/phaul/mstats.py
+++ b/phaul/mstats.py
@@ -16,24 +16,39 @@ class migration_stats:
 		self._iter_fr_times = []
 		self._frozen_time = 0
 
-	def start(self):
+	def handle_start(self):
 		self._start_time = time.time()
 
-	def stop(self, iters):
+	def handle_fs_start(self, fsstats):
+		self.__print_fsstats(fsstats)
+
+	def handle_stop(self, iters):
 		self._rst_time = iters.get_target_host().restore_time()
 		self._img_sync_time = iters.img.img_sync_time()
 		self._end_time = time.time()
-
-		self._print_stats()
-
-	def iteration(self, stats):
-		logging.info("Dumped %d pages, %d skipped",
-			stats.pages_written, stats.pages_skipped_parent)
-
-		self._iter_fr_times.append("%.2lf" % usec2sec(stats.frozen_time))
-		self._frozen_time += stats.frozen_time
-
-	def _print_stats(self):
+		self.__print_overall_stats()
+
+	def handle_iteration(self, dstats, fsstats):
+		self._iter_fr_times.append("%.2lf" % usec2sec(dstats.frozen_time))
+		self._frozen_time += dstats.frozen_time
+		self.__print_dstats(dstats)
+		self.__print_fsstats(fsstats)
+
+	def __print_dstats(self, dstats):
+		if dstats:
+			logging.info("Dumped %d pages, %d skipped",
+				dstats.pages_written, dstats.pages_skipped_parent)
+
+	def __print_fsstats(self, fsstats):
+		if fsstats:
+			mbytes_xferred_str = ""
+			mbytes_xferred = fsstats.bytes_xferred >> 20
+			if mbytes_xferred != 0:
+				mbytes_xferred_str = " (~{0}Mb)".format(mbytes_xferred)
+			logging.info("Fs driver transfer %d bytes%s",
+				fsstats.bytes_xferred, mbytes_xferred_str)
+
+	def __print_overall_stats(self):
 		logging.info("Migration succeeded")
 		logging.info("\t   total time is ~%.2lf sec", self._end_time - self._start_time)
 		logging.info("\t  frozen time is ~%.2lf sec (%s)", usec2sec(self._frozen_time), str(self._iter_fr_times))
-- 
1.7.1