search

lithops-cloud / lithops

A multi-cloud framework for big data analytics and embarrassingly parallel jobs, that provides an universal API for building parallel applications in the cloud ☁️🚀
http://lithops.cloud
Apache License 2.0
317 stars 105 forks source link

Too many activations triggered from sklearn grid search #1192

Closed foster999 closed 11 months ago

foster999 commented 11 months ago

Using the same example from #1172:

import joblib
from lithops.util.joblib import register_lithops
from sklearn.datasets import load_digits
from sklearn.ensemble import RandomForestClassifier
from sklearn.model_selection import GridSearchCV

digits = load_digits()
param_grid = {
    "n_estimators": [100, 50, 25],
}
model = RandomForestClassifier()
search = GridSearchCV(model, param_grid, cv=2, refit=True)

register_lithops()

with joblib.parallel_backend("lithops"):
    search.fit(
        digits.data,
        digits.target,
    )
print("Best score: %0.3f" % search.best_score_)
print("Best parameters set:")
best_parameters = search.best_estimator_.get_params()
print(best_parameters)

With configuration:

lithops:
    backend: localhost
    storage: localhost
    log_level: DEBUG

The expected 6 activations are run, followed by another 100 activations. I don't think these 100 should be being triggered?

In more complex examples the 100 activations seem to be running model training with the wrong X and Y datasets, causing other errors. This seems to be specific to this sklearn classifier, as others run without the additional activations.

The log shows:

