Ugh, a bunch of things. @overrides. --lmodule. Chromecasts. etc...
[python_utils.git] / executors.py
index 2f4cf8314fdb07c536c75999fa40ecd83781cb05..d5049a264317c2f764d2068e7108a65d858f7cb2 100644 (file)
@@ -17,13 +17,14 @@ 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 decorator_utils import singleton
-import histogram
+import histogram as hist
 
 logger = logging.getLogger(__name__)
 
@@ -61,43 +62,22 @@ parser.add_argument(
 
 RSYNC = 'rsync -q --no-motd -W --ignore-existing --timeout=60 --size-only -z'
 SSH = 'ssh -oForwardX11=no'
-HIST = histogram.SimpleHistogram(
-    histogram.SimpleHistogram.n_evenly_spaced_buckets(
-        int(0), int(500), 25
-    )
-)
-
-
-def run_local_bundle(fun, *args, **kwargs):
-    logger.debug(f"Running local bundle at {fun.__name__}")
-    start = time.time()
-    result = fun(*args, **kwargs)
-    end = time.time()
-    duration = end - start
-    logger.debug(f"{fun.__name__} finished; used {duration:.1f}s")
-    HIST.add_item(duration)
-    return result
-
-
-def run_cloud_pickle(pickle):
-    fun, args, kwargs = cloudpickle.loads(pickle)
-    logger.debug(f"Running pickled bundle at {fun.__name__}")
-    start = time.time()
-    result = fun(*args, **kwargs)
-    end = time.time()
-    duration = end - start
-    logger.debug(f"{fun.__name__} finished; used {duration:.1f}s")
-    return result
 
 
 def make_cloud_pickle(fun, *args, **kwargs):
-    logger.info(f"Making cloudpickled bundle at {fun.__name__}")
+    logger.debug(f"Making cloudpickled bundle at {fun.__name__}")
     return cloudpickle.dumps((fun, args, kwargs))
 
 
 class BaseExecutor(ABC):
-    def __init__(self):
-        pass
+    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
+            )
+        )
 
     @abstractmethod
     def submit(self,
@@ -111,6 +91,10 @@ class BaseExecutor(ABC):
                  wait: bool = True) -> None:
         pass
 
+    def adjust_task_count(self, delta: int) -> None:
+        self.task_count += delta
+        logger.debug(f'Executor current task count is {self.task_count}')
+
 
 class ThreadExecutor(BaseExecutor):
     def __init__(self,
@@ -126,29 +110,38 @@ class ThreadExecutor(BaseExecutor):
             max_workers=workers,
             thread_name_prefix="thread_executor_helper"
         )
-        self.job_count = 0
 
+    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:
-        self.job_count += 1
-        logger.debug(
-            f'Submitted work to threadpool; there are now {self.job_count} items.'
-        )
+        self.adjust_task_count(+1)
         newargs = []
         newargs.append(function)
         for arg in args:
             newargs.append(arg)
         return self._thread_pool_executor.submit(
-            run_local_bundle,
+            self.run_local_bundle,
             *newargs,
             **kwargs)
 
+    @overrides
     def shutdown(self,
                  wait = True) -> None:
-        logger.debug("Shutting down threadpool executor.")
-        print(HIST)
+        logger.debug(f'Shutting down threadpool executor {self.title}')
+        print(self.histogram)
         self._thread_pool_executor.shutdown(wait)
 
 
@@ -165,24 +158,43 @@ class ProcessExecutor(BaseExecutor):
         self._process_executor = fut.ProcessPoolExecutor(
             max_workers=workers,
         )
-        self.job_count = 0
 
+    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:
-        # Bundle it up before submitting because pickle sucks.
+        start = time.time()
+        self.adjust_task_count(+1)
         pickle = make_cloud_pickle(function, *args, **kwargs)
-        self.job_count += 1
-        logger.debug(
-            f'Submitting work to processpool executor; there are now {self.job_count} items.'
+        result = self._process_executor.submit(
+            self.run_cloud_pickle,
+            pickle
         )
-        return self._process_executor.submit(run_cloud_pickle, pickle)
+        result.add_done_callback(
+            lambda _: self.histogram.add_item(
+                time.time() - start
+            )
+        )
+        return result
 
+    @overrides
     def shutdown(self, wait=True) -> None:
-        logger.debug('Shutting down processpool executor')
-        print(HIST)
+        logger.debug(f'Shutting down processpool executor {self.title}')
         self._process_executor.shutdown(wait)
+        print(self.histogram)
+
+    def __getstate__(self):
+        state = self.__dict__.copy()
+        state['_process_executor'] = None
+        return state
 
 
 @dataclass
@@ -203,6 +215,7 @@ class RemoteWorkerRecord:
 class BundleDetails:
     pickled_code: bytes
     uuid: str
+    fname: str
     worker: Optional[RemoteWorkerRecord]
     username: Optional[str]
     machine: Optional[str]
@@ -468,6 +481,7 @@ class RemoteExecutor(BaseExecutor):
                  policy: RemoteWorkerSelectionPolicy) -> None:
         super().__init__()
         self.workers = workers
