X-Git-Url: https://wannabe.guru.org/gitweb/?a=blobdiff_plain;f=executors.py;h=a0273264339ef3b158c1370f457f110842decff1;hb=9821d383ba3de886f8d11d00a588e49c2c280579;hp=3cb0a916c080128e63a23600db76c07e93956ec9;hpb=d08bad64a6884f25d28a2c38c6cd1c87b4335188;p=python_utils.git diff --git a/executors.py b/executors.py index 3cb0a91..a027326 100644 --- a/executors.py +++ b/executors.py @@ -17,11 +17,12 @@ import time from typing import Any, Callable, Dict, List, Optional, Set import cloudpickle # type: ignore +from overrides import overrides from ansi import bg, fg, underline, reset import argparse_utils import config -from exec_utils import run_silently, cmd_in_background +from exec_utils import run_silently, cmd_in_background, cmd_with_timeout from decorator_utils import singleton import histogram as hist @@ -121,6 +122,7 @@ class ThreadExecutor(BaseExecutor): self.histogram.add_item(duration) return result + @overrides def submit(self, function: Callable, *args, @@ -135,6 +137,7 @@ class ThreadExecutor(BaseExecutor): *newargs, **kwargs) + @overrides def shutdown(self, wait = True) -> None: logger.debug(f'Shutting down threadpool executor {self.title}') @@ -163,6 +166,7 @@ class ProcessExecutor(BaseExecutor): self.adjust_task_count(-1) return result + @overrides def submit(self, function: Callable, *args, @@ -181,6 +185,7 @@ class ProcessExecutor(BaseExecutor): ) return result + @overrides def shutdown(self, wait=True) -> None: logger.debug(f'Shutting down processpool executor {self.title}') self._process_executor.shutdown(wait) @@ -192,6 +197,11 @@ class ProcessExecutor(BaseExecutor): return state +class RemoteExecutorException(Exception): + """Thrown when a bundle cannot be executed despite several retries.""" + pass + + @dataclass class RemoteWorkerRecord: username: str @@ -270,7 +280,7 @@ class RemoteExecutorStatus: ) -> None: assert self.lock.locked() self.known_workers.add(worker) - self.start_per_bundle[uuid] = time.time() + self.start_per_bundle[uuid] = None x = self.in_flight_bundles_by_worker.get(worker, set()) x.add(uuid) self.in_flight_bundles_by_worker[worker] = x @@ -287,6 +297,17 @@ class RemoteExecutorStatus: assert self.lock.locked() self.bundle_details_by_uuid[details.uuid] = details + def record_release_worker( + self, + worker: RemoteWorkerRecord, + uuid: str, + was_cancelled: bool, + ) -> None: + with self.lock: + self.record_release_worker_already_locked( + worker, uuid, was_cancelled + ) + def record_release_worker_already_locked( self, worker: RemoteWorkerRecord, @@ -304,6 +325,10 @@ class RemoteExecutorStatus: self.finished_bundle_timings_per_worker[worker] = x self.finished_bundle_timings.append(bundle_latency) + def record_processing_began(self, uuid: str): + with self.lock: + self.start_per_bundle[uuid] = time.time() + def total_in_flight(self) -> int: assert self.lock.locked() total_in_flight = 0 @@ -356,8 +381,13 @@ class RemoteExecutorStatus: None ) pid = str(details.pid) if details is not None else "TBD" - sec = ts - self.start_per_bundle[bundle_uuid] - ret += f' (pid={pid}): {bundle_uuid} for {sec:.1f}s so far ' + if self.start_per_bundle[bundle_uuid] is not None: + sec = ts - self.start_per_bundle[bundle_uuid] + ret += f' (pid={pid}): {bundle_uuid} for {sec:.1f}s so far ' + else: + ret += f' {bundle_uuid} setting up / copying data...' + sec = 0.0 + if qworker is not None: if sec > qworker[1]: ret += f'{bg("red")}>💻p95{reset()} ' @@ -483,18 +513,37 @@ class RemoteExecutor(BaseExecutor): if self.worker_count <= 0: msg = f"We need somewhere to schedule work; count was {self.worker_count}" logger.critical(msg) - raise Exception(msg) + 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.') self._helper_executor = fut.ThreadPoolExecutor( thread_name_prefix="remote_executor_helper", max_workers=self.worker_count, ) self.status = RemoteExecutorStatus(self.worker_count) self.total_bundles_submitted = 0 - logger.debug( - f'Creating remote processpool with {self.worker_count} remote worker threads.' - ) + + def bundle_prefix(self, bundle: BundleDetails) -> str: + colorz = [ + fg('violet red'), + fg('red'), + fg('orange'), + fg('peach orange'), + fg('yellow'), + fg('marigold yellow'), + fg('green yellow'), + fg('tea green'), + fg('cornflower blue'), + fg('turquoise blue'), + fg('tropical blue'), + fg('lavender purple'), + fg('medium purple'), + ] + c = colorz[int(bundle.uuid[-2:], 16) % len(colorz)] + fname = bundle.fname if bundle.fname is not None else 'nofname' + machine = bundle.machine if bundle.machine is not None else 'nomachine' + return f'{c}{bundle.uuid[-8:]}/{fname}/{machine}{reset()}' def is_worker_available(self) -> bool: return self.policy.is_worker_available() @@ -530,8 +579,9 @@ class RemoteExecutor(BaseExecutor): # Regular progress report self.status.periodic_dump(self.total_bundles_submitted) - # Look for bundles to reschedule - if len(self.status.finished_bundle_timings) > 7: + # Look for bundles to reschedule. + num_done = len(self.status.finished_bundle_timings) + if num_done > 7 or (num_done > 5 and self.is_worker_available()): for worker, bundle_uuids in self.status.in_flight_bundles_by_worker.items(): for uuid in bundle_uuids: bundle = self.status.bundle_details_by_uuid.get(uuid, None) @@ -571,25 +621,28 @@ class RemoteExecutor(BaseExecutor): return True return False - def launch(self, bundle: BundleDetails) -> Any: + def launch(self, bundle: BundleDetails, override_avoid_machine=None) -> Any: """Find a worker for bundle or block until one is available.""" self.adjust_task_count(+1) uuid = bundle.uuid hostname = bundle.hostname - avoid_machine = None + avoid_machine = override_avoid_machine + is_original = bundle.src_bundle is None # Try not to schedule a backup on the same host as the original. - if bundle.src_bundle is not None: + if avoid_machine is None and bundle.src_bundle is not None: avoid_machine = bundle.src_bundle.machine worker = None while worker is None: worker = self.find_available_worker_or_block(avoid_machine) + + # Ok, found a worker. bundle.worker = worker machine = bundle.machine = worker.machine username = bundle.username = worker.username fname = bundle.fname self.status.record_acquire_worker(worker, uuid) - logger.debug(f'Running bundle {uuid} on {worker}...') + logger.debug(f'{self.bundle_prefix(bundle)}: Running bundle on {worker}...') # Before we do any work, make sure the bundle is still viable. if self.check_if_cancelled(bundle): @@ -597,54 +650,151 @@ class RemoteExecutor(BaseExecutor): return self.post_launch_work(bundle) except Exception as e: logger.exception(e) - logger.info(f"{uuid}/{fname}: bundle seems to have failed?!") - if bundle.failure_count < config.config['executors_max_bundle_failures']: - return self.launch(bundle) + logger.error( + f'{self.bundle_prefix(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) + if is_original: + # Weird. We are the original owner of this + # bundle. For it to have been cancelled, a backup + # must have already started and completed before + # we even for started. Moreover, the backup says + # it is done but we can't find the results it + # should have copied over. Reschedule the whole + # thing. + return self.emergency_retry_nasty_bundle(bundle) else: - logger.info(f"{uuid}/{fname}: bundle is poison, giving up on it.") + # 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 + # see what?) but probably not worth worrying + # about. return None - # Send input to machine if it's not local. + # Send input code / data to worker machine if it's not local. if hostname not in machine: - cmd = f'{RSYNC} {bundle.code_file} {username}@{machine}:{bundle.code_file}' - logger.info(f"{uuid}/{fname}: Copying work to {worker} via {cmd}") - run_silently(cmd) + try: + cmd = f'{RSYNC} {bundle.code_file} {username}@{machine}:{bundle.code_file}' + start_ts = time.time() + logger.info(f"{self.bundle_prefix(bundle)}: Copying work to {worker} via {cmd}.") + run_silently(cmd) + xfer_latency = time.time() - start_ts + logger.info(f"{self.bundle_prefix(bundle)}: Copying done to {worker} in {xfer_latency:.1f}s.") + except Exception as e: + logger.exception(e) + logger.error( + f'{self.bundle_prefix(bundle)}: failed to send instructions to worker machine?!?' + ) + 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) + 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. + return self.emergency_retry_nasty_bundle(bundle) + else: + # This is actually expected; we're a backup. + # 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. + return None - # Do it. + # 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 py39-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'{self.bundle_prefix(bundle)}: Executing {cmd} in the background to kick off work...') p = cmd_in_background(cmd, silent=True) bundle.pid = pid = p.pid - logger.info(f"{uuid}/{fname}: Start training on {worker} via {cmd} (background pid {pid})") + logger.debug(f'{self.bundle_prefix(bundle)}: Local ssh process pid={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: + uuid = bundle.uuid + machine = bundle.machine + fname = bundle.fname + 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) + return self.emergency_retry_nasty_bundle(bundle) + + # Spin until either the ssh job we scheduled finishes the + # bundle or some backup worker signals that they finished it + # before we could. while True: try: p.wait(timeout=0.25) except subprocess.TimeoutExpired: self.heartbeat() - - # Both source and backup bundles can be cancelled by - # the other depending on which finishes first. if self.check_if_cancelled(bundle): - p.terminate() + logger.info( + f'{self.bundle_prefix(bundle)}: another worker finished bundle, checking it out...' + ) break else: - logger.debug( - f"{uuid}/{fname}: pid {pid} has finished its work normally." + logger.info( + f"{self.bundle_prefix(bundle)}: pid {pid} ({machine}) our ssh finished, checking it out..." ) + p = None break + # If we get here we believe the bundle is done; either the ssh + # subprocess finished (hopefully successfully) or we noticed + # that some other worker seems to have completed the bundle + # and we're bailing out. try: - return self.post_launch_work(bundle) + ret = self.post_launch_work(bundle) + if ret is not None and p is not None: + p.terminate() + return ret + + # Something went wrong; e.g. we could not copy the results + # back, cleanup after ourselves on the remote machine, or + # unpickle the results we got from the remove machine. If we + # still have an active ssh subprocess, keep waiting on it. + # Otherwise, time for an emergency reschedule. except Exception as e: logger.exception(e) - logger.info(f"{uuid}: Bundle seems to have failed?!") - if bundle.failure_count < config.config['executors_max_bundle_failures']: - return self.launch(bundle) - logger.info(f"{uuid}: Bundle is poison, giving up on it.") - return None + logger.error(f'{self.bundle_prefix(bundle)}: Something unexpected just happened...') + if p is not None: + logger.warning( + f"{self.bundle_prefix(bundle)}: Failed to wrap up \"done\" bundle, re-waiting on active ssh." + ) + 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) + return self.emergency_retry_nasty_bundle(bundle) def post_launch_work(self, bundle: BundleDetails) -> Any: with self.status.lock: @@ -666,22 +816,16 @@ class RemoteExecutor(BaseExecutor): if bundle.hostname not in bundle.machine: cmd = f'{RSYNC} {username}@{machine}:{result_file} {result_file} 2>/dev/null' logger.info( - f"{uuid}/{fname}: Fetching results from {username}@{machine} via {cmd}" + f"{self.bundle_prefix(bundle)}: Fetching results from {username}@{machine} via {cmd}" ) - try: - run_silently(cmd) - except subprocess.CalledProcessError: - logger.critical(f'Failed to copy {username}@{machine}:{result_file}!') + + # 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}"') dur = bundle.end_ts - bundle.start_ts self.histogram.add_item(dur) - assert bundle.worker is not None - self.status.record_release_worker_already_locked( - bundle.worker, - bundle.uuid, - was_cancelled - ) # Only the original worker should unpickle the file contents # though since it's the only one whose result matters. The @@ -690,17 +834,28 @@ class RemoteExecutor(BaseExecutor): # if one of the backups finished first; it still must read the # result from disk. if is_original: - logger.debug(f"{uuid}/{fname}: Unpickling {result_file}.") + logger.debug(f"{self.bundle_prefix(bundle)}: Unpickling {result_file}.") try: with open(f'{result_file}', 'rb') as rb: serialized = rb.read() result = cloudpickle.loads(serialized) except Exception as e: - msg = f'Failed to load {result_file}' + msg = f'Failed to load {result_file}, this is bad news.' logger.critical(msg) - bundle.failure_count += 1 + self.status.record_release_worker( + bundle.worker, + bundle.uuid, + True, + ) self.release_worker(bundle.worker) + + # 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}') @@ -711,11 +866,12 @@ class RemoteExecutor(BaseExecutor): if bundle.backup_bundles is not None: for backup in bundle.backup_bundles: logger.debug( - f'{uuid}/{fname}: Notifying backup {backup.uuid} that it\'s cancelled' + f'{self.bundle_prefix(bundle)}: Notifying backup {backup.uuid} that it\'s cancelled' ) backup.is_cancelled.set() - # This is a backup job. + # This is a backup job and, by now, we have already fetched + # the bundle results. else: # Backup results don't matter, they just need to leave the # result file in the right place for their originals to @@ -725,11 +881,16 @@ class RemoteExecutor(BaseExecutor): # Tell the original to stop if we finished first. if not was_cancelled: logger.debug( - f'{uuid}/{fname}: Notifying original {bundle.src_bundle.uuid} that it\'s cancelled' + f'{self.bundle_prefix(bundle)}: Notifying original {bundle.src_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) return result @@ -766,7 +927,7 @@ class RemoteExecutor(BaseExecutor): failure_count = 0, ) self.status.record_bundle_details(bundle) - logger.debug(f'{uuid}/{fname}: Created original bundle') + logger.debug(f'{self.bundle_prefix(bundle)}: Created an original bundle') return bundle def create_backup_bundle(self, src_bundle: BundleDetails): @@ -797,7 +958,7 @@ class RemoteExecutor(BaseExecutor): ) src_bundle.backup_bundles.append(backup_bundle) self.status.record_bundle_details_already_locked(backup_bundle) - logger.debug(f'{uuid}/{src_bundle.fname}: Created backup bundle') + logger.debug(f'{self.bundle_prefix(bundle)}: Created a backup bundle') return backup_bundle def schedule_backup_for_bundle(self, @@ -813,6 +974,37 @@ 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: + uuid = bundle.uuid + is_original = bundle.src_bundle is None + bundle.worker = None + avoid_last_machine = bundle.machine + bundle.machine = None + bundle.username = None + bundle.failure_count += 1 + if is_original: + retry_limit = 3 + else: + retry_limit = 2 + + if bundle.failure_count > retry_limit: + logger.error( + f'{self.bundle_prefix(bundle)}: Tried this bundle too many times already ({retry_limit}x); giving up.' + ) + if is_original: + raise RemoteExecutorException( + f'{self.bundle_prefix(bundle)}: This bundle can\'t be completed despite several backups and retries' + ) + else: + logger.error(f'{self.bundle_prefix(bundle)}: At least it\'s only a backup; better luck with the others.') + return None + else: + logger.warning( + f'>>> Emergency rescheduling {self.bundle_prefix(bundle)} because of unexected errors (wtf?!) <<<' + ) + return self.launch(bundle, avoid_last_machine) + + @overrides def submit(self, function: Callable, *args, @@ -822,6 +1014,7 @@ class RemoteExecutor(BaseExecutor): 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}') @@ -836,12 +1029,15 @@ class DefaultExecutors(object): self.remote_executor: Optional[RemoteExecutor] = None def ping(self, host) -> bool: - command = ['ping', '-c', '1', host] - return subprocess.call( - command, - stdout=subprocess.DEVNULL, - stderr=subprocess.DEVNULL, - ) == 0 + 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 + ) + return x == 0 + except Exception: + return False def thread_pool(self) -> ThreadExecutor: if self.thread_executor is None: @@ -855,8 +1051,10 @@ class DefaultExecutors(object): def remote_pool(self) -> RemoteExecutor: if self.remote_executor is None: + logger.info('Looking for some helper machines...') pool: List[RemoteWorkerRecord] = [] if self.ping('cheetah.house'): + logger.info('Found cheetah.house') pool.append( RemoteWorkerRecord( username = 'scott', @@ -866,6 +1064,7 @@ class DefaultExecutors(object): ), ) if self.ping('video.house'): + logger.info('Found video.house') pool.append( RemoteWorkerRecord( username = 'scott', @@ -875,6 +1074,7 @@ class DefaultExecutors(object): ), ) if self.ping('wannabe.house'): + logger.info('Found wannabe.house') pool.append( RemoteWorkerRecord( username = 'scott', @@ -884,6 +1084,7 @@ class DefaultExecutors(object): ), ) if self.ping('meerkat.cabin'): + logger.info('Found meerkat.cabin') pool.append( RemoteWorkerRecord( username = 'scott', @@ -893,6 +1094,7 @@ class DefaultExecutors(object): ), ) if self.ping('backup.house'): + logger.info('Found backup.house') pool.append( RemoteWorkerRecord( username = 'scott', @@ -901,7 +1103,18 @@ class DefaultExecutors(object): count = 4, ), ) + 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('puma.cabin'): + logger.info('Found puma.cabin') pool.append( RemoteWorkerRecord( username = 'scott', @@ -910,6 +1123,13 @@ class DefaultExecutors(object): count = 4, ), ) + + # 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}.') + record.count = 1 + policy = WeightedRandomRemoteWorkerSelectionPolicy() policy.register_worker_pool(pool) self.remote_executor = RemoteExecutor(pool, policy)