2023-11-09 14:11:06,105 [INFO] config.py:139 -- Lithops v3.0.2.dev0 - Python3.11
2023-11-09 14:11:06,105 [DEBUG] config.py:101 -- Loading configuration from .lithops_config
2023-11-09 14:11:06,106 [DEBUG] config.py:174 -- Loading compute backend module: localhost
2023-11-09 14:11:06,106 [DEBUG] config.py:233 -- Loading Storage backend module: localhost
2023-11-09 14:11:06,106 [DEBUG] localhost.py:36 -- Creating Localhost storage client
2023-11-09 14:11:06,106 [INFO] localhost.py:39 -- Localhost storage client created
2023-11-09 14:11:06,106 [DEBUG] localhost.py:49 -- Creating Localhost compute client
2023-11-09 14:11:06,106 [INFO] localhost.py:58 -- Localhost compute v1 client created
2023-11-09 14:11:06,106 [DEBUG] invokers.py:93 -- ExecutorID c271a1-0 - Invoker initialized. Max workers: 1
2023-11-09 14:11:06,106 [DEBUG] executors.py:148 -- Function executor for localhost created with ID: c271a1-0
2023-11-09 14:11:06,108 [INFO] lithops_backend.py:122 -- Optimizing shared data between tasks
2023-11-09 14:11:06,108 [DEBUG] config.py:101 -- Loading configuration from .lithops_config
2023-11-09 14:11:06,109 [DEBUG] config.py:233 -- Loading Storage backend module: localhost
2023-11-09 14:11:06,109 [DEBUG] localhost.py:36 -- Creating Localhost storage client
2023-11-09 14:11:06,109 [INFO] localhost.py:39 -- Localhost storage client created
2023-11-09 14:11:06,110 [DEBUG] lithops_backend.py:148 -- Proxying <class 'numpy.ndarray'>
2023-11-09 14:11:06,111 [DEBUG] lithops_backend.py:148 -- Proxying <class 'numpy.ndarray'>
2023-11-09 14:11:06,111 [DEBUG] lithops_backend.py:148 -- Proxying <class 'numpy.ndarray'>
2023-11-09 14:11:06,111 [DEBUG] lithops_backend.py:148 -- Proxying <class 'numpy.ndarray'>
2023-11-09 14:11:06,112 [DEBUG] lithops_backend.py:148 -- Proxying <class 'numpy.ndarray'>
2023-11-09 14:11:06,112 [DEBUG] lithops_backend.py:148 -- Proxying <class 'numpy.ndarray'>
2023-11-09 14:11:06,113 [INFO] invokers.py:107 -- ExecutorID c271a1-0 | JobID M000 - Selected Runtime: python 
2023-11-09 14:11:06,113 [DEBUG] storage.py:431 -- Runtime metadata found in local disk cache
2023-11-09 14:11:06,113 [DEBUG] job.py:235 -- ExecutorID c271a1-0 | JobID M000 - Serializing function and data
2023-11-09 14:11:06,117 [DEBUG] module_dependency.py:66 -- Queuing module 'traceback'
2023-11-09 14:11:06,118 [DEBUG] module_dependency.py:110 -- Module 'traceback' is to be ignored, skipping
2023-11-09 14:11:06,118 [DEBUG] module_dependency.py:66 -- Queuing module 'lithops.multiprocessing.util'
2023-11-09 14:11:06,118 [DEBUG] module_dependency.py:110 -- Module 'lithops' is to be ignored, skipping
2023-11-09 14:11:06,118 [DEBUG] module_dependency.py:66 -- Queuing module 'diskcache'
2023-11-09 14:11:06,118 [DEBUG] module_dependency.py:110 -- Module 'diskcache' is to be ignored, skipping
2023-11-09 14:11:06,118 [DEBUG] module_dependency.py:66 -- Queuing module 'os'
2023-11-09 14:11:06,118 [DEBUG] module_dependency.py:110 -- Module 'os' is to be ignored, skipping
2023-11-09 14:11:06,118 [DEBUG] module_dependency.py:66 -- Queuing module 'concurrent.futures.thread'
2023-11-09 14:11:06,118 [DEBUG] module_dependency.py:110 -- Module 'concurrent' is to be ignored, skipping
2023-11-09 14:11:06,118 [DEBUG] module_dependency.py:66 -- Queuing module 'lithops.multiprocessing.process'
2023-11-09 14:11:06,118 [DEBUG] module_dependency.py:110 -- Module 'lithops' is to be ignored, skipping
2023-11-09 14:11:06,118 [DEBUG] module_dependency.py:66 -- Queuing module 'lithops.util.joblib.lithops_backend'
2023-11-09 14:11:06,118 [DEBUG] module_dependency.py:110 -- Module 'lithops' is to be ignored, skipping
2023-11-09 14:11:06,118 [DEBUG] serialize.py:84 -- Referenced modules: .pyenv/versions/3.11.4/lib/python3.11/concurrent/futures/thread.py, venv/lib/python3.11/site-packages/lithops/multiprocessing/util.py, venv/lib/python3.11/site-packages/lithops/util/joblib/lithops_backend.py, venv/lib/python3.11/site-packages/lithops/multiprocessing/process.py, venv/lib/python3.11/site-packages/diskcache/__init__.py, frozen, .pyenv/versions/3.11.4/lib/python3.11/traceback.py
2023-11-09 14:11:06,118 [DEBUG] serialize.py:101 -- Modules to transmit: None
2023-11-09 14:11:06,118 [DEBUG] job.py:269 -- ExecutorID c271a1-0 | JobID M000 - Uploading function and modules to the storage backend
2023-11-09 14:11:06,118 [DEBUG] job.py:295 -- ExecutorID c271a1-0 | JobID M000 - Uploading data to the storage backend
2023-11-09 14:11:06,118 [INFO] invokers.py:172 -- ExecutorID c271a1-0 | JobID M000 - Starting function invocation: cloud_process_wrapper() - Total: 6 activations
2023-11-09 14:11:06,118 [DEBUG] invokers.py:177 -- ExecutorID c271a1-0 | JobID M000 - Worker processes: 10 - Chunksize: 10
2023-11-09 14:11:06,118 [DEBUG] localhost.py:136 -- ExecutorID c271a1-0 | JobID M000 - Putting job into localhost queue
2023-11-09 14:11:06,118 [DEBUG] localhost.py:72 -- Staring localhost job manager
2023-11-09 14:11:06,119 [DEBUG] localhost.py:357 -- Starting Default Environment for venv/bin/python
2023-11-09 14:11:06,119 [DEBUG] localhost.py:361 -- Setting up Default environment
2023-11-09 14:11:06,289 [DEBUG] invokers.py:253 -- ExecutorID c271a1-0 | JobID M000 - Job invoked (0.171s) - Activation ID: c271a1-0-M000
2023-11-09 14:11:06,289 [DEBUG] localhost.py:383 -- ExecutorID c271a1-0 | JobID M000 - Running 6 activations in the localhost worker
2023-11-09 14:11:06,289 [INFO] invokers.py:208 -- ExecutorID c271a1-0 | JobID M000 - View execution logs at /private/var/folders/t4/hdpq5bd51tjfws2mq4kj7gqh0000gn/T/lithops-/logs/c271a1-0-M000.log
2023-11-09 14:11:06,290 [DEBUG] monitor.py:381 -- ExecutorID c271a1-0 - Starting Storage job monitor
2023-11-09 14:11:06,290 [INFO] wait.py:98 -- ExecutorID c271a1-0 - Getting results from 6 function activations
2023-11-09 14:11:07,259 [DEBUG] localhost.py:85 -- ExecutorID c271a1-0 | JobID M000 - Execution finished
2023-11-09 14:11:07,259 [DEBUG] localhost.py:90 -- Localhost job manager stopped
2023-11-09 14:11:08,302 [DEBUG] monitor.py:127 -- ExecutorID c271a1-0 - Pending: 0 - Running: 0 - Done: 6
2023-11-09 14:11:08,302 [DEBUG] monitor.py:409 -- ExecutorID c271a1-0 - Storage job monitor finished
2023-11-09 14:11:08,306 [DEBUG] future.py:273 -- ExecutorID c271a1-0 | JobID M000 - Got status from call 00003 - Activation ID: 9af14688d7a1 - Time: 0.61 seconds
2023-11-09 14:11:08,306 [DEBUG] future.py:273 -- ExecutorID c271a1-0 | JobID M000 - Got status from call 00004 - Activation ID: 9af14688d7a1 - Time: 0.58 seconds
2023-11-09 14:11:08,306 [DEBUG] future.py:273 -- ExecutorID c271a1-0 | JobID M000 - Got status from call 00000 - Activation ID: 9af14688d7a1 - Time: 0.66 seconds
2023-11-09 14:11:08,307 [DEBUG] future.py:293 -- ExecutorID c271a1-0 | JobID M000 - Got output from call 00003 - Activation ID: 9af14688d7a1
2023-11-09 14:11:08,307 [DEBUG] future.py:273 -- ExecutorID c271a1-0 | JobID M000 - Got status from call 00002 - Activation ID: 9af14688d7a1 - Time: 0.61 seconds
2023-11-09 14:11:08,307 [DEBUG] future.py:273 -- ExecutorID c271a1-0 | JobID M000 - Got status from call 00001 - Activation ID: 9af14688d7a1 - Time: 0.66 seconds
2023-11-09 14:11:08,307 [DEBUG] future.py:293 -- ExecutorID c271a1-0 | JobID M000 - Got output from call 00004 - Activation ID: 9af14688d7a1
2023-11-09 14:11:08,307 [DEBUG] future.py:293 -- ExecutorID c271a1-0 | JobID M000 - Got output from call 00000 - Activation ID: 9af14688d7a1
2023-11-09 14:11:08,307 [DEBUG] future.py:273 -- ExecutorID c271a1-0 | JobID M000 - Got status from call 00005 - Activation ID: 9af14688d7a1 - Time: 0.58 seconds
2023-11-09 14:11:08,307 [DEBUG] future.py:293 -- ExecutorID c271a1-0 | JobID M000 - Got output from call 00002 - Activation ID: 9af14688d7a1
2023-11-09 14:11:08,308 [DEBUG] future.py:293 -- ExecutorID c271a1-0 | JobID M000 - Got output from call 00001 - Activation ID: 9af14688d7a1
2023-11-09 14:11:08,308 [DEBUG] future.py:293 -- ExecutorID c271a1-0 | JobID M000 - Got output from call 00005 - Activation ID: 9af14688d7a1
2023-11-09 14:11:08,309 [INFO] executors.py:596 -- ExecutorID c271a1-0 - Cleaning temporary data
2023-11-09 14:11:08,318 [DEBUG] executors.py:506 -- ExecutorID c271a1-0 - Finished getting results
2023-11-09 14:11:08,320 [DEBUG] pool.py:197 -- closing pool
2023-11-09 14:11:08,320 [DEBUG] pool.py:202 -- terminating pool
2023-11-09 14:11:08,360 [INFO] config.py:139 -- Lithops v3.0.2.dev0 - Python3.11
2023-11-09 14:11:08,360 [DEBUG] config.py:101 -- Loading configuration from .lithops_config
2023-11-09 14:11:08,361 [DEBUG] config.py:174 -- Loading compute backend module: localhost
2023-11-09 14:11:08,361 [DEBUG] config.py:233 -- Loading Storage backend module: localhost
2023-11-09 14:11:08,361 [DEBUG] localhost.py:36 -- Creating Localhost storage client
2023-11-09 14:11:08,361 [INFO] localhost.py:39 -- Localhost storage client created
2023-11-09 14:11:08,361 [DEBUG] localhost.py:49 -- Creating Localhost compute client
2023-11-09 14:11:08,361 [INFO] localhost.py:58 -- Localhost compute v1 client created
2023-11-09 14:11:08,361 [DEBUG] invokers.py:93 -- ExecutorID c271a1-1 - Invoker initialized. Max workers: 1
2023-11-09 14:11:08,361 [DEBUG] executors.py:148 -- Function executor for localhost created with ID: c271a1-1
2023-11-09 14:11:08,362 [INFO] lithops_backend.py:122 -- Optimizing shared data between tasks
2023-11-09 14:11:08,362 [DEBUG] config.py:101 -- Loading configuration from .lithops_config
2023-11-09 14:11:08,363 [DEBUG] config.py:233 -- Loading Storage backend module: localhost
2023-11-09 14:11:08,363 [DEBUG] localhost.py:36 -- Creating Localhost storage client
2023-11-09 14:11:08,363 [INFO] localhost.py:39 -- Localhost storage client created
2023-11-09 14:11:08,363 [DEBUG] lithops_backend.py:148 -- Proxying <class 'numpy.ndarray'>
2023-11-09 14:11:08,364 [DEBUG] lithops_backend.py:148 -- Proxying <class 'numpy.ndarray'>
2023-11-09 14:11:08,366 [INFO] invokers.py:107 -- ExecutorID c271a1-1 | JobID M000 - Selected Runtime: python 
2023-11-09 14:11:08,366 [DEBUG] storage.py:427 -- Runtime metadata found in local memory cache
2023-11-09 14:11:08,366 [DEBUG] job.py:235 -- ExecutorID c271a1-1 | JobID M000 - Serializing function and data
2023-11-09 14:11:08,419 [DEBUG] module_dependency.py:66 -- Queuing module 'traceback'
2023-11-09 14:11:08,419 [DEBUG] module_dependency.py:110 -- Module 'traceback' is to be ignored, skipping
2023-11-09 14:11:08,419 [DEBUG] module_dependency.py:66 -- Queuing module 'lithops.multiprocessing.util'
2023-11-09 14:11:08,419 [DEBUG] module_dependency.py:110 -- Module 'lithops' is to be ignored, skipping
2023-11-09 14:11:08,419 [DEBUG] module_dependency.py:66 -- Queuing module 'diskcache'
2023-11-09 14:11:08,419 [DEBUG] module_dependency.py:110 -- Module 'diskcache' is to be ignored, skipping
2023-11-09 14:11:08,419 [DEBUG] module_dependency.py:66 -- Queuing module 'os'
2023-11-09 14:11:08,419 [DEBUG] module_dependency.py:110 -- Module 'os' is to be ignored, skipping
2023-11-09 14:11:08,419 [DEBUG] module_dependency.py:66 -- Queuing module 'concurrent.futures.thread'
2023-11-09 14:11:08,419 [DEBUG] module_dependency.py:110 -- Module 'concurrent' is to be ignored, skipping
2023-11-09 14:11:08,419 [DEBUG] module_dependency.py:66 -- Queuing module 'lithops.multiprocessing.process'
2023-11-09 14:11:08,419 [DEBUG] module_dependency.py:110 -- Module 'lithops' is to be ignored, skipping
2023-11-09 14:11:08,419 [DEBUG] module_dependency.py:66 -- Queuing module 'lithops.util.joblib.lithops_backend'
2023-11-09 14:11:08,419 [DEBUG] module_dependency.py:110 -- Module 'lithops' is to be ignored, skipping
2023-11-09 14:11:08,419 [DEBUG] serialize.py:84 -- Referenced modules: .pyenv/versions/3.11.4/lib/python3.11/concurrent/futures/thread.py, venv/lib/python3.11/site-packages/lithops/multiprocessing/util.py, venv/lib/python3.11/site-packages/lithops/util/joblib/lithops_backend.py, venv/lib/python3.11/site-packages/lithops/multiprocessing/process.py, venv/lib/python3.11/site-packages/diskcache/__init__.py, frozen, .pyenv/versions/3.11.4/lib/python3.11/traceback.py
2023-11-09 14:11:08,419 [DEBUG] serialize.py:101 -- Modules to transmit: None
2023-11-09 14:11:08,419 [DEBUG] job.py:269 -- ExecutorID c271a1-1 | JobID M000 - Uploading function and modules to the storage backend
2023-11-09 14:11:08,419 [DEBUG] job.py:295 -- ExecutorID c271a1-1 | JobID M000 - Uploading data to the storage backend
2023-11-09 14:11:08,420 [INFO] invokers.py:172 -- ExecutorID c271a1-1 | JobID M000 - Starting function invocation: cloud_process_wrapper() - Total: 100 activations
2023-11-09 14:11:08,420 [DEBUG] invokers.py:177 -- ExecutorID c271a1-1 | JobID M000 - Worker processes: 10 - Chunksize: 100
2023-11-09 14:11:08,420 [DEBUG] localhost.py:136 -- ExecutorID c271a1-1 | JobID M000 - Putting job into localhost queue
2023-11-09 14:11:08,420 [DEBUG] localhost.py:72 -- Staring localhost job manager
2023-11-09 14:11:08,420 [DEBUG] localhost.py:357 -- Starting Default Environment for venv/bin/python
2023-11-09 14:11:08,420 [DEBUG] localhost.py:361 -- Setting up Default environment
2023-11-09 14:11:08,499 [DEBUG] invokers.py:253 -- ExecutorID c271a1-1 | JobID M000 - Job invoked (0.079s) - Activation ID: c271a1-1-M000
2023-11-09 14:11:08,499 [DEBUG] localhost.py:383 -- ExecutorID c271a1-1 | JobID M000 - Running 100 activations in the localhost worker
2023-11-09 14:11:08,499 [INFO] invokers.py:208 -- ExecutorID c271a1-1 | JobID M000 - View execution logs at /private/var/folders/t4/hdpq5bd51tjfws2mq4kj7gqh0000gn/T/lithops-/logs/c271a1-1-M000.log
2023-11-09 14:11:08,500 [DEBUG] monitor.py:381 -- ExecutorID c271a1-1 - Starting Storage job monitor
2023-11-09 14:11:08,500 [INFO] wait.py:98 -- ExecutorID c271a1-1 - Getting results from 100 function activations
2023-11-09 14:11:10,510 [DEBUG] monitor.py:127 -- ExecutorID c271a1-1 - Pending: 70 - Running: 10 - Done: 20
2023-11-09 14:11:10,511 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00000 - Activation ID: a944e4440c1d - Time: 0.84 seconds
2023-11-09 14:11:10,512 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00000 - Activation ID: a944e4440c1d
2023-11-09 14:11:10,512 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00005 - Activation ID: a944e4440c1d - Time: 0.81 seconds
2023-11-09 14:11:10,512 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00001 - Activation ID: a944e4440c1d - Time: 0.83 seconds
2023-11-09 14:11:10,512 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00002 - Activation ID: a944e4440c1d - Time: 0.82 seconds
2023-11-09 14:11:10,512 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00004 - Activation ID: a944e4440c1d - Time: 0.82 seconds
2023-11-09 14:11:10,513 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00006 - Activation ID: a944e4440c1d - Time: 0.83 seconds
2023-11-09 14:11:10,513 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00003 - Activation ID: a944e4440c1d - Time: 0.81 seconds
2023-11-09 14:11:10,513 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00005 - Activation ID: a944e4440c1d
2023-11-09 14:11:10,513 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00008 - Activation ID: a944e4440c1d - Time: 0.83 seconds
2023-11-09 14:11:10,513 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00001 - Activation ID: a944e4440c1d
2023-11-09 14:11:10,514 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00007 - Activation ID: a944e4440c1d - Time: 0.82 seconds
2023-11-09 14:11:10,514 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00009 - Activation ID: a944e4440c1d - Time: 0.82 seconds
2023-11-09 14:11:10,514 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00011 - Activation ID: a944e4440c1d - Time: 0.82 seconds
2023-11-09 14:11:10,514 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00015 - Activation ID: a944e4440c1d - Time: 0.84 seconds
2023-11-09 14:11:10,514 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00002 - Activation ID: a944e4440c1d
2023-11-09 14:11:10,514 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00013 - Activation ID: a944e4440c1d - Time: 0.81 seconds
2023-11-09 14:11:10,514 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00010 - Activation ID: a944e4440c1d - Time: 0.82 seconds
2023-11-09 14:11:10,515 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00012 - Activation ID: a944e4440c1d - Time: 0.82 seconds
2023-11-09 14:11:10,515 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00004 - Activation ID: a944e4440c1d
2023-11-09 14:11:10,515 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00014 - Activation ID: a944e4440c1d - Time: 0.84 seconds
2023-11-09 14:11:10,515 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00006 - Activation ID: a944e4440c1d
2023-11-09 14:11:10,516 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00008 - Activation ID: a944e4440c1d
2023-11-09 14:11:10,517 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00007 - Activation ID: a944e4440c1d
2023-11-09 14:11:10,517 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00003 - Activation ID: a944e4440c1d
2023-11-09 14:11:10,517 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00018 - Activation ID: a944e4440c1d - Time: 0.80 seconds
2023-11-09 14:11:10,517 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00019 - Activation ID: a944e4440c1d - Time: 0.82 seconds
2023-11-09 14:11:10,517 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00011 - Activation ID: a944e4440c1d
2023-11-09 14:11:10,517 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00017 - Activation ID: a944e4440c1d - Time: 0.80 seconds
2023-11-09 14:11:10,518 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00015 - Activation ID: a944e4440c1d
2023-11-09 14:11:10,518 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00016 - Activation ID: a944e4440c1d - Time: 0.80 seconds
2023-11-09 14:11:10,518 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00009 - Activation ID: a944e4440c1d
2023-11-09 14:11:10,518 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00013 - Activation ID: a944e4440c1d
2023-11-09 14:11:10,518 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00012 - Activation ID: a944e4440c1d
2023-11-09 14:11:10,518 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00010 - Activation ID: a944e4440c1d
2023-11-09 14:11:10,519 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00014 - Activation ID: a944e4440c1d
2023-11-09 14:11:10,519 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00019 - Activation ID: a944e4440c1d
2023-11-09 14:11:10,519 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00018 - Activation ID: a944e4440c1d
2023-11-09 14:11:10,520 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00017 - Activation ID: a944e4440c1d
2023-11-09 14:11:10,520 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00016 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,046 [DEBUG] monitor.py:127 -- ExecutorID c271a1-1 - Pending: 49 - Running: 10 - Done: 41
2023-11-09 14:11:13,531 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00022 - Activation ID: a944e4440c1d - Time: 0.89 seconds
2023-11-09 14:11:13,532 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00023 - Activation ID: a944e4440c1d - Time: 0.90 seconds
2023-11-09 14:11:13,532 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00020 - Activation ID: a944e4440c1d - Time: 0.92 seconds
2023-11-09 14:11:13,533 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00021 - Activation ID: a944e4440c1d - Time: 0.93 seconds
2023-11-09 14:11:13,534 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00024 - Activation ID: a944e4440c1d - Time: 0.93 seconds
2023-11-09 14:11:13,534 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00022 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,534 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00032 - Activation ID: a944e4440c1d - Time: 0.83 seconds
2023-11-09 14:11:13,535 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00021 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,535 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00020 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,535 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00025 - Activation ID: a944e4440c1d - Time: 0.89 seconds
2023-11-09 14:11:13,535 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00028 - Activation ID: a944e4440c1d - Time: 0.90 seconds
2023-11-09 14:11:13,536 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00023 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,536 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00024 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,536 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00029 - Activation ID: a944e4440c1d - Time: 0.87 seconds
2023-11-09 14:11:13,536 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00026 - Activation ID: a944e4440c1d - Time: 0.93 seconds
2023-11-09 14:11:13,536 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00031 - Activation ID: a944e4440c1d - Time: 0.82 seconds
2023-11-09 14:11:13,536 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00030 - Activation ID: a944e4440c1d - Time: 0.86 seconds
2023-11-09 14:11:13,537 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00033 - Activation ID: a944e4440c1d - Time: 0.82 seconds
2023-11-09 14:11:13,537 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00032 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,539 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00038 - Activation ID: a944e4440c1d - Time: 0.82 seconds
2023-11-09 14:11:13,539 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00027 - Activation ID: a944e4440c1d - Time: 0.91 seconds
2023-11-09 14:11:13,539 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00035 - Activation ID: a944e4440c1d - Time: 0.84 seconds
2023-11-09 14:11:13,540 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00034 - Activation ID: a944e4440c1d - Time: 1.06 seconds
2023-11-09 14:11:13,540 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00037 - Activation ID: a944e4440c1d - Time: 0.85 seconds
2023-11-09 14:11:13,540 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00025 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,540 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00028 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,540 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00036 - Activation ID: a944e4440c1d - Time: 0.81 seconds
2023-11-09 14:11:13,540 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00040 - Activation ID: a944e4440c1d - Time: 0.91 seconds
2023-11-09 14:11:13,541 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00039 - Activation ID: a944e4440c1d - Time: 0.83 seconds
2023-11-09 14:11:13,541 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00029 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,541 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00026 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,541 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00031 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,541 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00030 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,542 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00038 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,542 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00033 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,542 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00035 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,542 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00027 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,543 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00037 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,543 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00034 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,543 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00040 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,543 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00039 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,543 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00036 - Activation ID: a944e4440c1d
2023-11-09 14:11:13,562 [DEBUG] monitor.py:127 -- ExecutorID c271a1-1 - Pending: 40 - Running: 10 - Done: 50
2023-11-09 14:11:14,074 [DEBUG] monitor.py:127 -- ExecutorID c271a1-1 - Pending: 36 - Running: 10 - Done: 54
2023-11-09 14:11:14,552 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00043 - Activation ID: a944e4440c1d - Time: 0.94 seconds
2023-11-09 14:11:14,552 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00041 - Activation ID: a944e4440c1d - Time: 0.95 seconds
2023-11-09 14:11:14,552 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00046 - Activation ID: a944e4440c1d - Time: 0.92 seconds
2023-11-09 14:11:14,553 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00044 - Activation ID: a944e4440c1d - Time: 0.94 seconds
2023-11-09 14:11:14,553 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00045 - Activation ID: a944e4440c1d - Time: 1.13 seconds
2023-11-09 14:11:14,553 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00042 - Activation ID: a944e4440c1d - Time: 0.94 seconds
2023-11-09 14:11:14,554 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00041 - Activation ID: a944e4440c1d
2023-11-09 14:11:14,554 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00050 - Activation ID: a944e4440c1d - Time: 1.02 seconds
2023-11-09 14:11:14,554 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00043 - Activation ID: a944e4440c1d
2023-11-09 14:11:14,554 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00047 - Activation ID: a944e4440c1d - Time: 1.12 seconds
2023-11-09 14:11:14,555 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00048 - Activation ID: a944e4440c1d - Time: 1.25 seconds
2023-11-09 14:11:14,555 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00044 - Activation ID: a944e4440c1d
2023-11-09 14:11:14,555 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00051 - Activation ID: a944e4440c1d - Time: 0.98 seconds
2023-11-09 14:11:14,555 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00046 - Activation ID: a944e4440c1d
2023-11-09 14:11:14,555 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00049 - Activation ID: a944e4440c1d - Time: 1.07 seconds
2023-11-09 14:11:14,556 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00045 - Activation ID: a944e4440c1d
2023-11-09 14:11:14,556 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00052 - Activation ID: a944e4440c1d - Time: 0.96 seconds
2023-11-09 14:11:14,556 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00042 - Activation ID: a944e4440c1d
2023-11-09 14:11:14,556 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00053 - Activation ID: a944e4440c1d - Time: 0.95 seconds
2023-11-09 14:11:14,556 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00050 - Activation ID: a944e4440c1d
2023-11-09 14:11:14,557 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00047 - Activation ID: a944e4440c1d
2023-11-09 14:11:14,557 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00048 - Activation ID: a944e4440c1d
2023-11-09 14:11:14,557 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00051 - Activation ID: a944e4440c1d
2023-11-09 14:11:14,557 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00049 - Activation ID: a944e4440c1d
2023-11-09 14:11:14,558 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00052 - Activation ID: a944e4440c1d
2023-11-09 14:11:14,558 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00053 - Activation ID: a944e4440c1d
2023-11-09 14:11:14,583 [DEBUG] monitor.py:127 -- ExecutorID c271a1-1 - Pending: 30 - Running: 10 - Done: 60
2023-11-09 14:11:15,098 [DEBUG] monitor.py:127 -- ExecutorID c271a1-1 - Pending: 27 - Running: 9 - Done: 64
2023-11-09 14:11:15,563 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00055 - Activation ID: a944e4440c1d - Time: 1.21 seconds
2023-11-09 14:11:15,563 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00054 - Activation ID: a944e4440c1d - Time: 1.25 seconds
2023-11-09 14:11:15,565 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00055 - Activation ID: a944e4440c1d
2023-11-09 14:11:15,565 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00056 - Activation ID: a944e4440c1d - Time: 1.03 seconds
2023-11-09 14:11:15,566 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00054 - Activation ID: a944e4440c1d
2023-11-09 14:11:15,566 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00058 - Activation ID: a944e4440c1d - Time: 0.87 seconds
2023-11-09 14:11:15,566 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00059 - Activation ID: a944e4440c1d - Time: 1.14 seconds
2023-11-09 14:11:15,566 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00057 - Activation ID: a944e4440c1d - Time: 1.01 seconds
2023-11-09 14:11:15,567 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00056 - Activation ID: a944e4440c1d
2023-11-09 14:11:15,567 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00059 - Activation ID: a944e4440c1d
2023-11-09 14:11:15,567 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00058 - Activation ID: a944e4440c1d
2023-11-09 14:11:15,567 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00060 - Activation ID: a944e4440c1d - Time: 1.03 seconds
2023-11-09 14:11:15,568 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00061 - Activation ID: a944e4440c1d - Time: 1.07 seconds
2023-11-09 14:11:15,568 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00057 - Activation ID: a944e4440c1d
2023-11-09 14:11:15,568 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00063 - Activation ID: a944e4440c1d - Time: 1.03 seconds
2023-11-09 14:11:15,568 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00062 - Activation ID: a944e4440c1d - Time: 1.02 seconds
2023-11-09 14:11:15,569 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00060 - Activation ID: a944e4440c1d
2023-11-09 14:11:15,569 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00063 - Activation ID: a944e4440c1d
2023-11-09 14:11:15,569 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00061 - Activation ID: a944e4440c1d
2023-11-09 14:11:15,570 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00062 - Activation ID: a944e4440c1d
2023-11-09 14:11:15,614 [DEBUG] monitor.py:127 -- ExecutorID c271a1-1 - Pending: 20 - Running: 10 - Done: 70
2023-11-09 14:11:16,132 [DEBUG] monitor.py:127 -- ExecutorID c271a1-1 - Pending: 14 - Running: 10 - Done: 76
2023-11-09 14:11:16,575 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00064 - Activation ID: a944e4440c1d - Time: 0.86 seconds
2023-11-09 14:11:16,576 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00064 - Activation ID: a944e4440c1d
2023-11-09 14:11:16,576 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00066 - Activation ID: a944e4440c1d - Time: 1.08 seconds
2023-11-09 14:11:16,576 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00065 - Activation ID: a944e4440c1d - Time: 0.86 seconds
2023-11-09 14:11:16,577 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00067 - Activation ID: a944e4440c1d - Time: 1.10 seconds
2023-11-09 14:11:16,577 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00066 - Activation ID: a944e4440c1d
2023-11-09 14:11:16,577 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00069 - Activation ID: a944e4440c1d - Time: 0.99 seconds
2023-11-09 14:11:16,577 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00068 - Activation ID: a944e4440c1d - Time: 0.83 seconds
2023-11-09 14:11:16,578 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00065 - Activation ID: a944e4440c1d
2023-11-09 14:11:16,578 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00071 - Activation ID: a944e4440c1d - Time: 1.02 seconds
2023-11-09 14:11:16,578 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00070 - Activation ID: a944e4440c1d - Time: 1.05 seconds
2023-11-09 14:11:16,578 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00072 - Activation ID: a944e4440c1d - Time: 1.01 seconds
2023-11-09 14:11:16,579 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00067 - Activation ID: a944e4440c1d
2023-11-09 14:11:16,579 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00068 - Activation ID: a944e4440c1d
2023-11-09 14:11:16,579 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00069 - Activation ID: a944e4440c1d
2023-11-09 14:11:16,579 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00074 - Activation ID: a944e4440c1d - Time: 0.96 seconds
2023-11-09 14:11:16,579 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00077 - Activation ID: a944e4440c1d - Time: 0.74 seconds
2023-11-09 14:11:16,579 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00071 - Activation ID: a944e4440c1d
2023-11-09 14:11:16,580 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00070 - Activation ID: a944e4440c1d
2023-11-09 14:11:16,580 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00072 - Activation ID: a944e4440c1d
2023-11-09 14:11:16,580 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00075 - Activation ID: a944e4440c1d - Time: 0.95 seconds
2023-11-09 14:11:16,580 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00074 - Activation ID: a944e4440c1d
2023-11-09 14:11:16,581 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00077 - Activation ID: a944e4440c1d
2023-11-09 14:11:16,581 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00075 - Activation ID: a944e4440c1d
2023-11-09 14:11:16,650 [DEBUG] monitor.py:127 -- ExecutorID c271a1-1 - Pending: 10 - Running: 10 - Done: 80
2023-11-09 14:11:17,230 [DEBUG] monitor.py:127 -- ExecutorID c271a1-1 - Pending: 5 - Running: 10 - Done: 85
2023-11-09 14:11:17,586 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00078 - Activation ID: a944e4440c1d - Time: 1.08 seconds
2023-11-09 14:11:17,586 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00080 - Activation ID: a944e4440c1d - Time: 0.95 seconds
2023-11-09 14:11:17,586 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00079 - Activation ID: a944e4440c1d - Time: 0.87 seconds
2023-11-09 14:11:17,586 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00073 - Activation ID: a944e4440c1d - Time: 1.06 seconds
2023-11-09 14:11:17,586 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00076 - Activation ID: a944e4440c1d - Time: 0.97 seconds
2023-11-09 14:11:17,587 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00078 - Activation ID: a944e4440c1d
2023-11-09 14:11:17,587 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00082 - Activation ID: a944e4440c1d - Time: 0.94 seconds
2023-11-09 14:11:17,587 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00084 - Activation ID: a944e4440c1d - Time: 0.91 seconds
2023-11-09 14:11:17,587 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00080 - Activation ID: a944e4440c1d
2023-11-09 14:11:17,587 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00083 - Activation ID: a944e4440c1d - Time: 0.92 seconds
2023-11-09 14:11:17,587 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00081 - Activation ID: a944e4440c1d - Time: 0.95 seconds
2023-11-09 14:11:17,587 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00079 - Activation ID: a944e4440c1d
2023-11-09 14:11:17,587 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00073 - Activation ID: a944e4440c1d
2023-11-09 14:11:17,587 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00076 - Activation ID: a944e4440c1d
2023-11-09 14:11:17,588 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00082 - Activation ID: a944e4440c1d
2023-11-09 14:11:17,588 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00084 - Activation ID: a944e4440c1d
2023-11-09 14:11:17,588 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00083 - Activation ID: a944e4440c1d
2023-11-09 14:11:17,588 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00081 - Activation ID: a944e4440c1d
2023-11-09 14:11:17,744 [DEBUG] monitor.py:127 -- ExecutorID c271a1-1 - Pending: 0 - Running: 10 - Done: 90
2023-11-09 14:11:18,123 [DEBUG] localhost.py:85 -- ExecutorID c271a1-1 | JobID M000 - Execution finished
2023-11-09 14:11:18,123 [DEBUG] localhost.py:90 -- Localhost job manager stopped
2023-11-09 14:11:18,261 [DEBUG] monitor.py:127 -- ExecutorID c271a1-1 - Pending: 0 - Running: 0 - Done: 100
2023-11-09 14:11:18,262 [DEBUG] monitor.py:409 -- ExecutorID c271a1-1 - Storage job monitor finished
2023-11-09 14:11:18,591 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00087 - Activation ID: a944e4440c1d - Time: 1.09 seconds
2023-11-09 14:11:18,592 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00086 - Activation ID: a944e4440c1d - Time: 1.13 seconds
2023-11-09 14:11:18,592 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00088 - Activation ID: a944e4440c1d - Time: 0.92 seconds
2023-11-09 14:11:18,592 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00089 - Activation ID: a944e4440c1d - Time: 0.92 seconds
2023-11-09 14:11:18,593 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00087 - Activation ID: a944e4440c1d
2023-11-09 14:11:18,593 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00090 - Activation ID: a944e4440c1d - Time: 0.99 seconds
2023-11-09 14:11:18,593 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00085 - Activation ID: a944e4440c1d - Time: 1.15 seconds
2023-11-09 14:11:18,594 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00092 - Activation ID: a944e4440c1d - Time: 1.01 seconds
2023-11-09 14:11:18,595 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00091 - Activation ID: a944e4440c1d - Time: 0.95 seconds
2023-11-09 14:11:18,595 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00088 - Activation ID: a944e4440c1d
2023-11-09 14:11:18,596 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00086 - Activation ID: a944e4440c1d
2023-11-09 14:11:18,596 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00089 - Activation ID: a944e4440c1d
2023-11-09 14:11:18,596 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00096 - Activation ID: a944e4440c1d - Time: 0.75 seconds
2023-11-09 14:11:18,596 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00093 - Activation ID: a944e4440c1d - Time: 1.01 seconds
2023-11-09 14:11:18,596 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00094 - Activation ID: a944e4440c1d - Time: 0.93 seconds
2023-11-09 14:11:18,597 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00090 - Activation ID: a944e4440c1d
2023-11-09 14:11:18,597 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00098 - Activation ID: a944e4440c1d - Time: 0.70 seconds
2023-11-09 14:11:18,598 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00095 - Activation ID: a944e4440c1d - Time: 0.77 seconds
2023-11-09 14:11:18,598 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00085 - Activation ID: a944e4440c1d
2023-11-09 14:11:18,598 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00092 - Activation ID: a944e4440c1d
2023-11-09 14:11:18,598 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00097 - Activation ID: a944e4440c1d - Time: 0.77 seconds
2023-11-09 14:11:18,598 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00091 - Activation ID: a944e4440c1d
2023-11-09 14:11:18,598 [DEBUG] future.py:273 -- ExecutorID c271a1-1 | JobID M000 - Got status from call 00099 - Activation ID: a944e4440c1d - Time: 0.66 seconds
2023-11-09 14:11:18,599 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00096 - Activation ID: a944e4440c1d
2023-11-09 14:11:18,599 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00093 - Activation ID: a944e4440c1d
2023-11-09 14:11:18,599 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00094 - Activation ID: a944e4440c1d
2023-11-09 14:11:18,600 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00098 - Activation ID: a944e4440c1d
2023-11-09 14:11:18,600 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00095 - Activation ID: a944e4440c1d
2023-11-09 14:11:18,600 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00097 - Activation ID: a944e4440c1d
2023-11-09 14:11:18,600 [DEBUG] future.py:355 -- ExecutorID c271a1-1 | JobID M000 - Got output from call 00099 - Activation ID: a944e4440c1d
2023-11-09 14:11:18,601 [INFO] executors.py:596 -- ExecutorID c271a1-1 - Cleaning temporary data
2023-11-09 14:11:18,609 [DEBUG] executors.py:506 -- ExecutorID c271a1-1 - Finished getting results
2023-11-09 14:11:18,609 [DEBUG] pool.py:197 -- closing pool
2023-11-09 14:11:18,609 [DEBUG] pool.py:202 -- terminating pool
Best score: 0.927
Best parameters set:
{'bootstrap': True, 'ccp_alpha': 0.0, 'class_weight': None, 'criterion': 'gini', 'max_depth': None, 'max_features': 'sqrt', 'max_leaf_nodes': None, 'max_samples': None, 'min_impurity_decrease': 0.0, 'min_samples_leaf': 1, 'min_samples_split': 2, 'min_weight_fraction_leaf': 0.0, 'n_estimators': 100, 'n_jobs': None, 'oob_score': False, 'random_state': None, 'verbose': 0, 'warm_start': False}
foster999 commented 11 months ago