+        self.policy = policy
         self.worker_count = 0
         for worker in self.workers:
             self.worker_count += worker.count
@@ -475,7 +489,6 @@ class RemoteExecutor(BaseExecutor):
             msg = f"We need somewhere to schedule work; count was {self.worker_count}"
             logger.critical(msg)
             raise Exception(msg)
-        self.policy = policy
         self.policy.register_worker_pool(self.workers)
         self.cv = threading.Condition()
         self._helper_executor = fut.ThreadPoolExecutor(
@@ -485,7 +498,7 @@ class RemoteExecutor(BaseExecutor):
         self.status = RemoteExecutorStatus(self.worker_count)
         self.total_bundles_submitted = 0
         logger.debug(
-            f'Creating remote processpool with {self.worker_count} remote endpoints.'
+            f'Creating remote processpool with {self.worker_count} remote worker threads.'
         )
 
     def is_worker_available(self) -> bool:
@@ -565,6 +578,7 @@ class RemoteExecutor(BaseExecutor):
 
     def launch(self, bundle: BundleDetails) -> 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
@@ -578,6 +592,7 @@ class RemoteExecutor(BaseExecutor):
         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}...')
 
@@ -587,31 +602,31 @@ class RemoteExecutor(BaseExecutor):
                 return self.post_launch_work(bundle)
             except Exception as e:
                 logger.exception(e)
-                logger.info(f"Bundle {uuid} seems to have failed?!")
+                logger.info(f"{uuid}/{fname}: bundle seems to have failed?!")
                 if bundle.failure_count < config.config['executors_max_bundle_failures']:
                     return self.launch(bundle)
                 else:
-                    logger.info(f"Bundle {uuid} is poison, giving up on it.")
+                    logger.info(f"{uuid}/{fname}: bundle is poison, giving up on it.")
                     return None
 
         # Send input to 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"Copying work to {worker} via {cmd}")
+            logger.info(f"{uuid}/{fname}: Copying work to {worker} via {cmd}")
             run_silently(cmd)
 
         # Do it.
         cmd = (f'{SSH} {bundle.username}@{bundle.machine} '
-               f'"source remote-execution/bin/activate &&'
+               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}"')
         p = cmd_in_background(cmd, silent=True)
         bundle.pid = pid = p.pid
-        logger.info(f"Running {cmd} in the background as process {pid}")
+        logger.info(f"{uuid}/{fname}: Start training on {worker} via {cmd} (background pid {pid})")
 
         while True:
             try:
-                p.wait(timeout=0.5)
+                p.wait(timeout=0.25)
             except subprocess.TimeoutExpired:
                 self.heartbeat()
 
@@ -622,7 +637,7 @@ class RemoteExecutor(BaseExecutor):
                     break
             else:
                 logger.debug(
-                    f"{pid}/{bundle.uuid} has finished its work normally."
+                    f"{uuid}/{fname}: pid {pid} has finished its work normally."
                 )
                 break
 
@@ -630,10 +645,10 @@ class RemoteExecutor(BaseExecutor):
             return self.post_launch_work(bundle)
         except Exception as e:
             logger.exception(e)
-            logger.info(f"Bundle {uuid} seems to have failed?!")
+            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"Bundle {uuid} is poison, giving up on it.")
+            logger.info(f"{uuid}: Bundle is poison, giving up on it.")
             return None
 
     def post_launch_work(self, bundle: BundleDetails) -> Any:
@@ -644,47 +659,43 @@ class RemoteExecutor(BaseExecutor):
             machine = bundle.machine
             result_file = bundle.result_file
             code_file = bundle.code_file
+            fname = bundle.fname
+            uuid = bundle.uuid
 
             # Whether original or backup, if we finished first we must
             # fetch the results if the computation happened on a
             # remote machine.
+            bundle.end_ts = time.time()
             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'
                     logger.info(
-                        f"Fetching results from {username}@{machine} via {cmd}"
+                        f"{uuid}/{fname}: Fetching results from {username}@{machine} via {cmd}"
                     )
                     try:
                         run_silently(cmd)
                     except subprocess.CalledProcessError:
-                        pass
+                        logger.critical(f'Failed to copy {username}@{machine}:{result_file}!')
                     run_silently(f'{SSH} {username}@{machine}'
                                  f' "/bin/rm -f {code_file} {result_file}"')
-            bundle.end_ts = time.time()
+                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
             )
-            if not was_cancelled:
-                dur = bundle.end_ts - bundle.start_ts
-                HIST.add_item(dur)
-
-        # Original or not, the results should be back on the local
-        # machine.  Are they?
-        if not os.path.exists(result_file):
-            msg = f'{result_file} unexpectedly missing, wtf?!'
-            logger.critical(msg)
-            bundle.failure_count += 1
-            self.release_worker(bundle.worker)
-            raise Exception(msg)
 
         # Only the original worker should unpickle the file contents
