X-Git-Url: https://wannabe.guru.org/gitweb/?a=blobdiff_plain;f=executors.py;h=34528a33c2d10236cd7527fe53ffd027fa8020ca;hb=31c81f6539969a5eba864d3305f9fb7bf716a367;hp=6ccd7b675c760315d05158d68dad0768cc0f0871;hpb=55a3172e37855f388b9ba0dfc91641a6c9ad1376;p=python_utils.git diff --git a/executors.py b/executors.py index 6ccd7b6..34528a3 100644 --- a/executors.py +++ b/executors.py @@ -2,43 +2,43 @@ from __future__ import annotations -from abc import ABC, abstractmethod import concurrent.futures as fut -from collections import defaultdict -from dataclasses import dataclass import logging -import numpy import os import platform import random import subprocess import threading import time -from typing import Any, Callable, Dict, List, Optional, Set import warnings +from abc import ABC, abstractmethod +from collections import defaultdict +from dataclasses import dataclass +from typing import Any, Callable, Dict, List, Optional, Set import cloudpickle # type: ignore +import numpy from overrides import overrides -from ansi import bg, fg, underline, reset import argparse_utils import config -from decorator_utils import singleton -from exec_utils import run_silently, cmd_in_background, cmd_with_timeout import histogram as hist +from ansi import bg, fg, reset, underline +from decorator_utils import singleton +from exec_utils import cmd_in_background, cmd_with_timeout, run_silently +from thread_utils import background_thread logger = logging.getLogger(__name__) parser = config.add_commandline_args( - f"Executors ({__file__})", - "Args related to processing executors." + f"Executors ({__file__})", "Args related to processing executors." ) parser.add_argument( '--executors_threadpool_size', type=int, metavar='#THREADS', help='Number of threads in the default threadpool, leave unset for default', - default=None + default=None, ) parser.add_argument( '--executors_processpool_size', @@ -61,8 +61,8 @@ parser.add_argument( help='Maximum number of failures before giving up on a bundle', ) -RSYNC = 'rsync -q --no-motd -W --ignore-existing --timeout=60 --size-only -z' -SSH = 'ssh -oForwardX11=no' +SSH = '/usr/bin/ssh -oForwardX11=no' +SCP = '/usr/bin/scp -C' def make_cloud_pickle(fun, *args, **kwargs): @@ -73,33 +73,51 @@ def make_cloud_pickle(fun, *args, **kwargs): class BaseExecutor(ABC): def __init__(self, *, title=''): self.title = title - self.task_count = 0 self.histogram = hist.SimpleHistogram( - hist.SimpleHistogram.n_evenly_spaced_buckets( - int(0), int(500), 50 - ) + hist.SimpleHistogram.n_evenly_spaced_buckets(int(0), int(500), 50) ) + self.task_count = 0 @abstractmethod - def submit(self, - function: Callable, - *args, - **kwargs) -> fut.Future: + def submit(self, function: Callable, *args, **kwargs) -> fut.Future: pass @abstractmethod - def shutdown(self, - wait: bool = True) -> None: + def shutdown(self, *, wait: bool = True, quiet: bool = False) -> None: pass + def shutdown_if_idle(self, *, quiet: bool = False) -> bool: + """Shutdown the executor and return True if the executor is idle + (i.e. there are no pending or active tasks). Return False + otherwise. Note: this should only be called by the launcher + process. + + """ + if self.task_count == 0: + self.shutdown(wait=True, quiet=quiet) + return True + return False + def adjust_task_count(self, delta: int) -> None: + """Change the task count. Note: do not call this method from a + worker, it should only be called by the launcher process / + thread / machine. + + """ self.task_count += delta - logger.debug(f'Executor current task count is {self.task_count}') + logger.debug(f'Adjusted task count by {delta} to {self.task_count}') + + def get_task_count(self) -> int: + """Change the task count. Note: do not call this method from a + worker, it should only be called by the launcher process / + thread / machine. + + """ + return self.task_count class ThreadExecutor(BaseExecutor): - def __init__(self, - max_workers: Optional[int] = None): + def __init__(self, max_workers: Optional[int] = None): super().__init__() workers = None if max_workers is not None: @@ -108,47 +126,45 @@ class ThreadExecutor(BaseExecutor): workers = config.config['executors_threadpool_size'] logger.debug(f'Creating threadpool executor with {workers} workers') self._thread_pool_executor = fut.ThreadPoolExecutor( - max_workers=workers, - thread_name_prefix="thread_executor_helper" + 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__}") - start = time.time() result = fun(*args, **kwargs) - end = time.time() - self.adjust_task_count(-1) - duration = end - start - logger.debug(f"{fun.__name__} finished; used {duration:.1f}s") - self.histogram.add_item(duration) return result @overrides - def submit(self, - function: Callable, - *args, - **kwargs) -> fut.Future: + def submit(self, function: Callable, *args, **kwargs) -> fut.Future: + if self.already_shutdown: + raise Exception('Submitted work after shutdown.') self.adjust_task_count(+1) newargs = [] newargs.append(function) for arg in args: newargs.append(arg) - return self._thread_pool_executor.submit( - self.run_local_bundle, - *newargs, - **kwargs) + start = time.time() + result = self._thread_pool_executor.submit( + self.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 @overrides - def shutdown(self, - wait = True) -> None: - logger.debug(f'Shutting down threadpool executor {self.title}') - print(self.histogram) - self._thread_pool_executor.shutdown(wait) + def shutdown(self, *, wait: bool = True, quiet: bool = False) -> None: + if not self.already_shutdown: + logger.debug(f'Shutting down threadpool executor {self.title}') + self._thread_pool_executor.shutdown(wait) + if not quiet: + print(self.histogram.__repr__(label_formatter='%ds')) + self.already_shutdown = True class ProcessExecutor(BaseExecutor): - def __init__(self, - max_workers=None): + def __init__(self, max_workers=None): super().__init__() workers = None if max_workers is not None: @@ -159,38 +175,35 @@ class ProcessExecutor(BaseExecutor): 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): fun, args, kwargs = cloudpickle.loads(pickle) logger.debug(f"Running pickled bundle at {fun.__name__}") result = fun(*args, **kwargs) - self.adjust_task_count(-1) return result @overrides - def submit(self, - function: Callable, - *args, - **kwargs) -> fut.Future: + def submit(self, function: Callable, *args, **kwargs) -> fut.Future: + if self.already_shutdown: + raise Exception('Submitted work after shutdown.') 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.add_done_callback( - lambda _: self.histogram.add_item( - time.time() - start - ) - ) + result = self._process_executor.submit(self.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 @overrides - def shutdown(self, wait=True) -> None: - logger.debug(f'Shutting down processpool executor {self.title}') - self._process_executor.shutdown(wait) - print(self.histogram) + def shutdown(self, *, wait: bool = True, quiet: bool = False) -> None: + if not self.already_shutdown: + logger.debug(f'Shutting down processpool executor {self.title}') + self._process_executor.shutdown(wait) + if not quiet: + print(self.histogram.__repr__(label_formatter='%ds')) + self.already_shutdown = True def __getstate__(self): state = self.__dict__.copy() @@ -200,6 +213,7 @@ class ProcessExecutor(BaseExecutor): class RemoteExecutorException(Exception): """Thrown when a bundle cannot be executed despite several retries.""" + pass @@ -233,7 +247,7 @@ class BundleDetails: end_ts: float slower_than_local_p95: bool slower_than_global_p95: bool - src_bundle: BundleDetails + src_bundle: Optional[BundleDetails] is_cancelled: threading.Event was_cancelled: bool backup_bundles: Optional[List[BundleDetails]] @@ -270,42 +284,30 @@ class BundleDetails: class RemoteExecutorStatus: def __init__(self, total_worker_count: int) -> None: - self.worker_count = total_worker_count + self.worker_count: int = total_worker_count self.known_workers: Set[RemoteWorkerRecord] = set() - self.start_per_bundle: Dict[str, float] = defaultdict(float) + self.start_time: float = time.time() + self.start_per_bundle: Dict[str, Optional[float]] = defaultdict(float) self.end_per_bundle: Dict[str, float] = defaultdict(float) self.finished_bundle_timings_per_worker: Dict[ - RemoteWorkerRecord, - List[float] - ] = {} - self.in_flight_bundles_by_worker: Dict[ - RemoteWorkerRecord, - Set[str] + RemoteWorkerRecord, List[float] ] = {} + self.in_flight_bundles_by_worker: Dict[RemoteWorkerRecord, Set[str]] = {} self.bundle_details_by_uuid: Dict[str, BundleDetails] = {} self.finished_bundle_timings: List[float] = [] self.last_periodic_dump: Optional[float] = None - self.total_bundles_submitted = 0 + self.total_bundles_submitted: int = 0 # Protects reads and modification using self. Also used # as a memory fence for modifications to bundle. - self.lock = threading.Lock() + self.lock: threading.Lock = threading.Lock() - def record_acquire_worker( - self, - worker: RemoteWorkerRecord, - uuid: str - ) -> None: + def record_acquire_worker(self, worker: RemoteWorkerRecord, uuid: str) -> None: with self.lock: - self.record_acquire_worker_already_locked( - worker, - uuid - ) + self.record_acquire_worker_already_locked(worker, uuid) def record_acquire_worker_already_locked( - self, - worker: RemoteWorkerRecord, - uuid: str + self, worker: RemoteWorkerRecord, uuid: str ) -> None: assert self.lock.locked() self.known_workers.add(worker) @@ -314,41 +316,37 @@ class RemoteExecutorStatus: x.add(uuid) self.in_flight_bundles_by_worker[worker] = x - def record_bundle_details( - self, - details: BundleDetails) -> None: + def record_bundle_details(self, details: BundleDetails) -> None: with self.lock: self.record_bundle_details_already_locked(details) - def record_bundle_details_already_locked( - self, - details: BundleDetails) -> None: + def record_bundle_details_already_locked(self, details: BundleDetails) -> None: assert self.lock.locked() self.bundle_details_by_uuid[details.uuid] = details def record_release_worker( - self, - worker: RemoteWorkerRecord, - uuid: str, - was_cancelled: bool, + self, + worker: RemoteWorkerRecord, + uuid: str, + was_cancelled: bool, ) -> None: with self.lock: - self.record_release_worker_already_locked( - worker, uuid, was_cancelled - ) + self.record_release_worker_already_locked(worker, uuid, was_cancelled) def record_release_worker_already_locked( - self, - worker: RemoteWorkerRecord, - uuid: str, - was_cancelled: bool, + self, + worker: RemoteWorkerRecord, + uuid: str, + was_cancelled: bool, ) -> None: assert self.lock.locked() ts = time.time() self.end_per_bundle[uuid] = ts self.in_flight_bundles_by_worker[worker].remove(uuid) if not was_cancelled: - bundle_latency = ts - self.start_per_bundle[uuid] + start = self.start_per_bundle[uuid] + assert start + bundle_latency = ts - start x = self.finished_bundle_timings_per_worker.get(worker, list()) x.append(bundle_latency) self.finished_bundle_timings_per_worker[worker] = x @@ -379,13 +377,14 @@ class RemoteExecutorStatus: if len(self.finished_bundle_timings) > 1: qall = numpy.quantile(self.finished_bundle_timings, [0.5, 0.95]) ret += ( - f'⏱=∀p50:{qall[0]:.1f}s, ∀p95:{qall[1]:.1f}s, ' + f'⏱=∀p50:{qall[0]:.1f}s, ∀p95:{qall[1]:.1f}s, total={ts-self.start_time:.1f}s, ' f'✅={total_finished}/{self.total_bundles_submitted}, ' f'💻n={total_in_flight}/{self.worker_count}\n' ) else: ret += ( - f' ✅={total_finished}/{self.total_bundles_submitted}, ' + f'⏱={ts-self.start_time:.1f}s, ' + f'✅={total_finished}/{self.total_bundles_submitted}, ' f'💻n={total_in_flight}/{self.worker_count}\n' ) @@ -405,10 +404,7 @@ class RemoteExecutorStatus: if in_flight > 0: ret += f' ...{in_flight} bundles currently in flight:\n' for bundle_uuid in self.in_flight_bundles_by_worker[worker]: - details = self.bundle_details_by_uuid.get( - bundle_uuid, - None - ) + details = self.bundle_details_by_uuid.get(bundle_uuid, None) pid = str(details.pid) if (details and details.pid != 0) else "TBD" if self.start_per_bundle[bundle_uuid] is not None: sec = ts - self.start_per_bundle[bundle_uuid] @@ -440,10 +436,7 @@ class RemoteExecutorStatus: assert self.lock.locked() self.total_bundles_submitted = total_bundles_submitted ts = time.time() - if ( - self.last_periodic_dump is None - or ts - self.last_periodic_dump > 5.0 - ): + if self.last_periodic_dump is None or ts - self.last_periodic_dump > 5.0: print(self) self.last_periodic_dump = ts @@ -457,10 +450,7 @@ class RemoteWorkerSelectionPolicy(ABC): pass @abstractmethod - def acquire_worker( - self, - machine_to_avoid = None - ) -> Optional[RemoteWorkerRecord]: + def acquire_worker(self, machine_to_avoid=None) -> Optional[RemoteWorkerRecord]: pass @@ -473,27 +463,32 @@ class WeightedRandomRemoteWorkerSelectionPolicy(RemoteWorkerSelectionPolicy): return False @overrides - def acquire_worker( - self, - machine_to_avoid = None - ) -> Optional[RemoteWorkerRecord]: + def acquire_worker(self, machine_to_avoid=None) -> Optional[RemoteWorkerRecord]: grabbag = [] for worker in self.workers: - for x in range(0, worker.count): - for y in range(0, worker.weight): - grabbag.append(worker) - - for _ in range(0, 5): - random.shuffle(grabbag) - worker = grabbag[0] - if worker.machine != machine_to_avoid or _ > 2: + if worker.machine != machine_to_avoid: if worker.count > 0: - worker.count -= 1 - logger.debug(f'Selected worker {worker}') - return worker - msg = 'Unexpectedly could not find a worker, retrying...' - logger.warning(msg) - return None + 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) + + if len(grabbag) == 0: + logger.warning('There are no available workers?!') + return None + + worker = random.sample(grabbag, 1)[0] + assert worker.count > 0 + worker.count -= 1 + logger.debug(f'Chose worker {worker}') + return worker class RoundRobinRemoteWorkerSelectionPolicy(RemoteWorkerSelectionPolicy): @@ -509,8 +504,7 @@ class RoundRobinRemoteWorkerSelectionPolicy(RemoteWorkerSelectionPolicy): @overrides def acquire_worker( - self, - machine_to_avoid: str = None + self, machine_to_avoid: str = None ) -> Optional[RemoteWorkerRecord]: x = self.index while True: @@ -533,9 +527,11 @@ class RoundRobinRemoteWorkerSelectionPolicy(RemoteWorkerSelectionPolicy): class RemoteExecutor(BaseExecutor): - def __init__(self, - workers: List[RemoteWorkerRecord], - policy: RemoteWorkerSelectionPolicy) -> None: + def __init__( + self, + workers: List[RemoteWorkerRecord], + policy: RemoteWorkerSelectionPolicy, + ) -> None: super().__init__() self.workers = workers self.policy = policy @@ -548,7 +544,9 @@ 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( + f'Creating {self.worker_count} local threads, one per remote worker.' + ) self._helper_executor = fut.ThreadPoolExecutor( thread_name_prefix="remote_executor_helper", max_workers=self.worker_count, @@ -557,19 +555,144 @@ class RemoteExecutor(BaseExecutor): self.total_bundles_submitted = 0 self.backup_lock = threading.Lock() self.last_backup = None + ( + self.heartbeat_thread, + self.heartbeat_stop_event, + ) = self.run_periodic_heartbeat() + self.already_shutdown = False + + @background_thread + def run_periodic_heartbeat(self, stop_event: threading.Event) -> None: + while not stop_event.is_set(): + time.sleep(5.0) + logger.debug('Running periodic heartbeat code...') + self.heartbeat() + logger.debug('Periodic heartbeat thread shutting down.') + + def heartbeat(self) -> None: + # Note: this is invoked on a background thread, not an + # executor thread. Be careful what you do with it b/c it + # needs to get back and dump status again periodically. + with self.status.lock: + self.status.periodic_dump(self.total_bundles_submitted) + + # Look for bundles to reschedule via executor.submit + if config.config['executors_schedule_remote_backups']: + self.maybe_schedule_backup_bundles() + + def maybe_schedule_backup_bundles(self): + assert self.status.lock.locked() + num_done = len(self.status.finished_bundle_timings) + num_idle_workers = self.worker_count - self.task_count + now = time.time() + if ( + num_done > 2 + and num_idle_workers > 1 + and (self.last_backup is None or (now - self.last_backup > 9.0)) + and self.backup_lock.acquire(blocking=False) + ): + try: + assert self.backup_lock.locked() + + bundle_to_backup = None + best_score = None + for ( + worker, + bundle_uuids, + ) in self.status.in_flight_bundles_by_worker.items(): + + # Prefer to schedule backups of bundles running on + # slower machines. + base_score = 0 + for record in self.workers: + if worker.machine == record.machine: + base_score = float(record.weight) + base_score = 1.0 / base_score + base_score *= 200.0 + base_score = int(base_score) + break + + for uuid in bundle_uuids: + bundle = self.status.bundle_details_by_uuid.get(uuid, None) + if ( + bundle is not None + and bundle.src_bundle is None + and bundle.backup_bundles is not None + ): + score = base_score + + # Schedule backups of bundles running + # longer; especially those that are + # unexpectedly slow. + start_ts = self.status.start_per_bundle[uuid] + if start_ts is not None: + runtime = now - start_ts + score += runtime + logger.debug( + f'score[{bundle}] => {score} # latency boost' + ) + + if bundle.slower_than_local_p95: + score += runtime / 2 + logger.debug( + f'score[{bundle}] => {score} # >worker p95' + ) + + if bundle.slower_than_global_p95: + score += runtime / 4 + logger.debug( + f'score[{bundle}] => {score} # >global p95' + ) + + # Prefer backups of bundles that don't + # have backups already. + backup_count = len(bundle.backup_bundles) + if backup_count == 0: + score *= 2 + elif backup_count == 1: + score /= 2 + elif backup_count == 2: + score /= 8 + else: + score = 0 + logger.debug( + f'score[{bundle}] => {score} # {backup_count} dup backup factor' + ) + + if score != 0 and ( + best_score is None or score > best_score + ): + bundle_to_backup = bundle + assert bundle is not None + assert bundle.backup_bundles is not None + assert bundle.src_bundle is None + best_score = score + + # Note: this is all still happening on the heartbeat + # runner thread. That's ok because + # schedule_backup_for_bundle uses the executor to + # submit the bundle again which will cause it to be + # picked up by a worker thread and allow this thread + # to return to run future heartbeats. + if bundle_to_backup is not None: + self.last_backup = now + logger.info( + f'=====> SCHEDULING BACKUP {bundle_to_backup} (score={best_score:.1f}) <=====' + ) + self.schedule_backup_for_bundle(bundle_to_backup) + finally: + self.backup_lock.release() def is_worker_available(self) -> bool: return self.policy.is_worker_available() def acquire_worker( - self, - machine_to_avoid: str = None + self, machine_to_avoid: str = None ) -> Optional[RemoteWorkerRecord]: return self.policy.acquire_worker(machine_to_avoid) def find_available_worker_or_block( - self, - machine_to_avoid: str = None + self, machine_to_avoid: str = None ) -> RemoteWorkerRecord: with self.cv: while not self.is_worker_available(): @@ -581,97 +704,19 @@ class RemoteExecutor(BaseExecutor): logger.critical(msg) raise Exception(msg) - def release_worker(self, worker: RemoteWorkerRecord) -> None: + def release_worker(self, bundle: BundleDetails, *, was_cancelled=True) -> None: + worker = bundle.worker + assert worker is not None logger.debug(f'Released worker {worker}') + self.status.record_release_worker( + worker, + bundle.uuid, + was_cancelled, + ) with self.cv: worker.count += 1 self.cv.notify() - - def heartbeat(self) -> None: - with self.status.lock: - # Regular progress report - self.status.periodic_dump(self.total_bundles_submitted) - - # Look for bundles to reschedule. - num_done = len(self.status.finished_bundle_timings) - num_idle_workers = self.worker_count - self.task_count - now = time.time() - if ( - config.config['executors_schedule_remote_backups'] - and num_done > 2 - and num_idle_workers > 1 - and (self.last_backup is None or (now - self.last_backup > 1.0)) - and self.backup_lock.acquire(blocking=False) - ): - try: - assert self.backup_lock.locked() - - bundle_to_backup = None - best_score = None - for worker, bundle_uuids in self.status.in_flight_bundles_by_worker.items(): - # Prefer to schedule backups of bundles on slower machines. - base_score = 0 - for record in self.workers: - if worker.machine == record.machine: - base_score = float(record.weight) - base_score = 1.0 / base_score - base_score *= 200.0 - base_score = int(base_score) - break - - for uuid in bundle_uuids: - bundle = self.status.bundle_details_by_uuid.get(uuid, None) - if ( - bundle is not None - and bundle.src_bundle is None - and bundle.backup_bundles is not None - ): - score = base_score - - # Schedule backups of bundles running longer; especially those - # that are unexpectedly slow. - start_ts = self.status.start_per_bundle[uuid] - if start_ts is not None: - runtime = now - start_ts - score += runtime - logger.debug(f'score[{bundle}] => {score} # latency boost') - - if bundle.slower_than_local_p95: - score += runtime / 2 - logger.debug(f'score[{bundle}] => {score} # >worker p95') - - if bundle.slower_than_global_p95: - score += runtime / 2 - logger.debug(f'score[{bundle}] => {score} # >global p95') - - # Prefer backups of bundles that don't have backups already. - backup_count = len(bundle.backup_bundles) - if backup_count == 0: - score *= 2 - elif backup_count == 1: - score /= 2 - elif backup_count == 2: - score /= 8 - else: - score = 0 - logger.debug(f'score[{bundle}] => {score} # {backup_count} dup backup factor') - - if ( - score != 0 - and (best_score is None or score > best_score) - ): - bundle_to_backup = bundle - assert bundle is not None - assert bundle.backup_bundles is not None - assert bundle.src_bundle is None - best_score = score - - if bundle_to_backup is not None: - self.last_backup = now - logger.info(f'=====> SCHEDULING BACKUP {bundle_to_backup} (score={best_score:.1f}) <=====') - self.schedule_backup_for_bundle(bundle_to_backup) - finally: - self.backup_lock.release() + self.adjust_task_count(-1) def check_if_cancelled(self, bundle: BundleDetails) -> bool: with self.status.lock: @@ -695,32 +740,27 @@ class RemoteExecutor(BaseExecutor): worker = None while worker is None: worker = self.find_available_worker_or_block(avoid_machine) + assert worker # Ok, found a worker. bundle.worker = worker 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}...') # Before we do any work, make sure the bundle is still viable. + # It may have been some time between when it was submitted and + # now due to lack of worker availability and someone else may + # have already finished it. if self.check_if_cancelled(bundle): try: - return self.post_launch_work(bundle) + return self.process_work_result(bundle) except Exception as e: - logger.exception(e) - logger.error( + logger.warning( f'{bundle}: bundle says it\'s cancelled upfront but no results?!' ) - assert bundle.worker is not None - self.status.record_release_worker( - bundle.worker, - bundle.uuid, - True, - ) - self.release_worker(bundle.worker) - self.adjust_task_count(-1) + self.release_worker(bundle) if is_original: # Weird. We are the original owner of this # bundle. For it to have been cancelled, a backup @@ -729,41 +769,43 @@ class RemoteExecutor(BaseExecutor): # it is done but we can't find the results it # should have copied over. Reschedule the whole # 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.' + ) return self.emergency_retry_nasty_bundle(bundle) else: # Expected(?). We're a backup and our bundle is # cancelled before we even got started. Something - # went bad in post_launch_work (I acutually don't + # went bad in process_work_result (I acutually don't # see what?) but probably not worth worrying - # about. + # about. Let the original thread worry about + # either finding the results or complaining about + # it. return None # Send input code / data to worker machine if it's not local. if hostname not in machine: try: - cmd = f'{RSYNC} {bundle.code_file} {username}@{machine}:{bundle.code_file}' + 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}.") run_silently(cmd) xfer_latency = time.time() - start_ts - logger.info(f"{bundle}: Copying done to {worker} in {xfer_latency:.1f}s.") + logger.debug(f"{bundle}: Copying to {worker} took {xfer_latency:.1f}s.") except Exception as e: - assert bundle.worker is not None - self.status.record_release_worker( - bundle.worker, - bundle.uuid, - True, - ) - self.release_worker(bundle.worker) - self.adjust_task_count(-1) + self.release_worker(bundle) if is_original: # Weird. We tried to copy the code to the worker and it failed... # 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...' + 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..." ) return self.emergency_retry_nasty_bundle(bundle) else: @@ -780,31 +822,32 @@ class RemoteExecutor(BaseExecutor): # Kick off the work. Note that if this fails we let # wait_for_process deal with it. self.status.record_processing_began(uuid) - cmd = (f'{SSH} {bundle.username}@{bundle.machine} ' - f'"source py38-venv/bin/activate &&' - f' /home/scott/lib/python_modules/remote_worker.py' - f' --code_file {bundle.code_file} --result_file {bundle.result_file}"') + cmd = ( + f'{SSH} {bundle.username}@{bundle.machine} ' + f'"source py38-venv/bin/activate &&' + 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...') p = cmd_in_background(cmd, silent=True) - bundle.pid = pid = p.pid - logger.debug(f'{bundle}: Local ssh process pid={pid}; remote worker is {machine}.') + bundle.pid = p.pid + logger.debug( + f'{bundle}: Local ssh process pid={p.pid}; remote worker is {machine}.' + ) return self.wait_for_process(p, bundle, 0) - def wait_for_process(self, p: subprocess.Popen, bundle: BundleDetails, depth: int) -> Any: + def wait_for_process( + self, p: Optional[subprocess.Popen], bundle: BundleDetails, depth: int + ) -> Any: machine = bundle.machine + assert p pid = p.pid if depth > 3: logger.error( f"I've gotten repeated errors waiting on this bundle; giving up on pid={pid}." ) p.terminate() - self.status.record_release_worker( - bundle.worker, - bundle.uuid, - True, - ) - self.release_worker(bundle.worker) - self.adjust_task_count(-1) + self.release_worker(bundle) return self.emergency_retry_nasty_bundle(bundle) # Spin until either the ssh job we scheduled finishes the @@ -814,16 +857,13 @@ class RemoteExecutor(BaseExecutor): try: p.wait(timeout=0.25) except subprocess.TimeoutExpired: - self.heartbeat() if self.check_if_cancelled(bundle): logger.info( - f'{bundle}: another worker finished bundle, checking it out...' + f'{bundle}: looks like another worker finished bundle...' ) break else: - logger.info( - f"{bundle}: pid {pid} ({machine}) our ssh finished, checking it out..." - ) + logger.info(f"{bundle}: pid {pid} ({machine}) is finished!") p = None break @@ -832,7 +872,7 @@ class RemoteExecutor(BaseExecutor): # that some other worker seems to have completed the bundle # and we're bailing out. try: - ret = self.post_launch_work(bundle) + ret = self.process_work_result(bundle) if ret is not None and p is not None: p.terminate() return ret @@ -850,16 +890,10 @@ class RemoteExecutor(BaseExecutor): logger.warning(msg) return self.wait_for_process(p, bundle, depth + 1) else: - self.status.record_release_worker( - bundle.worker, - bundle.uuid, - True, - ) - self.release_worker(bundle.worker) - self.adjust_task_count(-1) + self.release_worker(bundle) return self.emergency_retry_nasty_bundle(bundle) - def post_launch_work(self, bundle: BundleDetails) -> Any: + def process_work_result(self, bundle: BundleDetails) -> Any: with self.status.lock: is_original = bundle.src_bundle is None was_cancelled = bundle.was_cancelled @@ -875,16 +909,31 @@ class RemoteExecutor(BaseExecutor): if not was_cancelled: assert bundle.machine is not None if bundle.hostname not in bundle.machine: - cmd = f'{RSYNC} {username}@{machine}:{result_file} {result_file} 2>/dev/null' + cmd = f'{SCP} {username}@{machine}:{result_file} {result_file} 2>/dev/null' logger.info( - f"{bundle}: Fetching results from {username}@{machine} via {cmd}" + f"{bundle}: Fetching results back from {username}@{machine} via {cmd}" ) # If either of these throw they are handled in # wait_for_process. - run_silently(cmd) - run_silently(f'{SSH} {username}@{machine}' - f' "/bin/rm -f {code_file} {result_file}"') + attempts = 0 + while True: + try: + run_silently(cmd) + except Exception as e: + attempts += 1 + if attempts >= 3: + 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.' + ) dur = bundle.end_ts - bundle.start_ts self.histogram.add_item(dur) @@ -901,22 +950,15 @@ class RemoteExecutor(BaseExecutor): serialized = rb.read() result = cloudpickle.loads(serialized) except Exception as e: - msg = f'Failed to load {result_file}, this is bad news.' + logger.exception(e) + msg = f'Failed to load {result_file}... this is bad news.' logger.critical(msg) - self.status.record_release_worker( - bundle.worker, - bundle.uuid, - True, - ) - self.release_worker(bundle.worker) + 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}.' - ) + logger.debug(f'Removing local (master) {code_file} and {result_file}.') os.remove(f'{result_file}') os.remove(f'{code_file}') @@ -941,23 +983,18 @@ class RemoteExecutor(BaseExecutor): # Tell the original to stop if we finished first. if not was_cancelled: + orig_bundle = bundle.src_bundle + assert orig_bundle logger.debug( - f'{bundle}: Notifying original {bundle.src_bundle.uuid} we beat them to it.' + f'{bundle}: Notifying original {orig_bundle.uuid} we beat them to it.' ) - bundle.src_bundle.is_cancelled.set() - - assert bundle.worker is not None - self.status.record_release_worker( - bundle.worker, - bundle.uuid, - was_cancelled, - ) - self.release_worker(bundle.worker) - self.adjust_task_count(-1) + orig_bundle.is_cancelled.set() + self.release_worker(bundle, was_cancelled=was_cancelled) return result def create_original_bundle(self, pickle, fname: str): from string_utils import generate_uuid + uuid = generate_uuid(omit_dashes=True) code_file = f'/tmp/{uuid}.code.bin' result_file = f'/tmp/{uuid}.result.bin' @@ -967,25 +1004,25 @@ class RemoteExecutor(BaseExecutor): wb.write(pickle) bundle = BundleDetails( - pickled_code = pickle, - uuid = uuid, - fname = fname, - worker = None, - username = None, - machine = None, - hostname = platform.node(), - code_file = code_file, - result_file = result_file, - pid = 0, - start_ts = time.time(), - end_ts = 0.0, - slower_than_local_p95 = False, - slower_than_global_p95 = False, - src_bundle = None, - is_cancelled = threading.Event(), - was_cancelled = False, - backup_bundles = [], - failure_count = 0, + pickled_code=pickle, + uuid=uuid, + fname=fname, + worker=None, + username=None, + machine=None, + hostname=platform.node(), + code_file=code_file, + result_file=result_file, + pid=0, + start_ts=time.time(), + end_ts=0.0, + slower_than_local_p95=False, + slower_than_global_p95=False, + src_bundle=None, + is_cancelled=threading.Event(), + was_cancelled=False, + backup_bundles=[], + failure_count=0, ) self.status.record_bundle_details(bundle) logger.debug(f'{bundle}: Created an original bundle') @@ -997,33 +1034,32 @@ class RemoteExecutor(BaseExecutor): uuid = src_bundle.uuid + f'_backup#{n}' backup_bundle = BundleDetails( - pickled_code = src_bundle.pickled_code, - uuid = uuid, - fname = src_bundle.fname, - worker = None, - username = None, - machine = None, - hostname = src_bundle.hostname, - code_file = src_bundle.code_file, - result_file = src_bundle.result_file, - pid = 0, - start_ts = time.time(), - end_ts = 0.0, - slower_than_local_p95 = False, - slower_than_global_p95 = False, - src_bundle = src_bundle, - is_cancelled = threading.Event(), - was_cancelled = False, - backup_bundles = None, # backup backups not allowed - failure_count = 0, + pickled_code=src_bundle.pickled_code, + uuid=uuid, + fname=src_bundle.fname, + worker=None, + username=None, + machine=None, + hostname=src_bundle.hostname, + code_file=src_bundle.code_file, + result_file=src_bundle.result_file, + pid=0, + start_ts=time.time(), + end_ts=0.0, + slower_than_local_p95=False, + slower_than_global_p95=False, + src_bundle=src_bundle, + is_cancelled=threading.Event(), + was_cancelled=False, + backup_bundles=None, # backup backups not allowed + failure_count=0, ) 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') return backup_bundle - def schedule_backup_for_bundle(self, - src_bundle: BundleDetails): + def schedule_backup_for_bundle(self, src_bundle: BundleDetails): assert self.status.lock.locked() assert src_bundle is not None backup_bundle = self.create_backup_bundle(src_bundle) @@ -1036,7 +1072,9 @@ class RemoteExecutor(BaseExecutor): # they will move the result_file to this machine and let # the original pick them up and unpickle them. - def emergency_retry_nasty_bundle(self, bundle: BundleDetails) -> fut.Future: + def emergency_retry_nasty_bundle( + self, bundle: BundleDetails + ) -> Optional[fut.Future]: is_original = bundle.src_bundle is None bundle.worker = None avoid_last_machine = bundle.machine @@ -1057,7 +1095,9 @@ class RemoteExecutor(BaseExecutor): 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.') + logger.error( + f'{bundle}: At least it\'s only a backup; better luck with the others.' + ) return None else: msg = f'>>> Emergency rescheduling {bundle} because of unexected errors (wtf?!) <<<' @@ -1066,20 +1106,24 @@ class RemoteExecutor(BaseExecutor): return self.launch(bundle, avoid_last_machine) @overrides - def submit(self, - function: Callable, - *args, - **kwargs) -> fut.Future: + def submit(self, function: Callable, *args, **kwargs) -> fut.Future: + if self.already_shutdown: + raise Exception('Submitted work after shutdown.') pickle = make_cloud_pickle(function, *args, **kwargs) bundle = self.create_original_bundle(pickle, function.__name__) self.total_bundles_submitted += 1 return self._helper_executor.submit(self.launch, bundle) @overrides - def shutdown(self, wait=True) -> None: - self._helper_executor.shutdown(wait) - logging.debug(f'Shutting down RemoteExecutor {self.title}') - print(self.histogram) + def shutdown(self, *, wait: bool = True, quiet: bool = False) -> None: + if not self.already_shutdown: + logging.debug(f'Shutting down RemoteExecutor {self.title}') + self.heartbeat_stop_event.set() + self.heartbeat_thread.join() + self._helper_executor.shutdown(wait) + if not quiet: + print(self.histogram.__repr__(label_formatter='%ds')) + self.already_shutdown = True @singleton @@ -1093,8 +1137,7 @@ class DefaultExecutors(object): logger.debug(f'RUN> ping -c 1 {host}') try: x = cmd_with_timeout( - f'ping -c 1 {host} >/dev/null 2>/dev/null', - timeout_seconds=1.0 + f'ping -c 1 {host} >/dev/null 2>/dev/null', timeout_seconds=1.0 ) return x == 0 except Exception: @@ -1118,60 +1161,50 @@ class DefaultExecutors(object): logger.info('Found cheetah.house') pool.append( RemoteWorkerRecord( - username = 'scott', - machine = 'cheetah.house', - weight = 25, - count = 6, + username='scott', + machine='cheetah.house', + weight=30, + count=6, ), ) if self.ping('meerkat.cabin'): logger.info('Found meerkat.cabin') pool.append( RemoteWorkerRecord( - username = 'scott', - machine = 'meerkat.cabin', - weight = 5, - count = 2, + username='scott', + machine='meerkat.cabin', + weight=12, + count=2, ), ) - # if self.ping('kiosk.house'): - # logger.info('Found kiosk.house') - # pool.append( - # RemoteWorkerRecord( - # username = 'pi', - # machine = 'kiosk.house', - # weight = 1, - # count = 2, - # ), - # ) - if self.ping('hero.house'): - logger.info('Found hero.house') + if self.ping('wannabe.house'): + logger.info('Found wannabe.house') pool.append( RemoteWorkerRecord( - username = 'scott', - machine = 'hero.house', - weight = 30, - count = 10, + username='scott', + machine='wannabe.house', + weight=25, + count=10, ), ) if self.ping('puma.cabin'): logger.info('Found puma.cabin') pool.append( RemoteWorkerRecord( - username = 'scott', - machine = 'puma.cabin', - weight = 25, - count = 6, + username='scott', + machine='puma.cabin', + weight=30, + count=6, ), ) if self.ping('backup.house'): logger.info('Found backup.house') pool.append( RemoteWorkerRecord( - username = 'scott', - machine = 'backup.house', - weight = 3, - count = 2, + username='scott', + machine='backup.house', + weight=8, + count=2, ), ) @@ -1185,3 +1218,14 @@ class DefaultExecutors(object): policy.register_worker_pool(pool) self.remote_executor = RemoteExecutor(pool, policy) return self.remote_executor + + def shutdown(self) -> None: + if self.thread_executor is not None: + self.thread_executor.shutdown(wait=True, quiet=True) + self.thread_executor = None + if self.process_executor is not None: + self.process_executor.shutdown(wait=True, quiet=True) + self.process_executor = None + if self.remote_executor is not None: + self.remote_executor.shutdown(wait=True, quiet=True) + self.remote_executor = None