I noted a later sklearn version vs the previous issue. So could be another API change on their end? Edit: Rolling back to 1.3.1 has the same issue

Version details:

System:
    python: 3.11.4 (main, Jul 18 2023, 13:23:55) [Clang 14.0.3 (clang-1403.0.22.14.1)]
executable: /Users/davidfoster/repos/data_engineering_model/venv/bin/python
   machine: macOS-14.1.1-arm64-arm-64bit

Python dependencies:
      sklearn: 1.3.2
          pip: 23.2.1
   setuptools: 65.5.0
        numpy: 1.26.0
        scipy: 1.11.3
       Cython: None
       pandas: 2.1.1
   matplotlib: 3.8.0
       joblib: 1.3.2
threadpoolctl: 3.2.0

Built with OpenMP: True

threadpoolctl info:
       user_api: openmp
   internal_api: openmp
    num_threads: 10
         prefix: libomp
       filepath: /Users/davidfoster/repos/data_engineering_model/venv/lib/python3.11/site-packages/sklearn/.dylibs/libomp.dylib
        version: None

       user_api: blas
   internal_api: openblas
    num_threads: 10
         prefix: libopenblas
       filepath: /Users/davidfoster/repos/data_engineering_model/venv/lib/python3.11/site-packages/numpy/.dylibs/libopenblas64_.0.dylib
        version: 0.3.23.dev
