Merge pull request #27 from PageUpPeopleOrg/feature/log-stats-upon-completion

log stats upon completion

Author: ChintanRaval

dpo/Shared.py

@@ -36,6 +36,10 @@ class StepName:
 _defaultLogLevelString = logging.getLevelName(logging.INFO)
 
 
+def safe_format_number(x, default_value=''):
+    return default_value if x is None else f'{x:,}'
+
+
 def configure_root_logger(log_level):
     # get the root logger
     logger = logging.getLogger()

dpo/commands/CompleteExecutionCommand.py

@@ -9,3 +9,12 @@ def __init__(self, db_connection_string, execution_id, logger=None):
     def execute(self):
         execution = self.repository.complete_execution(self._execution_id)
         self.logger.debug('Completed Execution: ' + str(execution))
+
+        total_execution_seconds = execution.execution_time_ms // 1000
+        execution_hours = total_execution_seconds // 3600
+        execution_minutes = (total_execution_seconds // 60) % 60
+        execution_seconds = total_execution_seconds % 60
+        self.logger.info(f'Completed Execution ID: {execution.execution_id}; '
+                         f'Started On: {execution.started_on.isoformat()}; '
+                         f'Completed On: {execution.completed_on.isoformat()}; '
+                         f'Execution Time: {execution_hours}h {execution_minutes}m {execution_seconds}s.')

dpo/commands/CompleteStepCommand.py

@@ -1,12 +1,27 @@
 from dpo.commands.BaseCommand import BaseCommand
+from dpo import Shared
 
 
 class CompleteStepCommand(BaseCommand):
     def __init__(self, db_connection_string, step_id, rows_processed, logger=None):
         super().__init__(db_connection_string, logger)
         self._step_id = step_id
         self._rows_processed = rows_processed
+        self.logger.debug(f'step_id={self._step_id};'
+                          f'rows_processed={self._rows_processed}')
 
     def execute(self):
         execution_step = self.repository.complete_execution_step(self._step_id, self._rows_processed)
         self.logger.debug('Completed Execution Step: ' + str(execution_step))
+
+        total_execution_seconds = execution_step.execution_time_ms // 1000
+        execution_hours = total_execution_seconds // 3600
+        execution_minutes = (total_execution_seconds // 60) % 60
+        execution_seconds = total_execution_seconds % 60
+        execution_step_models = self.repository.get_execution_step_models(self._step_id)
+        self.logger.info(f'Completed Execution Step: {execution_step.step_name}; '
+                         f'Started On: {execution_step.started_on.isoformat()}; '
+                         f'Completed On: {execution_step.completed_on.isoformat()}; '
+                         f'Execution Time: {execution_hours}h {execution_minutes}m {execution_seconds}s; '
+                         f'Models Processed: {Shared.safe_format_number(len(execution_step_models))}; '
+                         f'Rows Processed: {Shared.safe_format_number(execution_step.rows_processed, "N/A")}.')

dpo/entities/execution_entity.py

@@ -54,4 +54,4 @@ def __str__(self):
                f'status={self.status}, ' \
                f'started_on={self.started_on}, ' \
                f'completed_on={self.completed_on}, ' \
-               f'execution_time_ms={self.execution_time_ms}.'
+               f'execution_time_ms={Shared.safe_format_number(self.execution_time_ms)}.'

dpo/entities/execution_step_entity.py

@@ -65,13 +65,13 @@ class ExecutionStepEntity(Shared.BaseEntity):
                             nullable=True)
 
     def __str__(self):
-        return f'execution_step_id={self.execution_step_id}, ' \
+        return f'execution_id={self.execution_id}, ' \
+               f'execution_step_id={self.execution_step_id}, ' \
                f'created_on={self.created_on}, ' \
                f'updated_on={self.updated_on}, ' \
-               f'execution_id={self.execution_id}, ' \
                f'step_name={self.step_name}, ' \
                f'status={self.status}, ' \
                f'started_on={self.started_on}, ' \
                f'completed_on={self.completed_on}, ' \
-               f'execution_time_ms={self.execution_time_ms}, ' \
-               f'rows_processed={self.rows_processed}.'
+               f'execution_time_ms={Shared.safe_format_number(self.execution_time_ms)}, ' \
+               f'rows_processed={Shared.safe_format_number(self.rows_processed)}.'