-        # though since it's the only one whose result matters.
+        # though since it's the only one whose result matters.  The
+        # original is also the only job that may delete result_file
+        # from disk.  Note that the original may have been cancelled
+        # if one of the backups finished first; it still must read the
+        # result from disk.
         if is_original:
-            logger.debug(f"Unpickling {result_file}.")
+            logger.debug(f"{uuid}/{fname}: Unpickling {result_file}.")
             try:
                 with open(f'{result_file}', 'rb') as rb:
                     serialized = rb.read()
@@ -705,29 +716,30 @@ class RemoteExecutor(BaseExecutor):
             if bundle.backup_bundles is not None:
                 for backup in bundle.backup_bundles:
                     logger.debug(
-                        f'Notifying backup {backup.uuid} that it is cancelled'
+                        f'{uuid}/{fname}: Notifying backup {backup.uuid} that it\'s cancelled'
                     )
                     backup.is_cancelled.set()
 
-        # This is a backup.
+        # This is a backup job.
         else:
             # Backup results don't matter, they just need to leave the
-            # result file in the right place for their original to
-            # read later.
+            # result file in the right place for their originals to
+            # read/unpickle later.
             result = None
 
             # Tell the original to stop if we finished first.
             if not was_cancelled:
                 logger.debug(
-                    f'Notifying original {bundle.src_bundle.uuid} that it is cancelled'
+                    f'{uuid}/{fname}: Notifying original {bundle.src_bundle.uuid} that it\'s cancelled'
                 )
                 bundle.src_bundle.is_cancelled.set()
 
         assert bundle.worker is not None
         self.release_worker(bundle.worker)
+        self.adjust_task_count(-1)
         return result
 
-    def create_original_bundle(self, pickle):
+    def create_original_bundle(self, pickle, fname: str):
         from string_utils import generate_uuid
         uuid = generate_uuid(as_hex=True)
         code_file = f'/tmp/{uuid}.code.bin'
@@ -740,6 +752,7 @@ class RemoteExecutor(BaseExecutor):
         bundle = BundleDetails(
             pickled_code = pickle,
             uuid = uuid,
+            fname = fname,
             worker = None,
             username = None,
             machine = None,
@@ -758,7 +771,7 @@ class RemoteExecutor(BaseExecutor):
             failure_count = 0,
         )
         self.status.record_bundle_details(bundle)
-        logger.debug(f'Created original bundle {uuid}')
+        logger.debug(f'{uuid}/{fname}: Created original bundle')
         return bundle
 
     def create_backup_bundle(self, src_bundle: BundleDetails):
@@ -769,6 +782,7 @@ class RemoteExecutor(BaseExecutor):
         backup_bundle = BundleDetails(
             pickled_code = src_bundle.pickled_code,
             uuid = uuid,
+            fname = src_bundle.fname,
             worker = None,
             username = None,
             machine = None,
@@ -788,7 +802,7 @@ class RemoteExecutor(BaseExecutor):
         )
         src_bundle.backup_bundles.append(backup_bundle)
         self.status.record_bundle_details_already_locked(backup_bundle)
-        logger.debug(f'Created backup bundle {uuid}')
+        logger.debug(f'{uuid}/{src_bundle.fname}: Created backup bundle')
         return backup_bundle
 
     def schedule_backup_for_bundle(self,
@@ -796,7 +810,7 @@ class RemoteExecutor(BaseExecutor):
         assert self.status.lock.locked()
         backup_bundle = self.create_backup_bundle(src_bundle)
         logger.debug(
-            f'Scheduling backup bundle {backup_bundle.uuid} for execution'
+            f'{backup_bundle.uuid}/{backup_bundle.fname}: Scheduling backup for execution...'
         )
         self._helper_executor.submit(self.launch, backup_bundle)
 
@@ -804,21 +818,21 @@ class RemoteExecutor(BaseExecutor):
         # they will move the result_file to this machine and let
         # the original pick them up and unpickle them.
 
+    @overrides
     def submit(self,
                function: Callable,
                *args,
                **kwargs) -> fut.Future:
         pickle = make_cloud_pickle(function, *args, **kwargs)
-        bundle = self.create_original_bundle(pickle)
+        bundle = self.create_original_bundle(pickle, function.__name__)
         self.total_bundles_submitted += 1
-        logger.debug(
-            f'Submitted work to remote executor; {self.total_bundles_submitted} items now submitted'
-        )
         return self._helper_executor.submit(self.launch, bundle)
 
+    @overrides
     def shutdown(self, wait=True) -> None:
         self._helper_executor.shutdown(wait)
-        print(HIST)
+        logging.debug(f'Shutting down RemoteExecutor {self.title}')
+        print(self.histogram)
 
 
 @singleton
@@ -881,7 +895,7 @@ class DefaultExecutors(object):
                     RemoteWorkerRecord(
                         username = 'scott',
                         machine = 'meerkat.cabin',
-                        weight = 7,
+                        weight = 5,
                         count = 2,
                     ),
                 )