threading_layer: pthreads
   architecture: armv8

       user_api: blas
   internal_api: openblas
    num_threads: 10
         prefix: libopenblas
       filepath: /Users/davidfoster/repos/data_engineering_model/venv/lib/python3.11/site-packages/scipy/.dylibs/libopenblas.0.dylib
        version: 0.3.21.dev
threading_layer: pthreads
   architecture: armv8
JosepSampe commented 11 months ago

Hi @foster999, just a couple of tweaks for clarity:

I'm not familiar with using sklearn, but the Lithops backend implementation is quite straightforward, similar to other implementations like Ray. It essentially spawns the functions it receives from sklearn.

Is there a way to verify the correctness or incorrectness of what you found? Perhaps by trying the Python multiprocessing backend instead of Lithops?"

foster999 commented 11 months ago

If I switch the joblib backend to "loky" both the minimal and more complex example run fine. The complex example doesn't error, which means the additional broken function calls aren't being made

I'll try some debugging in the lithops backend to see if I can spot where the additional calls are coming from

JosepSampe commented 11 months ago

Interesting. I Will try to spot it as well. There might be an error in the Lithops backend, even if it is simple.

foster999 commented 11 months ago

In brief, the sklearn grid search trains multiple models with combinations of parameters (2 * 3 combinations in this example, so 6 activations). When refit is on, it should repeat the training of the model with the best outcome. So this should be a single additional activation.

