diff options
| -rw-r--r-- | conversion_utils.py | 2 | ||||
| -rw-r--r-- | datetime_utils.py | 17 | ||||
| -rw-r--r-- | decorator_utils.py | 33 | ||||
| -rw-r--r-- | deferred_operand.py | 4 | ||||
| -rw-r--r-- | dict_utils.py | 10 | ||||
| -rw-r--r-- | directory_filter.py | 12 | ||||
| -rw-r--r-- | exceptions.py | 9 | ||||
| -rw-r--r-- | exec_utils.py | 4 | ||||
| -rw-r--r-- | executors.py | 268 | ||||
| -rw-r--r-- | file_utils.py | 8 | ||||
| -rwxr-xr-x | tests/parallelize_itest.py | 9 |
11 files changed, 246 insertions, 130 deletions
diff --git a/conversion_utils.py b/conversion_utils.py index 8e64a87..cf4fcaa 100644 --- a/conversion_utils.py +++ b/conversion_utils.py @@ -1,6 +1,8 @@ #!/usr/bin/env python3 # -*- coding: utf-8 -*- +"""Utilities involving converting between different units.""" + from typing import Callable, SupportsFloat import constants diff --git a/datetime_utils.py b/datetime_utils.py index 1cee516..fc1ca4e 100644 --- a/datetime_utils.py +++ b/datetime_utils.py @@ -159,9 +159,8 @@ def time_to_datetime_today(time: datetime.time) -> datetime.datetime: False """ - now = now_pacific() tz = time.tzinfo - return datetime.datetime.combine(now, time, tz) + return datetime.datetime.combine(now_pacific(), time, tz) def date_and_time_to_datetime(date: datetime.date, time: datetime.time) -> datetime.datetime: @@ -248,12 +247,12 @@ class TimeUnit(enum.IntEnum): @classmethod def is_valid(cls, value: Any): - if type(value) is int: - return value in cls._value2member_map_ - elif type(value) is TimeUnit: - return value.value in cls._value2member_map_ - elif type(value) is str: - return value in cls._member_names_ + if isinstance(value, int): + return cls(value) is not None + elif isinstance(value, TimeUnit): + return cls(value.value) is not None + elif isinstance(value, str): + return cls.__members__[value] is not None else: print(type(value)) return False @@ -508,6 +507,7 @@ def datetime_to_string( date_time_separator=date_time_separator, include_timezone=include_timezone, include_dayname=include_dayname, + use_month_abbrevs=use_month_abbrevs, include_seconds=include_seconds, include_fractional=include_fractional, twelve_hour=twelve_hour, @@ -541,6 +541,7 @@ def string_to_datetime( date_time_separator=date_time_separator, include_timezone=include_timezone, include_dayname=include_dayname, + use_month_abbrevs=use_month_abbrevs, include_seconds=include_seconds, include_fractional=include_fractional, twelve_hour=twelve_hour, diff --git a/decorator_utils.py b/decorator_utils.py index 68a9d69..5d1e779 100644 --- a/decorator_utils.py +++ b/decorator_utils.py @@ -133,7 +133,7 @@ def rate_limited(n_calls: int, *, per_period_in_seconds: float = 1.0) -> Callabl wait_time = min_interval_seconds - elapsed_since_last else: wait_time = 0.0 - logger.debug(f'@{time.time()}> wait_time = {wait_time}') + logger.debug('@%.4f> wait_time = %.4f', time.time(), wait_time) return wait_time def wrapper_wrapper_rate_limited(*args, **kargs) -> Any: @@ -145,10 +145,12 @@ def rate_limited(n_calls: int, *, per_period_in_seconds: float = 1.0) -> Callabl ): break with cv: - logger.debug(f'@{time.time()}> calling it...') + logger.debug('@%.4f> calling it...', time.time()) ret = func(*args, **kargs) last_invocation_timestamp[0] = time.time() - logger.debug(f'@{time.time()}> Last invocation <- {last_invocation_timestamp[0]}') + logger.debug( + '@%.4f> Last invocation <- %.4f', time.time(), last_invocation_timestamp[0] + ) cv.notify() return ret @@ -225,6 +227,11 @@ def debug_count_calls(func: Callable) -> Callable: class DelayWhen(enum.IntEnum): + """When should we delay: before or after calling the function (or + both)? + + """ + BEFORE_CALL = 1 AFTER_CALL = 2 BEFORE_AND_AFTER = 3 @@ -259,11 +266,11 @@ def delay( @functools.wraps(func) def wrapper_delay(*args, **kwargs): if when & DelayWhen.BEFORE_CALL: - logger.debug(f"@delay for {seconds}s BEFORE_CALL to {func.__name__}") + logger.debug("@delay for %fs BEFORE_CALL to %s", seconds, func.__name__) time.sleep(seconds) retval = func(*args, **kwargs) if when & DelayWhen.AFTER_CALL: - logger.debug(f"@delay for {seconds}s AFTER_CALL to {func.__name__}") + logger.debug("@delay for %fs AFTER_CALL to %s", seconds, func.__name__) time.sleep(seconds) return retval @@ -288,7 +295,7 @@ class _SingletonWrapper: def __call__(self, *args, **kwargs): """Returns a single instance of decorated class""" - logger.debug(f"@singleton returning global instance of {self.__wrapped__.__name__}") + logger.debug('@singleton returning global instance of %s', self.__wrapped__.__name__) if self._instance is None: self._instance = self.__wrapped__(*args, **kwargs) return self._instance @@ -355,13 +362,13 @@ def memoized(func: Callable) -> Callable: cache_key = args + tuple(kwargs.items()) if cache_key not in wrapper_memoized.cache: value = func(*args, **kwargs) - logger.debug(f"Memoizing {cache_key} => {value} for {func.__name__}") + logger.debug('Memoizing %s => %s for %s', cache_key, value, func.__name__) wrapper_memoized.cache[cache_key] = value else: - logger.debug(f"Returning memoized value for {func.__name__}") + logger.debug('Returning memoized value for %s', {func.__name__}) return wrapper_memoized.cache[cache_key] - wrapper_memoized.cache = dict() # type: ignore + wrapper_memoized.cache = {} # type: ignore return wrapper_memoized @@ -403,7 +410,7 @@ def retry_predicate( @functools.wraps(f) def f_retry(*args, **kwargs): mtries, mdelay = tries, delay_sec # make mutable - logger.debug(f'deco_retry: will make up to {mtries} attempts...') + logger.debug('deco_retry: will make up to %d attempts...', mtries) retval = f(*args, **kwargs) while mtries > 0: if predicate(retval) is True: @@ -537,7 +544,7 @@ def thunkify(func): def _raise_exception(exception, error_message: Optional[str]): if error_message is None: - raise Exception() + raise Exception(exception) else: raise Exception(error_message) @@ -620,6 +627,7 @@ class _Timeout(object): if flag: return load raise load + return None def timeout( @@ -722,7 +730,8 @@ def call_with_sample_rate(sample_rate: float) -> Callable: if random.uniform(0, 1) < sample_rate: return f(*args, **kwargs) else: - logger.debug(f"@call_with_sample_rate skipping a call to {f.__name__}") + logger.debug("@call_with_sample_rate skipping a call to %s", f.__name__) + return None return _call_with_sample_rate diff --git a/deferred_operand.py b/deferred_operand.py index 75e98d9..70e9d57 100644 --- a/deferred_operand.py +++ b/deferred_operand.py @@ -1,5 +1,9 @@ #!/usr/bin/env python3 +"""This is a helper class that tries to define every __dunder__ method +so as to defer that evaluation of an object as long as possible. It +is used by smart_future.py as a base class.""" + from abc import ABC, abstractmethod from typing import Any, Generic, TypeVar diff --git a/dict_utils.py b/dict_utils.py index 451a87d..ecd23fd 100644 --- a/dict_utils.py +++ b/dict_utils.py @@ -1,5 +1,7 @@ #!/usr/bin/env python3 +"""Helper functions for dealing with dictionaries.""" + from itertools import islice from typing import Any, Callable, Dict, Iterator, List, Tuple @@ -42,10 +44,10 @@ def shard(d: Dict[Any, Any], size: int) -> Iterator[Dict[Any, Any]]: """ items = d.items() for x in range(0, len(d), size): - yield {key: value for (key, value) in islice(items, x, x + size)} + yield dict(islice(items, x, x + size)) -def coalesce_by_creating_list(key, new_value, old_value): +def coalesce_by_creating_list(_, new_value, old_value): from list_utils import flatten return flatten([new_value, old_value]) @@ -55,11 +57,11 @@ def coalesce_by_creating_set(key, new_value, old_value): return set(coalesce_by_creating_list(key, new_value, old_value)) -def coalesce_last_write_wins(key, new_value, old_value): +def coalesce_last_write_wins(_, new_value, discarded_old_value): return new_value -def coalesce_first_write_wins(key, new_value, old_value): +def coalesce_first_write_wins(_, discarded_new_value, old_value): return old_value diff --git a/directory_filter.py b/directory_filter.py index b057f85..6985831 100644 --- a/directory_filter.py +++ b/directory_filter.py @@ -1,5 +1,11 @@ #!/usr/bin/env python3 +"""Two predicates that can help avoid unnecessary disk I/O by +detecting if a particular file is identical to the contents about to +be written or if a particular directory already contains a file that +is identical to the one to be written. See class docs below for +examples.""" + import hashlib import logging import os @@ -58,18 +64,18 @@ class DirectoryFileFilter(object): assert mtime is not None if self.mtime_by_filename.get(filename, 0) != mtime: md5 = file_utils.get_file_md5(filename) - logger.debug(f'Computed/stored {filename}\'s MD5 at ts={mtime} ({md5})') + logger.debug('Computed/stored %s\'s MD5 at ts=%.2f (%s)', filename, mtime, md5) self.mtime_by_filename[filename] = mtime self.md5_by_filename[filename] = md5 def apply(self, item: Any, filename: str) -> bool: self._update_file(filename) file_md5 = self.md5_by_filename.get(filename, 0) - logger.debug(f'{filename}\'s checksum is {file_md5}') + logger.debug('%s\'s checksum is %s', filename, file_md5) mem_hash = hashlib.md5() mem_hash.update(item) md5 = mem_hash.hexdigest() - logger.debug(f'Item\'s checksum is {md5}') + logger.debug('Item\'s checksum is %s', md5) return md5 != file_md5 diff --git a/exceptions.py b/exceptions.py index 82a82a5..aa0aecb 100644 --- a/exceptions.py +++ b/exceptions.py @@ -1,19 +1,28 @@ #!/usr/bin/env python3 +"""Some exceptions used elsewhere.""" + # This module is commonly used by others in here and should avoid # taking any unnecessary dependencies back on them. class PreconditionException(AssertionError): + """Use to indicate function preconditions violated.""" + pass class PostconditionException(AssertionError): + """Use to indicate function postconditions violated.""" + pass class TimeoutError(Exception): + """Use to indicate an operation that timed out.""" + def __init__(self, value: str = "Timed out"): + super().__init__() self.value = value def __str__(self): diff --git a/exec_utils.py b/exec_utils.py index df27335..a440de5 100644 --- a/exec_utils.py +++ b/exec_utils.py @@ -1,5 +1,7 @@ #!/usr/bin/env python3 +"""Helper methods concerned with executing subprocesses.""" + import atexit import logging import os @@ -137,7 +139,7 @@ def cmd_in_background(command: str, *, silent: bool = False) -> subprocess.Popen def kill_subproc() -> None: try: if subproc.poll() is None: - logger.info(f'At exit handler: killing {subproc} ({command})') + logger.info('At exit handler: killing %s (%s)', subproc, command) subproc.terminate() subproc.wait(timeout=10.0) except BaseException as be: diff --git a/executors.py b/executors.py index 6933012..2d80c3b 100644 --- a/executors.py +++ b/executors.py @@ -1,6 +1,14 @@ #!/usr/bin/env python3 # -*- coding: utf-8 -*- +"""Defines three executors: a thread executor for doing work using a +threadpool, a process executor for doing work in other processes on +the same machine and a remote executor for farming out work to other +machines. + +Also defines DefaultExecutors which is a container for references to +global executors / worker pools with automatic shutdown semantics.""" + from __future__ import annotations import concurrent.futures as fut @@ -67,11 +75,13 @@ SCP = '/usr/bin/scp -C' def make_cloud_pickle(fun, *args, **kwargs): - logger.debug(f"Making cloudpickled bundle at {fun.__name__}") + logger.debug("Making cloudpickled bundle at %s", fun.__name__) return cloudpickle.dumps((fun, args, kwargs)) class BaseExecutor(ABC): + """The base executor interface definition.""" + def __init__(self, *, title=''): self.title = title self.histogram = hist.SimpleHistogram( @@ -106,7 +116,7 @@ class BaseExecutor(ABC): """ self.task_count += delta - logger.debug(f'Adjusted task count by {delta} to {self.task_count}') + logger.debug('Adjusted task count by %d to %d.', delta, self.task_count) def get_task_count(self) -> int: """Change the task count. Note: do not call this method from a @@ -118,6 +128,8 @@ class BaseExecutor(ABC): class ThreadExecutor(BaseExecutor): + """A threadpool executor instance.""" + def __init__(self, max_workers: Optional[int] = None): super().__init__() workers = None @@ -125,15 +137,16 @@ class ThreadExecutor(BaseExecutor): workers = max_workers elif 'executors_threadpool_size' in config.config: workers = config.config['executors_threadpool_size'] - logger.debug(f'Creating threadpool executor with {workers} workers') + logger.debug('Creating threadpool executor with %d workers', workers) self._thread_pool_executor = fut.ThreadPoolExecutor( max_workers=workers, thread_name_prefix="thread_executor_helper" ) self.already_shutdown = False # This is run on a different thread; do not adjust task count here. - def run_local_bundle(self, fun, *args, **kwargs): - logger.debug(f"Running local bundle at {fun.__name__}") + @staticmethod + def run_local_bundle(fun, *args, **kwargs): + logger.debug("Running local bundle at %s", fun.__name__) result = fun(*args, **kwargs) return result @@ -147,7 +160,9 @@ class ThreadExecutor(BaseExecutor): for arg in args: newargs.append(arg) start = time.time() - result = self._thread_pool_executor.submit(self.run_local_bundle, *newargs, **kwargs) + result = self._thread_pool_executor.submit( + ThreadExecutor.run_local_bundle, *newargs, **kwargs + ) result.add_done_callback(lambda _: self.histogram.add_item(time.time() - start)) result.add_done_callback(lambda _: self.adjust_task_count(-1)) return result @@ -155,7 +170,7 @@ class ThreadExecutor(BaseExecutor): @overrides def shutdown(self, *, wait: bool = True, quiet: bool = False) -> None: if not self.already_shutdown: - logger.debug(f'Shutting down threadpool executor {self.title}') + logger.debug('Shutting down threadpool executor %s', self.title) self._thread_pool_executor.shutdown(wait) if not quiet: print(self.histogram.__repr__(label_formatter='%ds')) @@ -163,6 +178,8 @@ class ThreadExecutor(BaseExecutor): class ProcessExecutor(BaseExecutor): + """A processpool executor.""" + def __init__(self, max_workers=None): super().__init__() workers = None @@ -170,16 +187,17 @@ class ProcessExecutor(BaseExecutor): workers = max_workers elif 'executors_processpool_size' in config.config: workers = config.config['executors_processpool_size'] - logger.debug(f'Creating processpool executor with {workers} workers.') + logger.debug('Creating processpool executor with %d workers.', workers) self._process_executor = fut.ProcessPoolExecutor( max_workers=workers, ) self.already_shutdown = False # This is run in another process; do not adjust task count here. - def run_cloud_pickle(self, pickle): + @staticmethod + def run_cloud_pickle(pickle): fun, args, kwargs = cloudpickle.loads(pickle) - logger.debug(f"Running pickled bundle at {fun.__name__}") + logger.debug("Running pickled bundle at %s", fun.__name__) result = fun(*args, **kwargs) return result @@ -190,7 +208,7 @@ class ProcessExecutor(BaseExecutor): start = time.time() self.adjust_task_count(+1) pickle = make_cloud_pickle(function, *args, **kwargs) - result = self._process_executor.submit(self.run_cloud_pickle, pickle) + result = self._process_executor.submit(ProcessExecutor.run_cloud_pickle, pickle) result.add_done_callback(lambda _: self.histogram.add_item(time.time() - start)) result.add_done_callback(lambda _: self.adjust_task_count(-1)) return result @@ -198,7 +216,7 @@ class ProcessExecutor(BaseExecutor): @overrides def shutdown(self, *, wait: bool = True, quiet: bool = False) -> None: if not self.already_shutdown: - logger.debug(f'Shutting down processpool executor {self.title}') + logger.debug('Shutting down processpool executor %s', self.title) self._process_executor.shutdown(wait) if not quiet: print(self.histogram.__repr__(label_formatter='%ds')) @@ -218,6 +236,8 @@ class RemoteExecutorException(Exception): @dataclass class RemoteWorkerRecord: + """A record of info about a remote worker.""" + username: str machine: str weight: int @@ -232,6 +252,12 @@ class RemoteWorkerRecord: @dataclass class BundleDetails: + """All info necessary to define some unit of work that needs to be + done, where it is being run, its state, whether it is an original + bundle of a backup bundle, how many times it has failed, etc... + + """ + pickled_code: bytes uuid: str fname: str @@ -282,6 +308,8 @@ class BundleDetails: class RemoteExecutorStatus: + """A status 'scoreboard' for a remote executor.""" + def __init__(self, total_worker_count: int) -> None: self.worker_count: int = total_worker_count self.known_workers: Set[RemoteWorkerRecord] = set() @@ -342,7 +370,7 @@ class RemoteExecutorStatus: start = self.start_per_bundle[uuid] assert start is not None bundle_latency = ts - start - x = self.finished_bundle_timings_per_worker.get(worker, list()) + x = self.finished_bundle_timings_per_worker.get(worker, []) x.append(bundle_latency) self.finished_bundle_timings_per_worker[worker] = x self.finished_bundle_timings.append(bundle_latency) @@ -437,7 +465,12 @@ class RemoteExecutorStatus: class RemoteWorkerSelectionPolicy(ABC): - def register_worker_pool(self, workers): + """A policy for selecting a remote worker base class.""" + + def __init__(self): + self.workers: Optional[List[RemoteWorkerRecord]] = None + + def register_worker_pool(self, workers: List[RemoteWorkerRecord]): self.workers = workers @abstractmethod @@ -450,28 +483,33 @@ class RemoteWorkerSelectionPolicy(ABC): class WeightedRandomRemoteWorkerSelectionPolicy(RemoteWorkerSelectionPolicy): + """A remote worker selector that uses weighted RNG.""" + @overrides def is_worker_available(self) -> bool: - for worker in self.workers: - if worker.count > 0: - return True + if self.workers: + for worker in self.workers: + if worker.count > 0: + return True return False @overrides def acquire_worker(self, machine_to_avoid=None) -> Optional[RemoteWorkerRecord]: grabbag = [] - for worker in self.workers: - if worker.machine != machine_to_avoid: - if worker.count > 0: - for _ in range(worker.count * worker.weight): - grabbag.append(worker) + if self.workers: + for worker in self.workers: + if worker.machine != machine_to_avoid: + if worker.count > 0: + for _ in range(worker.count * worker.weight): + grabbag.append(worker) if len(grabbag) == 0: - logger.debug(f'There are no available workers that avoid {machine_to_avoid}...') - for worker in self.workers: - if worker.count > 0: - for _ in range(worker.count * worker.weight): - grabbag.append(worker) + logger.debug('There are no available workers that avoid %s', machine_to_avoid) + if self.workers: + for worker in self.workers: + if worker.count > 0: + for _ in range(worker.count * worker.weight): + grabbag.append(worker) if len(grabbag) == 0: logger.warning('There are no available workers?!') @@ -480,44 +518,51 @@ class WeightedRandomRemoteWorkerSelectionPolicy(RemoteWorkerSelectionPolicy): worker = random.sample(grabbag, 1)[0] assert worker.count > 0 worker.count -= 1 - logger.debug(f'Chose worker {worker}') + logger.debug('Selected worker %s', worker) return worker class RoundRobinRemoteWorkerSelectionPolicy(RemoteWorkerSelectionPolicy): + """A remote worker selector that just round robins.""" + def __init__(self) -> None: + super().__init__() self.index = 0 @overrides def is_worker_available(self) -> bool: - for worker in self.workers: - if worker.count > 0: - return True + if self.workers: + for worker in self.workers: + if worker.count > 0: + return True return False @overrides def acquire_worker(self, machine_to_avoid: str = None) -> Optional[RemoteWorkerRecord]: - x = self.index - while True: - worker = self.workers[x] - if worker.count > 0: - worker.count -= 1 + if self.workers: + x = self.index + while True: + worker = self.workers[x] + if worker.count > 0: + worker.count -= 1 + x += 1 + if x >= len(self.workers): + x = 0 + self.index = x + logger.debug('Selected worker %s', worker) + return worker x += 1 if x >= len(self.workers): x = 0 - self.index = x - logger.debug(f'Selected worker {worker}') - return worker - x += 1 - if x >= len(self.workers): - x = 0 - if x == self.index: - msg = 'Unexpectedly could not find a worker, retrying...' - logger.warning(msg) - return None + if x == self.index: + logger.warning('Unexpectedly could not find a worker, retrying...') + return None + return None class RemoteExecutor(BaseExecutor): + """A remote work executor.""" + def __init__( self, workers: List[RemoteWorkerRecord], @@ -535,7 +580,7 @@ class RemoteExecutor(BaseExecutor): raise RemoteExecutorException(msg) self.policy.register_worker_pool(self.workers) self.cv = threading.Condition() - logger.debug(f'Creating {self.worker_count} local threads, one per remote worker.') + logger.debug('Creating %d local threads, one per remote worker.', self.worker_count) self._helper_executor = fut.ThreadPoolExecutor( thread_name_prefix="remote_executor_helper", max_workers=self.worker_count, @@ -617,15 +662,15 @@ class RemoteExecutor(BaseExecutor): if start_ts is not None: runtime = now - start_ts score += runtime - logger.debug(f'score[{bundle}] => {score} # latency boost') + logger.debug('score[%s] => %.1f # latency boost', bundle, score) if bundle.slower_than_local_p95: score += runtime / 2 - logger.debug(f'score[{bundle}] => {score} # >worker p95') + logger.debug('score[%s] => %.1f # >worker p95', bundle, score) if bundle.slower_than_global_p95: score += runtime / 4 - logger.debug(f'score[{bundle}] => {score} # >global p95') + logger.debug('score[%s] => %.1f # >global p95', bundle, score) # Prefer backups of bundles that don't # have backups already. @@ -639,7 +684,9 @@ class RemoteExecutor(BaseExecutor): else: score = 0 logger.debug( - f'score[{bundle}] => {score} # {backup_count} dup backup factor' + 'score[%s] => %.1f # {backup_count} dup backup factor', + bundle, + score, ) if score != 0 and (best_score is None or score > best_score): @@ -658,7 +705,9 @@ class RemoteExecutor(BaseExecutor): if bundle_to_backup is not None: self.last_backup = now logger.info( - f'=====> SCHEDULING BACKUP {bundle_to_backup} (score={best_score:.1f}) <=====' + '=====> SCHEDULING BACKUP %s (score=%.1f}) <=====', + bundle_to_backup, + best_score, ) self.schedule_backup_for_bundle(bundle_to_backup) finally: @@ -684,7 +733,7 @@ class RemoteExecutor(BaseExecutor): def release_worker(self, bundle: BundleDetails, *, was_cancelled=True) -> None: worker = bundle.worker assert worker is not None - logger.debug(f'Released worker {worker}') + logger.debug('Released worker %s', worker) self.status.record_release_worker( worker, bundle.uuid, @@ -698,7 +747,7 @@ class RemoteExecutor(BaseExecutor): def check_if_cancelled(self, bundle: BundleDetails) -> bool: with self.status.lock: if bundle.is_cancelled.wait(timeout=0.0): - logger.debug(f'Bundle {bundle.uuid} is cancelled, bail out.') + logger.debug('Bundle %s is cancelled, bail out.', bundle.uuid) bundle.was_cancelled = True return True return False @@ -724,7 +773,7 @@ class RemoteExecutor(BaseExecutor): machine = bundle.machine = worker.machine username = bundle.username = worker.username self.status.record_acquire_worker(worker, uuid) - logger.debug(f'{bundle}: Running bundle on {worker}...') + logger.debug('%s: Running bundle on %s...', bundle, worker) # Before we do any work, make sure the bundle is still viable. # It may have been some time between when it was submitted and @@ -734,7 +783,7 @@ class RemoteExecutor(BaseExecutor): try: return self.process_work_result(bundle) except Exception as e: - logger.warning(f'{bundle}: bundle says it\'s cancelled upfront but no results?!') + logger.warning('%s: bundle says it\'s cancelled upfront but no results?!', bundle) self.release_worker(bundle) if is_original: # Weird. We are the original owner of this @@ -746,8 +795,9 @@ class RemoteExecutor(BaseExecutor): # thing. logger.exception(e) logger.error( - f'{bundle}: We are the original owner thread and yet there are ' - + 'no results for this bundle. This is unexpected and bad.' + '%s: We are the original owner thread and yet there are ' + 'no results for this bundle. This is unexpected and bad.', + bundle, ) return self.emergency_retry_nasty_bundle(bundle) else: @@ -765,10 +815,10 @@ class RemoteExecutor(BaseExecutor): try: cmd = f'{SCP} {bundle.code_file} {username}@{machine}:{bundle.code_file}' start_ts = time.time() - logger.info(f"{bundle}: Copying work to {worker} via {cmd}.") + logger.info("%s: Copying work to %s via %s.", bundle, worker, cmd) run_silently(cmd) xfer_latency = time.time() - start_ts - logger.debug(f"{bundle}: Copying to {worker} took {xfer_latency:.1f}s.") + logger.debug("%s: Copying to %s took %.1fs.", bundle, worker, xfer_latency) except Exception as e: self.release_worker(bundle) if is_original: @@ -776,9 +826,10 @@ class RemoteExecutor(BaseExecutor): # And we're the original bundle. We have to retry. logger.exception(e) logger.error( - f"{bundle}: Failed to send instructions to the worker machine?! " - + "This is not expected; we\'re the original bundle so this shouldn\'t " - + "be a race condition. Attempting an emergency retry..." + "%s: Failed to send instructions to the worker machine?! " + "This is not expected; we\'re the original bundle so this shouldn\'t " + "be a race condition. Attempting an emergency retry...", + bundle, ) return self.emergency_retry_nasty_bundle(bundle) else: @@ -786,10 +837,12 @@ class RemoteExecutor(BaseExecutor): # There's a race condition where someone else # already finished the work and removed the source # code file before we could copy it. No biggie. - msg = f'{bundle}: Failed to send instructions to the worker machine... ' - msg += 'We\'re a backup and this may be caused by the original (or some ' - msg += 'other backup) already finishing this work. Ignoring this.' - logger.warning(msg) + logger.warning( + '%s: Failed to send instructions to the worker machine... ' + 'We\'re a backup and this may be caused by the original (or ' + 'some other backup) already finishing this work. Ignoring.', + bundle, + ) return None # Kick off the work. Note that if this fails we let @@ -801,10 +854,10 @@ class RemoteExecutor(BaseExecutor): f' /home/scott/lib/python_modules/remote_worker.py' f' --code_file {bundle.code_file} --result_file {bundle.result_file}"' ) - logger.debug(f'{bundle}: Executing {cmd} in the background to kick off work...') + logger.debug('%s: Executing %s in the background to kick off work...', bundle, cmd) p = cmd_in_background(cmd, silent=True) bundle.pid = p.pid - logger.debug(f'{bundle}: Local ssh process pid={p.pid}; remote worker is {machine}.') + logger.debug('%s: Local ssh process pid=%d; remote worker is %s.', bundle, p.pid, machine) return self.wait_for_process(p, bundle, 0) def wait_for_process( @@ -815,7 +868,7 @@ class RemoteExecutor(BaseExecutor): pid = p.pid if depth > 3: logger.error( - f"I've gotten repeated errors waiting on this bundle; giving up on pid={pid}." + "I've gotten repeated errors waiting on this bundle; giving up on pid=%d", pid ) p.terminate() self.release_worker(bundle) @@ -829,10 +882,10 @@ class RemoteExecutor(BaseExecutor): p.wait(timeout=0.25) except subprocess.TimeoutExpired: if self.check_if_cancelled(bundle): - logger.info(f'{bundle}: looks like another worker finished bundle...') + logger.info('%s: looks like another worker finished bundle...', bundle) break else: - logger.info(f"{bundle}: pid {pid} ({machine}) is finished!") + logger.info("%s: pid %d (%s) is finished!", bundle, pid, machine) p = None break @@ -853,10 +906,11 @@ class RemoteExecutor(BaseExecutor): # Otherwise, time for an emergency reschedule. except Exception as e: logger.exception(e) - logger.error(f'{bundle}: Something unexpected just happened...') + logger.error('%s: Something unexpected just happened...', bundle) if p is not None: - msg = f"{bundle}: Failed to wrap up \"done\" bundle, re-waiting on active ssh." - logger.warning(msg) + logger.warning( + "%s: Failed to wrap up \"done\" bundle, re-waiting on active ssh.", bundle + ) return self.wait_for_process(p, bundle, depth + 1) else: self.release_worker(bundle) @@ -880,7 +934,11 @@ class RemoteExecutor(BaseExecutor): if bundle.hostname not in bundle.machine: cmd = f'{SCP} {username}@{machine}:{result_file} {result_file} 2>/dev/null' logger.info( - f"{bundle}: Fetching results back from {username}@{machine} via {cmd}" + "%s: Fetching results back from %s@%s via %s", + bundle, + username, + machine, + cmd, ) # If either of these throw they are handled in @@ -892,14 +950,14 @@ class RemoteExecutor(BaseExecutor): except Exception as e: attempts += 1 if attempts >= 3: - raise (e) + raise e else: break run_silently( f'{SSH} {username}@{machine}' f' "/bin/rm -f {code_file} {result_file}"' ) - logger.debug(f'Fetching results back took {time.time() - bundle.end_ts:.1f}s.') + logger.debug('Fetching results back took %.2fs', time.time() - bundle.end_ts) dur = bundle.end_ts - bundle.start_ts self.histogram.add_item(dur) @@ -910,23 +968,22 @@ class RemoteExecutor(BaseExecutor): # if one of the backups finished first; it still must read the # result from disk. if is_original: - logger.debug(f"{bundle}: Unpickling {result_file}.") + logger.debug("%s: Unpickling %s.", bundle, result_file) try: with open(result_file, 'rb') as rb: serialized = rb.read() result = cloudpickle.loads(serialized) except Exception as e: logger.exception(e) - msg = f'Failed to load {result_file}... this is bad news.' - logger.critical(msg) + logger.error('Failed to load %s... this is bad news.', result_file) self.release_worker(bundle) # Re-raise the exception; the code in wait_for_process may # decide to emergency_retry_nasty_bundle here. - raise Exception(e) - logger.debug(f'Removing local (master) {code_file} and {result_file}.') - os.remove(f'{result_file}') - os.remove(f'{code_file}') + raise e + logger.debug('Removing local (master) %s and %s.', code_file, result_file) + os.remove(result_file) + os.remove(code_file) # Notify any backups that the original is done so they # should stop ASAP. Do this whether or not we @@ -934,7 +991,9 @@ class RemoteExecutor(BaseExecutor): # backup. if bundle.backup_bundles is not None: for backup in bundle.backup_bundles: - logger.debug(f'{bundle}: Notifying backup {backup.uuid} that it\'s cancelled') + logger.debug( + '%s: Notifying backup %s that it\'s cancelled', bundle, backup.uuid + ) backup.is_cancelled.set() # This is a backup job and, by now, we have already fetched @@ -949,7 +1008,9 @@ class RemoteExecutor(BaseExecutor): if not was_cancelled: orig_bundle = bundle.src_bundle assert orig_bundle is not None - logger.debug(f'{bundle}: Notifying original {orig_bundle.uuid} we beat them to it.') + logger.debug( + '%s: Notifying original %s we beat them to it.', bundle, orig_bundle.uuid + ) orig_bundle.is_cancelled.set() self.release_worker(bundle, was_cancelled=was_cancelled) return result @@ -961,8 +1022,8 @@ class RemoteExecutor(BaseExecutor): code_file = f'/tmp/{uuid}.code.bin' result_file = f'/tmp/{uuid}.result.bin' - logger.debug(f'Writing pickled code to {code_file}') - with open(f'{code_file}', 'wb') as wb: + logger.debug('Writing pickled code to %s', code_file) + with open(code_file, 'wb') as wb: wb.write(pickle) bundle = BundleDetails( @@ -987,7 +1048,7 @@ class RemoteExecutor(BaseExecutor): failure_count=0, ) self.status.record_bundle_details(bundle) - logger.debug(f'{bundle}: Created an original bundle') + logger.debug('%s: Created an original bundle', bundle) return bundle def create_backup_bundle(self, src_bundle: BundleDetails): @@ -1018,7 +1079,7 @@ class RemoteExecutor(BaseExecutor): ) src_bundle.backup_bundles.append(backup_bundle) self.status.record_bundle_details_already_locked(backup_bundle) - logger.debug(f'{backup_bundle}: Created a backup bundle') + logger.debug('%s: Created a backup bundle', backup_bundle) return backup_bundle def schedule_backup_for_bundle(self, src_bundle: BundleDetails): @@ -1026,7 +1087,7 @@ class RemoteExecutor(BaseExecutor): assert src_bundle is not None backup_bundle = self.create_backup_bundle(src_bundle) logger.debug( - f'{backup_bundle.uuid}/{backup_bundle.fname}: Scheduling backup for execution...' + '%s/%s: Scheduling backup for execution...', backup_bundle.uuid, backup_bundle.fname ) self._helper_executor.submit(self.launch, backup_bundle) @@ -1048,15 +1109,17 @@ class RemoteExecutor(BaseExecutor): if bundle.failure_count > retry_limit: logger.error( - f'{bundle}: Tried this bundle too many times already ({retry_limit}x); giving up.' + '%s: Tried this bundle too many times already (%dx); giving up.', + bundle, + retry_limit, ) if is_original: raise RemoteExecutorException( - f'{bundle}: This bundle can\'t be completed despite several backups and retries' + f'{bundle}: This bundle can\'t be completed despite several backups and retries', ) else: logger.error( - f'{bundle}: At least it\'s only a backup; better luck with the others.' + '%s: At least it\'s only a backup; better luck with the others.', bundle ) return None else: @@ -1077,7 +1140,7 @@ class RemoteExecutor(BaseExecutor): @overrides def shutdown(self, *, wait: bool = True, quiet: bool = False) -> None: if not self.already_shutdown: - logging.debug(f'Shutting down RemoteExecutor {self.title}') + logging.debug('Shutting down RemoteExecutor %s', self.title) self.heartbeat_stop_event.set() self.heartbeat_thread.join() self._helper_executor.shutdown(wait) @@ -1088,13 +1151,20 @@ class RemoteExecutor(BaseExecutor): @singleton class DefaultExecutors(object): + """A container for a default thread, process and remote executor. + These are not created until needed and we take care to clean up + before process exit. + + """ + def __init__(self): self.thread_executor: Optional[ThreadExecutor] = None self.process_executor: Optional[ProcessExecutor] = None self.remote_executor: Optional[RemoteExecutor] = None - def ping(self, host) -> bool: - logger.debug(f'RUN> ping -c 1 {host}') + @staticmethod + def ping(host) -> bool: + logger.debug('RUN> ping -c 1 %s', host) try: x = cmd_with_timeout(f'ping -c 1 {host} >/dev/null 2>/dev/null', timeout_seconds=1.0) return x == 0 @@ -1169,7 +1239,7 @@ class DefaultExecutors(object): # The controller machine has a lot to do; go easy on it. for record in pool: if record.machine == platform.node() and record.count > 1: - logger.info(f'Reducing workload for {record.machine}.') + logger.info('Reducing workload for %s.', record.machine) record.count = 1 policy = WeightedRandomRemoteWorkerSelectionPolicy() diff --git a/file_utils.py b/file_utils.py index 6bcfc75..d1e2eff 100644 --- a/file_utils.py +++ b/file_utils.py @@ -6,7 +6,6 @@ import datetime import errno import glob import hashlib -import io import logging import os import pathlib @@ -190,7 +189,7 @@ def create_path_if_not_exist(path, on_error=None): >>> os.path.exists(path) True """ - logger.debug(f"Creating path {path}") + logger.debug("Creating path %s", path) previous_umask = os.umask(0) try: os.makedirs(path) @@ -462,6 +461,11 @@ def get_files_recursive(directory: str): class FileWriter(object): + """A helper that writes a file to a temporary location and then moves + it atomically to its ultimate destination on close. + + """ + def __init__(self, filename: str) -> None: self.filename = filename uuid = uuid4() diff --git a/tests/parallelize_itest.py b/tests/parallelize_itest.py index d09e9f3..409b8dc 100755 --- a/tests/parallelize_itest.py +++ b/tests/parallelize_itest.py @@ -1,5 +1,6 @@ #!/usr/bin/env python3 +import logging import sys import bootstrap @@ -8,6 +9,8 @@ import executors import parallelize as p import smart_future +logger = logging.getLogger(__name__) + @p.parallelize(method=p.Method.THREAD) def compute_factorial_thread(n): @@ -77,4 +80,8 @@ def main() -> None: if __name__ == '__main__': - main() + try: + main() + except Exception as e: + logger.exception(e) + sys.exit(1) |