Repository navigation
The scheduler does not appear to be running. Last heartbeat was received X minutes ago. #19192
Description
Apache Airflow version
2.1.4
Operating System
Linux / Ubuntu Server
Versions of Apache Airflow Providers
apache-airflow-providers-ftp==2.0.1
apache-airflow-providers-http==2.0.1
apache-airflow-providers-imap==2.0.1
apache-airflow-providers-postgres==2.3.0
Deployment
Virtualenv installation
Deployment details
Airflow v2.1.4
Postgres 14
LocalExecutor
Installed with Virtualenv / ansible - https://github.com/idealista/airflow-role
What happened
I run a single BashOperator (for a long running task, we have to download data for 8+ hours initially to download from the rate-limited data source API, then download more each day in small increments).
We're only using 3% CPU and 2 GB of memory (out of 64 GB) but the scheduler is unable to run any other simple task at the same time.
Currently only the long task is running, everything else is queued, even thought we have more resources:
What you expected to happen
I expect my long running BashOperator task to run, but for airflow to have the resources to run other tasks without getting blocked like this.
How to reproduce
I run a command with bashoperator (I use it because I have python, C, and rust programs being scheduled by airflow).
bash_command='umask 002 && cd /opt/my_code/ && /opt/my_code/venv/bin/python -m path.to.my.python.namespace'
Configuration:
airflow_executor: LocalExecutor
airflow_database_conn: 'postgresql+psycopg2://airflow:airflow_pass@localhost:5432/airflow'
airflow_database_engine_encoding: utf-8
airflow_database_engine_collation_for_ids:
airflow_database_pool_enabled: True
airflow_database_pool_size: 3
airflow_database_max_overflow: 10
airflow_database_pool_recycle: 2000
airflow_database_pool_pre_ping: True
airflow_database_schema:
airflow_database_connect_args:
airflow_parallelism: 10
airflow_dag_concurrency: 7
airflow_dags_are_paused_at_creation: True
airflow_max_active_runs_per_dag: 16
airflow_load_examples: False
airflow_load_default_connections: False
airflow_plugins_folder: "{{ airflow_app_home }}/plugins"
# [operators]
airflow_operator_default_owner: airflow
airflow_operator_default_cpus: 1
airflow_operator_default_ram: 512
airflow_operator_default_disk: 512
airflow_operator_default_gpus: 0
airflow_default_queue: default
airflow_allow_illegal_arguments: False
Anything else
This occurs every time consistently, also on 2.1.2
The other tasks have this state:
When the long-running task finishes, the other tasks resume normally. But I expect to be able to do some parallel execution /w LocalExecutor.
I haven't tried using pgbouncer.
Are you willing to submit PR?
- Yes I am willing to submit a PR!
Code of Conduct
- I agree to follow this project's Code of Conduct
Activity
potiuk commentedon Oct 28, 2021
It looks like you are actually using SequentialExecutor. That would perfectly explain the behaviour. Are you sure you are using local executor and scheduler is running ? Can you run
airflow infoand verify it / paste the results here?t4n1o commentedon Oct 28, 2021
LocalExecutor:
In this screenshot the scheduler is running 4 of the same process / task, because
max_active_runswas not set (I subsequently set it to 1, because that's the behaviour I want).As stated above, the issue is airflow will not run other dags and the scheduler is not responding. (Strangely, the scheduler is apparently also quite happy to run 1 task from 1 dag in 4 parallel processes.)
I suspect some value in the configuration or not enough database connections.
t4n1o commentedon Oct 28, 2021
potiuk commentedon Oct 28, 2021
It does not look like like Airflow problem to be honest.
It certainly looks like your long running task blocks some resources that blocks scheduler somehow (but there is no indication how it can be blocked). There must be something in your DAGs or task that simply causes the Airflow scheduler to lock up.
This is almost certainly something specific to your deployment (others do not experience it). But what it is, it's hard to say from the information provided.
My best guess is that you have some lock on the database and it makes scheduler wait while running some query.
Is it possible to dump the state of scheduler and dump generaly more of the state of your machine, resouces, sockets, DB locks while it happens (this shoudl be possible with py-spy for example). Also getting all logs of scheduler and seing if it actually "does" something might help. Unfortunately the information we have now is not enough to deduce the reason.
Any insight of WHERE the schduler is locked might help with investigating it.
potiuk commentedon Oct 28, 2021
BTW. Yeah, checking the limits of connections opened in your DB might be a good idea. Especially if you are using variables in your DAGs at top level, it MIGHT lead to a significant number of connections opened, which *might eventually cause scheduler to try to open a new connection and patiently wait until the DB server will have any connection free. It might simply be that your long running tasks are written in the way that they (accidentally) open a lot of those connections and do not close them until the task completes.
I think PGBouncer might help with that, but if too many connections are opened by a single long running task and they are not closed, that might also not help too much.
t4n1o commentedon Jan 2, 2022
Well, there is nothing locking the db. This issue occurs even if there is no database being used by my application.
Types of tasks that cause this problem:
Any program written in rust or python that takes a long time to execute will cause this problem. We are using airflow because once we sync all the historical data, we run the task once per day each new day.
Here is a dump of what the scheduler is doing, while it's stuck.
State of the various airflow processes:
I am starting the rust/python programs in a separate process with BashOperator, and it's stuck on _recv(). Since all the tasks are limited by a rate-limit of some API, disk speed, or network speed, it would be better if airflow could actually run more than 1 task at a time. Any ideas?
t4n1o commentedon Jan 2, 2022
potiuk commentedon Jan 2, 2022
I think you are misusing Airlfow. Airlfow by definition can run multiple tasks even with single local executor, so you are likely misunderstanding how airflow operators are run and run it as a top-level code, and not as task?
Can you please copy your DAG here?
You are not supposed to run long running operations when the DAG file is parsed - parsing should be run rather quickly and from what it looks like you execute a long running process while parsing happens rather than when tasks are executed:
https://airflow.apache.org/docs/apache-airflow/stable/best-practices.html#top-level-python-code
t4n1o commentedon Jan 2, 2022
t4n1o commentedon Jan 2, 2022
I'm not sure how airflow is intended to be used, but sometimes people find other use cases for a tool they haven't designed.
We run a task that can take a few hours to collect all the historical data and process it. And then we want the task to run once per day.
It appears, from my side, that the airflow server UI can't contact the scheduler while the long task is running, and other DAGs can't be run. Perhaps the scheduler wants my code to yield control back to it frequently (once per day of data, for example), but I prefer to let my own code manage the date ranges, because that's where the unit tests are, and all the heavy lifting is in rust anyway.
t4n1o commentedon Jan 2, 2022
What I do find use for in airflow
potiuk commentedon Jan 2, 2022
This is what airflow is designed for. I tihnk you just use it wrongly (or misconfigured it). It is supposed to handle that case perfectly (and it works this way for thousands of users. So it's your configuration/setup/way of using it is wrong.
No. This is no the case (unless you use Sequential Executor which is only suposed to be used for debugging). . Airflow is designed to run multiple paralllel tass at a time:. You likely have some problem in your airlfow installation/configuration
Questions:
Do you actually have scheduler running at all? Does it have coninuous access to the DB?
Are you absolutely sure you are not using SequentialExecutior ? What does your
airflow infosay - can you paste-bin output of it ? (airlfow has built-in flag to send to pastebin). Please make sure also that you do it in exactly the way your scheduler works. Miost likely you run your scheduler with a different configuration than your webserver and that causes the problem.Are you sure you are using Postgres and not Sqlite? What does your
airflow infosay?Where is your Python code (non-DAG)? Did you .airflowignore non-DAG files from airflow's DAG folder?
can you upgrade to Airlfow 2.2.3 (latest released) - it has built-in warnings in case you use Sequential Executor/SQLite in the UI.
Can you change your DAGs to:
I just run it in 2.2.3 and I was able to successuly start even 5 paralllel runs and no problems with Scheduler
t4n1o commentedon Jan 2, 2022
26 remaining items
potiuk commentedon Aug 17, 2022
Do you remember which one @uranusjr ?
potiuk commentedon Aug 17, 2022
This one ? #25532
deepchand commentedon Aug 18, 2022
I have tried to debug it more and found its
self.executor.heartbeat()function which is taking almost 95% of total time of scheduling loopuranusjr commentedon Aug 18, 2022
Yes that one
deepchand commentedon Aug 23, 2022
@potiuk i have debugged more on this issue and found like updating the task state in the scheduler loop significantly increase the total time of self.executor.heartbeat() function which is causing this problem
"The scheduler does not appear to be running. Last heartbeat was received X minutes ago"To be specific
airflow/airflow/executors/celery_executor.py
Line 312 in 9ac7428
"The scheduler does not appear to be running. Last heartbeat was received X minutes ago"Please have a look and let me know if any other info is needed
potiuk commentedon Aug 26, 2022
I do not know that well, but for me it looks like you have some bottlences with your Celery Queu. You have not specified what kind of queue you used - but I think you should look at your Redis or RabbitMQ and see if there are no problems there. Also it might be that simply your Redis or RabbitMQ is badly configured or overloaded and it is somehow blocking state update.
Can you please set log level to debug and see if there are more information printed on what's going on in update_state method?
(you will find how to do it in airlfow configuration docs)
deepchand commentedon Aug 26, 2022
@potiuk We are using Redis as queue, i have cross verified redis is not bottleneck and messages are consumed from redis as soon as they land in redis queue. We have enough resources available on redis side as well.
potiuk commentedon Aug 26, 2022
Any chance for debug logs ?
deepchand commentedon Aug 26, 2022
Debug logs of scheduler ?
potiuk commentedon Aug 26, 2022
Yep:
deepchand commentedon Aug 26, 2022
@potiuk I have added some more debug logs to find the total time taken while fetching state of a single result and for total results in a single loop, please find below
deepchand commentedon Aug 26, 2022
Too much debug logs so tried to filter out only important one, let me know if more info needed
potiuk commentedon Aug 26, 2022
I think your problem is simply extremely slow connection to your database. 5 seconds to run single query indicate a HUGE problem you have with your database. It should take single mlilliseconds .
THIS IS your problem. Not airflow.
You should fix your DB/connectivity and debug why your database is 1000x slower than it should.