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

Reduce monitor debug log verbosity #913

Closed aitorarjona closed 2 years ago

aitorarjona commented 2 years ago

This patch aims to reduce logging verbosity for the monitor with debug mode. Currently, it prints pending/running/done futures every update. It could only print the log when there is a future status change (from running to done or pending to running) in order to reduce the number of logs.

Before:

2022-04-25 09:30:15,147 [INFO] lithops.config -- Lithops v2.6.1.dev0
2022-04-25 09:30:15,147 [DEBUG] lithops.config -- Loading configuration from /home/aitor/Projects/lithops-github/lithops/.lithops_config
2022-04-25 09:30:15,154 [DEBUG] lithops.config -- Loading Serverless backend module: ibm_cf
2022-04-25 09:30:15,166 [DEBUG] lithops.config -- Loading Storage backend module: ibm_cos
2022-04-25 09:30:15,185 [DEBUG] lithops.storage.backends.ibm_cos.ibm_cos -- Creating IBM COS client
2022-04-25 09:30:15,185 [DEBUG] lithops.storage.backends.ibm_cos.ibm_cos -- Set IBM COS Endpoint to https://s3.us-south.cloud-object-storage.appdomain.cloud
2022-04-25 09:30:15,185 [DEBUG] lithops.util.ibm_token_manager -- Using IBM COS API Key - Reusing Token from local cache
2022-04-25 09:30:15,188 [DEBUG] lithops.util.ibm_token_manager -- Token expiry time: 2022-04-25 10:16:48.244101+02:00 - Minutes left: 46
2022-04-25 09:30:15,216 [INFO] lithops.storage.backends.ibm_cos.ibm_cos -- IBM COS client created - Region: us-south
2022-04-25 09:30:15,217 [DEBUG] lithops.serverless.backends.ibm_cf.ibm_cf -- Creating IBM Cloud Functions client
2022-04-25 09:30:15,217 [DEBUG] lithops.serverless.backends.ibm_cf.ibm_cf -- Set IBM CF Namespace to aitor_dev_us_south
2022-04-25 09:30:15,217 [DEBUG] lithops.serverless.backends.ibm_cf.ibm_cf -- Set IBM CF Endpoint to https://us-south.functions.cloud.ibm.com
2022-04-25 09:30:15,217 [INFO] lithops.serverless.backends.ibm_cf.ibm_cf -- IBM CF client created - Region: us-south - Namespace: aitor_dev_us_south
2022-04-25 09:30:15,217 [DEBUG] lithops.invokers -- ExecutorID 35d781-0 - Invoker initialized. Max workers: 1200
2022-04-25 09:30:15,217 [DEBUG] lithops.invokers -- ExecutorID 35d781-0 - Serverless invoker created
2022-04-25 09:30:15,217 [DEBUG] lithops.executors -- Function executor for ibm_cf created with ID: 35d781-0
2022-04-25 09:30:15,217 [INFO] lithops.invokers -- ExecutorID 35d781-0 | JobID A000 - Selected Runtime: aitorarjona/cloudbutton-wildfire-ibmcf:0.1 - 2048MB
2022-04-25 09:30:15,217 [DEBUG] lithops.storage.storage -- Runtime metadata found in local disk cache
2022-04-25 09:30:15,217 [DEBUG] lithops.job.job -- ExecutorID 35d781-0 | JobID A000 - Serializing function and data
2022-04-25 09:30:15,218 [DEBUG] lithops.job.serialize -- Referenced modules: time
2022-04-25 09:30:15,218 [DEBUG] lithops.job.serialize -- Modules to transmit: None
2022-04-25 09:30:15,218 [DEBUG] lithops.job.job -- ExecutorID 35d781-0 | JobID A000 - Uploading function and modules to the storage backend
2022-04-25 09:30:16,366 [DEBUG] lithops.storage.backends.ibm_cos.ibm_cos -- PUT Object lithops.jobs/35d781-0/c7b232b4678a50b30e1b1ab2937a3a2d.func.pickle - Size: 611.0B - OK
2022-04-25 09:30:16,366 [DEBUG] lithops.job.job -- ExecutorID 35d781-0 | JobID A000 - Data per activation is < 8.0KiB. Passing data through invocation payload
2022-04-25 09:30:16,366 [INFO] lithops.invokers -- ExecutorID 35d781-0 | JobID A000 - Starting function invocation: my_function() - Total: 1 activations
2022-04-25 09:30:16,367 [DEBUG] lithops.invokers -- ExecutorID 35d781-0 | JobID A000 - Worker processes: 1 - Chunksize: 1
2022-04-25 09:30:16,367 [DEBUG] lithops.invokers -- ExecutorID 35d781-0 - Async invoker 0 started
2022-04-25 09:30:16,368 [DEBUG] lithops.invokers -- ExecutorID 35d781-0 - Async invoker 1 started
2022-04-25 09:30:16,368 [DEBUG] lithops.invokers -- ExecutorID 35d781-0 | JobID A000 - Free workers: 1200 - Going to run 1 activations in 1 workers
2022-04-25 09:30:16,369 [INFO] lithops.invokers -- ExecutorID 35d781-0 | JobID A000 - View execution logs at /tmp/lithops/logs/35d781-0-A000.log
2022-04-25 09:30:16,371 [DEBUG] lithops.monitor -- ExecutorID 35d781-0 - Starting Storage job monitor
2022-04-25 09:30:16,371 [INFO] lithops.wait -- ExecutorID 35d781-0 - Getting results from 1 function activations
2022-04-25 09:30:17,622 [DEBUG] lithops.invokers -- ExecutorID 35d781-0 | JobID A000 - Calls 00000 invoked (1.253s) - Activation ID: 45da1c55b945402a9a1c55b945e02a34
2022-04-25 09:30:18,766 [DEBUG] lithops.monitor -- ExecutorID 35d781-0 - Pending: 0 - Running: 1 - Done: 0
2022-04-25 09:30:21,125 [DEBUG] lithops.monitor -- ExecutorID 35d781-0 - Pending: 0 - Running: 1 - Done: 0
2022-04-25 09:30:23,481 [DEBUG] lithops.monitor -- ExecutorID 35d781-0 - Pending: 0 - Running: 1 - Done: 0
2022-04-25 09:30:25,813 [DEBUG] lithops.monitor -- ExecutorID 35d781-0 - Pending: 0 - Running: 1 - Done: 0
2022-04-25 09:30:28,112 [DEBUG] lithops.monitor -- ExecutorID 35d781-0 - Pending: 0 - Running: 1 - Done: 0
2022-04-25 09:30:30,519 [DEBUG] lithops.monitor -- ExecutorID 35d781-0 - Pending: 0 - Running: 0 - Done: 1
2022-04-25 09:30:30,519 [DEBUG] lithops.monitor -- ExecutorID 35d781-0 - Storage job monitor finished
2022-04-25 09:30:31,392 [DEBUG] lithops.future -- ExecutorID 35d781-0 | JobID A000 - Got status from call 00000 - Activation ID: 45da1c55b945402a9a1c55b945e02a34 - Time: 10.53 seconds
2022-04-25 09:30:31,579 [DEBUG] lithops.future -- ExecutorID 35d781-0 | JobID A000 - Got output from call 00000 - Activation ID: 45da1c55b945402a9a1c55b945e02a34
2022-04-25 09:30:31,580 [INFO] lithops.executors -- ExecutorID 35d781-0 - Cleaning temporary data
2022-04-25 09:30:31,588 [DEBUG] lithops.executors -- ExecutorID 35d781-0 - Finished getting results