I've found that the switching off the refit argument stops the 100 activations, so it's likely an issue in the way the model training is being called when refit is True:

import joblib
from lithops.util.joblib import register_lithops
from sklearn.datasets import load_digits
from sklearn.ensemble import RandomForestClassifier
from sklearn.model_selection import GridSearchCV

digits = load_digits()
param_grid = {
    "n_estimators": [100, 50, 25],
}
model = RandomForestClassifier()
search = GridSearchCV(model, param_grid, cv=2, refit=False)

register_lithops()

with joblib.parallel_backend("loky"):
    search.fit(
        digits.data,
        digits.target,
    )
print("Best score: %0.3f" % search.best_score_)
# print("Best parameters set:")
# # best_parameters = search.best_estimator_.get_params()
# # print(best_parameters)
foster999 commented 11 months ago

This call in sklearn is the one that triggers the 100 activations: https://github.com/scikit-learn/scikit-learn/blob/f0fee2736426553a8a32df1ff153ee9ccdfb434b/sklearn/model_selection/_search.py#L1008C11-L1008C11

It's very confusing, as some or all of the additional activations seems to have the positional arguments to this call reordered 🤔

foster999 commented 11 months ago

I'm not sure if this is related, or a secondary issue. The error that I see from the erroneous activations isn't handled correctly by lithops: TypeError: LocalhostHandler.clear() got an unexpected keyword argument 'exception'

