Skip to content

Commit

Permalink
Feature/rcs/profiling (#132)
Browse files Browse the repository at this point in the history
* initial timer class and context manager

* change log rotation defaults

* Timer.elapsed_time_formatted property

* implement duration logging in deployment
  • Loading branch information
blueskyjunkie authored Mar 3, 2022
1 parent b2a7961 commit 6f9a5dd
Show file tree
Hide file tree
Showing 4 changed files with 164 additions and 60 deletions.
4 changes: 2 additions & 2 deletions foodx_devops_tools/_declarations.py
Original file line number Diff line number Diff line change
Expand Up @@ -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"]
124 changes: 66 additions & 58 deletions foodx_devops_tools/deploy_me/_deployment.py
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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(
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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(
Expand All @@ -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
)
Expand All @@ -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
Expand Down
71 changes: 71 additions & 0 deletions foodx_devops_tools/profiling.py
Original file line number Diff line number Diff line change
@@ -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 <https://opensource.org/licenses/MIT>.

"""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
25 changes: 25 additions & 0 deletions tests/ci/unit_tests/test_profiling.py
Original file line number Diff line number Diff line change
@@ -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 <https://opensource.org/licenses/MIT>.

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"

0 comments on commit 6f9a5dd

Please sign in to comment.