After:

2022-04-25 09:27:59,717 [INFO] lithops.config -- Lithops v2.6.1.dev0
2022-04-25 09:27:59,717 [DEBUG] lithops.config -- Loading configuration from /home/aitor/Projects/lithops-github/lithops/.lithops_config
2022-04-25 09:27:59,726 [DEBUG] lithops.config -- Loading Serverless backend module: ibm_cf
2022-04-25 09:27:59,741 [DEBUG] lithops.config -- Loading Storage backend module: ibm_cos
2022-04-25 09:27:59,766 [DEBUG] lithops.storage.backends.ibm_cos.ibm_cos -- Creating IBM COS client
2022-04-25 09:27:59,766 [DEBUG] lithops.storage.backends.ibm_cos.ibm_cos -- Set IBM COS Endpoint to https://s3.us-south.cloud-object-storage.appdomain.cloud
2022-04-25 09:27:59,766 [DEBUG] lithops.util.ibm_token_manager -- Using IBM COS API Key - Reusing Token from local cache
2022-04-25 09:27:59,769 [DEBUG] lithops.util.ibm_token_manager -- Token expiry time: 2022-04-25 10:16:48.244101+02:00 - Minutes left: 48
2022-04-25 09:27:59,804 [INFO] lithops.storage.backends.ibm_cos.ibm_cos -- IBM COS client created - Region: us-south
2022-04-25 09:27:59,804 [DEBUG] lithops.serverless.backends.ibm_cf.ibm_cf -- Creating IBM Cloud Functions client
2022-04-25 09:27:59,804 [DEBUG] lithops.serverless.backends.ibm_cf.ibm_cf -- Set IBM CF Namespace to aitor_dev_us_south
2022-04-25 09:27:59,804 [DEBUG] lithops.serverless.backends.ibm_cf.ibm_cf -- Set IBM CF Endpoint to https://us-south.functions.cloud.ibm.com
2022-04-25 09:27:59,804 [INFO] lithops.serverless.backends.ibm_cf.ibm_cf -- IBM CF client created - Region: us-south - Namespace: aitor_dev_us_south
2022-04-25 09:27:59,805 [DEBUG] lithops.invokers -- ExecutorID b3d3f8-0 - Invoker initialized. Max workers: 1200
2022-04-25 09:27:59,805 [DEBUG] lithops.invokers -- ExecutorID b3d3f8-0 - Serverless invoker created
2022-04-25 09:27:59,805 [DEBUG] lithops.executors -- Function executor for ibm_cf created with ID: b3d3f8-0
2022-04-25 09:27:59,805 [INFO] lithops.invokers -- ExecutorID b3d3f8-0 | JobID A000 - Selected Runtime: aitorarjona/cloudbutton-wildfire-ibmcf:0.1 - 2048MB
2022-04-25 09:27:59,805 [DEBUG] lithops.storage.storage -- Runtime metadata found in local disk cache
2022-04-25 09:27:59,805 [DEBUG] lithops.job.job -- ExecutorID b3d3f8-0 | JobID A000 - Serializing function and data
2022-04-25 09:27:59,806 [DEBUG] lithops.job.serialize -- Referenced modules: time
2022-04-25 09:27:59,806 [DEBUG] lithops.job.serialize -- Modules to transmit: None
2022-04-25 09:27:59,806 [DEBUG] lithops.job.job -- ExecutorID b3d3f8-0 | JobID A000 - Uploading function and modules to the storage backend
2022-04-25 09:28:00,807 [DEBUG] lithops.storage.backends.ibm_cos.ibm_cos -- PUT Object lithops.jobs/b3d3f8-0/c7b232b4678a50b30e1b1ab2937a3a2d.func.pickle - Size: 611.0B - OK
2022-04-25 09:28:00,807 [DEBUG] lithops.job.job -- ExecutorID b3d3f8-0 | JobID A000 - Data per activation is < 8.0KiB. Passing data through invocation payload
2022-04-25 09:28:00,808 [INFO] lithops.invokers -- ExecutorID b3d3f8-0 | JobID A000 - Starting function invocation: my_function() - Total: 1 activations
2022-04-25 09:28:00,808 [DEBUG] lithops.invokers -- ExecutorID b3d3f8-0 | JobID A000 - Worker processes: 1 - Chunksize: 1
2022-04-25 09:28:00,808 [DEBUG] lithops.invokers -- ExecutorID b3d3f8-0 - Async invoker 0 started
2022-04-25 09:28:00,809 [DEBUG] lithops.invokers -- ExecutorID b3d3f8-0 - Async invoker 1 started
2022-04-25 09:28:00,810 [DEBUG] lithops.invokers -- ExecutorID b3d3f8-0 | JobID A000 - Free workers: 1200 - Going to run 1 activations in 1 workers
2022-04-25 09:28:00,811 [INFO] lithops.invokers -- ExecutorID b3d3f8-0 | JobID A000 - View execution logs at /tmp/lithops/logs/b3d3f8-0-A000.log
2022-04-25 09:28:00,812 [DEBUG] lithops.monitor -- ExecutorID b3d3f8-0 - Starting Storage job monitor
2022-04-25 09:28:00,813 [INFO] lithops.wait -- ExecutorID b3d3f8-0 - Getting results from 1 function activations
2022-04-25 09:28:02,404 [DEBUG] lithops.invokers -- ExecutorID b3d3f8-0 | JobID A000 - Calls 00000 invoked (1.594s) - Activation ID: 0142d21561f24c7e82d21561f2ec7eb9
2022-04-25 09:28:03,168 [DEBUG] lithops.monitor -- ExecutorID b3d3f8-0 - Pending: 1 - Running: 0 - Done: 0
2022-04-25 09:28:05,537 [DEBUG] lithops.monitor -- ExecutorID b3d3f8-0 - Pending: 0 - Running: 1 - Done: 0
2022-04-25 09:28:15,351 [DEBUG] lithops.monitor -- ExecutorID b3d3f8-0 - Pending: 0 - Running: 0 - Done: 1
2022-04-25 09:28:15,352 [DEBUG] lithops.monitor -- ExecutorID b3d3f8-0 - Storage job monitor finished
2022-04-25 09:28:15,836 [DEBUG] lithops.future -- ExecutorID b3d3f8-0 | JobID A000 - Got status from call 00000 - Activation ID: 0142d21561f24c7e82d21561f2ec7eb9 - Time: 10.39 seconds
2022-04-25 09:28:15,996 [DEBUG] lithops.future -- ExecutorID b3d3f8-0 | JobID A000 - Got output from call 00000 - Activation ID: 0142d21561f24c7e82d21561f2ec7eb9
2022-04-25 09:28:15,997 [INFO] lithops.executors -- ExecutorID b3d3f8-0 - Cleaning temporary data
2022-04-25 09:28:16,008 [DEBUG] lithops.executors -- ExecutorID b3d3f8-0 - Finished getting results

