diff --git a/foodx_devops_tools/_declarations.py b/foodx_devops_tools/_declarations.py index 4604c5a..d0d5cb6 100644 --- a/foodx_devops_tools/_declarations.py +++ b/foodx_devops_tools/_declarations.py @@ -17,9 +17,9 @@ DEFAULT_CONSOLE_LOGGING_ENABLED = False DEFAULT_FILE_LOGGING_DISABLED = False -DEFAULT_FILE_ROTATION_BACKUPS = 10 +DEFAULT_FILE_ROTATION_BACKUPS = 100 DEFAULT_FILE_ROTATION_ENABLED = True -DEFAULT_FILE_ROTATION_SIZE_MB = 1 +DEFAULT_FILE_ROTATION_SIZE_MB = 10 DEFAULT_LOG_LEVEL = "warning" VALID_LOG_LEVELS = ["critical", "error", "warning", "info", "debug", "notset"] diff --git a/foodx_devops_tools/deploy_me/_deployment.py b/foodx_devops_tools/deploy_me/_deployment.py index 3782039..f9a5ab8 100644 --- a/foodx_devops_tools/deploy_me/_deployment.py +++ b/foodx_devops_tools/deploy_me/_deployment.py @@ -28,6 +28,7 @@ ApplicationStepDeploymentDefinition, ApplicationStepScript, ) +from foodx_devops_tools.profiling import timing from foodx_devops_tools.puff import PuffError from ._dependency_monitor import wait_for_dependencies @@ -110,27 +111,28 @@ async def _do_application_deployment( ][deployment_data.context.azure_subscription_name] for this_step in application_data: - if isinstance(this_step, ApplicationStepDeploymentDefinition): - await deploy_step( - this_step, - deployment_data, - puff_parameter_data, - this_context, - enable_validation, - ) - elif isinstance(this_step, ApplicationStepScript): - await script_step( - this_step, - deployment_data, - this_context, - ) - elif isinstance(this_step, ApplicationStepDelay): - await delay_step(this_step.delay_seconds) - else: - raise DeploymentError( - "Bad application step definition, " - "{0}".format(this_context) - ) + with timing(log, this_context): + if isinstance(this_step, ApplicationStepDeploymentDefinition): + await deploy_step( + this_step, + deployment_data, + puff_parameter_data, + this_context, + enable_validation, + ) + elif isinstance(this_step, ApplicationStepScript): + await script_step( + this_step, + deployment_data, + this_context, + ) + elif isinstance(this_step, ApplicationStepDelay): + await delay_step(this_step.delay_seconds) + else: + raise DeploymentError( + "Bad application step definition, " + "{0}".format(this_context) + ) log.info("application deployment succeeded, {0}".format(this_context)) await application_status.write( @@ -201,13 +203,14 @@ async def deploy_application( ), ) else: - await _do_application_deployment( - this_context, - application_data.steps, - deployment_data, - application_status, - enable_validation, - ) + with timing(log, this_context): + await _do_application_deployment( + this_context, + application_data.steps, + deployment_data, + application_status, + enable_validation, + ) except Exception as e: message = "application deployment failed, {0}, {1}, {2}".format( this_context, type(e), str(e) @@ -329,13 +332,14 @@ async def deploy_frame( message="deployment targeted frame, {0}".format(str(deploy_to)), ) else: - await _do_frame_deployment( - this_context, - pipeline_parameters, - deployment_data, - frame_data, - frame_status, - ) + with timing(log, this_context): + await _do_frame_deployment( + this_context, + pipeline_parameters, + deployment_data, + frame_data, + frame_status, + ) async def do_deploy( @@ -351,6 +355,7 @@ async def do_deploy( ``pipeline_parameters`` is exceeded. """ this_frames = configuration.frames + this_context = deployment_data.data.iteration_context.copy() deployment_data.data.iteration_context.append( deployment_data.data.deployment_tuple ) @@ -361,30 +366,33 @@ async def do_deploy( timeout_seconds=pipeline_parameters.wait_timeout_seconds, ) try: - # this is a temporary work-around to the login concurrency problem - - # it works provided there is no more than a single subscription per - # deployment at a time. - # https://github.com/Food-X-Technologies/foodx_devops_tools/issues/129 - await login_service_principal(deployment_data.data.azure_credentials) - - wait_task = asyncio.create_task( - frame_deployment_status.wait_for_all_completed() - ) - frame_deployment_status.start_monitor() + with timing(log, str(this_context)): + # this is a temporary work-around to the login concurrency problem - + # it works provided there is no more than a single subscription per + # deployment at a time. + # https://github.com/Food-X-Technologies/foodx_devops_tools/issues/129 + await login_service_principal( + deployment_data.data.azure_credentials + ) - await asyncio.gather( - *[ - deploy_frame( - frame_data, - deployment_data.copy_add_frame(frame_name), - frame_deployment_status, - pipeline_parameters, - ) - for frame_name, frame_data in this_frames.frames.items() - ], - return_exceptions=False, - ) - await wait_task + wait_task = asyncio.create_task( + frame_deployment_status.wait_for_all_completed() + ) + frame_deployment_status.start_monitor() + + await asyncio.gather( + *[ + deploy_frame( + frame_data, + deployment_data.copy_add_frame(frame_name), + frame_deployment_status, + pipeline_parameters, + ) + for frame_name, frame_data in this_frames.frames.items() + ], + return_exceptions=False, + ) + await wait_task except asyncio.TimeoutError: message = "timeout waiting for frame deployments, {0}".format( deployment_data.data.iteration_context diff --git a/foodx_devops_tools/profiling.py b/foodx_devops_tools/profiling.py new file mode 100644 index 0000000..a59f1b2 --- /dev/null +++ b/foodx_devops_tools/profiling.py @@ -0,0 +1,71 @@ +# Copyright (c) 2022 Food-X Technologies +# +# This file is part of foodx_devops_tools. +# +# You should have received a copy of the MIT License along with +# foodx_devops_tools. If not, see . + +"""Utilities for maintaining timing information.""" + +import contextlib +import datetime +import logging +import time +import typing + +log = logging.getLogger(__name__) + +T = typing.TypeVar("T", bound="Timer") + + +class Timer: + """A simple relative monotonic timer.""" + + def __init__(self: T) -> None: + """Construct ``Timer`` object.""" + self.start_time_seconds: float = 0.0 + self.stop_time_seconds: float = 0.0 + + def start(self: T) -> None: + """Record the start time.""" + self.start_time_seconds = time.monotonic() + + def stop(self: T) -> None: + """Record the stop time.""" + self.stop_time_seconds = time.monotonic() + + @property + def elapsed_time_seconds(self: T) -> float: + """Calculate the elapsed time interval in seconds.""" + return self.stop_time_seconds - self.start_time_seconds + + @property + def elapsed_time_formatted(self: T) -> str: + """Calculate the elapsed time and format into a string.""" + return str(datetime.timedelta(seconds=self.elapsed_time_seconds)) + + def log_duration( + self: T, this_log: logging.Logger, iteration_context: str + ) -> None: + """Log the elapsed time of the iteration.""" + this_log.info( + f"{iteration_context} " + f"elapsed time, {self.elapsed_time_formatted}" + ) + + +@contextlib.contextmanager +def timing( + this_log: logging.Logger, + iteration_context: str, +) -> typing.Generator[Timer, None, Timer]: + """Manage the context of calculating a time interval.""" + this_timer = Timer() + this_timer.start() + + yield this_timer + + this_timer.stop() + this_timer.log_duration(this_log, iteration_context) + + return this_timer diff --git a/tests/ci/unit_tests/test_profiling.py b/tests/ci/unit_tests/test_profiling.py new file mode 100644 index 0000000..0fb760a --- /dev/null +++ b/tests/ci/unit_tests/test_profiling.py @@ -0,0 +1,25 @@ +# Copyright (c) 2022 Food-X Technologies +# +# This file is part of foodx_devops_tools. +# +# You should have received a copy of the MIT License along with +# foodx_devops_tools. If not, see . + +import logging +import time + +from foodx_devops_tools.profiling import timing + +log = logging.getLogger(__name__) + + +def test_clean(mocker): + mocker.patch( + "foodx_devops_tools.profiling.time.monotonic", side_effect=[1.2, 3.5] + ) + + with timing(log, "some.context") as t: + time.sleep(0.2) + + assert t.elapsed_time_seconds == 2.3 + assert t.elapsed_time_formatted == "0:00:02.300000"