It looks like it's using the v1 handler, but passing parameters for the v2 handler

Edit: This must be a separate issue with backwards compatibility of the default/v1 handler. Setting the localhost version to 2 removes this handling error.

JosepSampe commented 11 months ago

Hi, I found and fixed this issue yesterday afternoon, so it is already in master branch if you update.

foster999 commented 11 months ago

Thanks @JosepSampe. Do the additional activations reproduce for you with the example above?

foster999 commented 11 months ago

I've found that sklearn generates the additional function calls here from a second initialisation of the parallel backend and that these calls are intentional. However, this param prefer="threads" is supposed to indicate that they should be run as threads on a single process rather than spinning up multiple processes.

sklearn seems to intepret this prefer param, so it might be a bug in sklearn that means threading is not used for these calls.

I've traced the args and kwargs being passed to these calls and they appear to be correct when passed to the parallel backend, so it seems like lithops could be passing the args incorrectly for these later activations that error

Edit: prefer is actually interpreted by joblib, so it could be that lithops isn't respecting the preference for these calls?

JosepSampe commented 11 months ago

@foster999 I can confirm I have the same issue with the example above, and with refit set to False, those 100 extra functions are not initiated.

EDIT: As you found this prefer parameter is not interpreted inside the lithops backend. So I think the way to proceed is to check this parameter and when it is set to threads, spawn only one function that will use a threading pool to execute all the received tasks in a single function invocation.

JosepSampe commented 11 months ago

@foster999 I included the fix in here if you want to give it a try

foster999 commented 11 months ago

Thanks very much for adding the feature @JosepSampe, that's working for the example above and the more complex use case 🥳