Developer's Certificate of Origin 1.1

   By making a contribution to this project, I certify that:

   (a) The contribution was created in whole or in part by me and I
       have the right to submit it under the Apache License 2.0; or

   (b) The contribution is based upon previous work that, to the best
       of my knowledge, is covered under an appropriate open source
       license and I have the right under that license to submit that
       work with modifications, whether created in whole or in part
       by me, under the same open source license (unless I am
       permitted to submit under a different license), as indicated
       in the file; or

   (c) The contribution was provided directly to me by some other
       person who certified (a), (b) or (c) and I have not modified
       it.

   (d) I understand and agree that this project and the contribution
       are public and that a record of the contribution (including all
       personal information I submit with it, including my sign-off) is
       maintained indefinitely and may be redistributed consistent with
       this project or the open source license(s) involved.
JosepSampe commented 2 years ago

@aitorarjona The idea was to avoid the feeling that the job is stuck somewhere when logs are not shown, specially for long-running workflows. So, what do you think if at least we show the log once or twice a minute even if it is the same as before?

JosepSampe commented 2 years ago

@aitorarjona ready?

aitorarjona commented 2 years ago

@JosepSampe If you approve this change, then it's ready 🙌 - What do you think, is 60s enough? Should this value be a configurable parameter?

JosepSampe commented 2 years ago

Maybe you can put a global var in monitor.py called LOG_FREQUENCY or so