Mysterious 50 seconds delay between task being queued and start running

[snippins]

I'm using airflow version 2.5.0.

For all the tasks in airflow, after they being queued, there is a mysterious 50 (+/- 2) seconds delay before the tasks actually starts running. I'm using LocalExecutor.

And this happens for all tasks, what can be the reasons for this?

[potiuk]

Hard to say without any evidences or logs, and explaining more about your deployment details (database, how you run your airflow/scheduler etc., Ideally some correlation from logs showing when the scheduler schedules the task for execution and when it actually starts. And finding and sharing all the logs from in-between from all the processes you have.

Also it very much depends on the database you use. For example if you are using sqlite, then ... don't . Various things might happen. Also such delays often say about some resourcing problems - memory, CPU, networking, sockets, filesystem. all that might have some effect.

[snippins]

We're using postgresql for the database. Also I might note that the delay is weirdly very consistent at ~50s (+/- 2).

So I added logging_level=DEBUG under section [core] to see what happen. After I triggered the dag in the web UI, the dag appeared as "queued" on the UI, however in the scheduler log, it keeps printing 0 running and 0 in queue even though the web UI say the dag/task is queued.

Aug 22 14:08:53 frt-airflow-5d444c6969-n9hlk python[34]: [2023-08-22 14:08:53,031] {scheduler_job.py:355} DEBUG - No tasks to consider for execution.
Aug 22 14:08:53 frt-airflow-5d444c6969-n9hlk python[34]: [2023-08-22 14:08:53,033] {base_executor.py:163} DEBUG - 0 running task instances
Aug 22 14:08:53 frt-airflow-5d444c6969-n9hlk python[34]: [2023-08-22 14:08:53,033] {base_executor.py:164} DEBUG - 0 in queue
Aug 22 14:08:53 frt-airflow-5d444c6969-n9hlk python[34]: [2023-08-22 14:08:53,033] {base_executor.py:165} DEBUG - 32 open slots
Aug 22 14:08:53 frt-airflow-5d444c6969-n9hlk python[34]: [2023-08-22 14:08:53,033] {base_executor.py:174} DEBUG - Calling the <class 'airflow.executors.local_executor.LocalExecutor'> sync method

After 50s, the dag starts normally:

Aug 22 14:08:59 frt-airflow-5d444c6969-n9hlk python[34]: [2023-08-22 14:08:59,602] {dagrun.py:687} DEBUG - number of tis tasks for <DagRun airflow_test_dag @ 2023-08-22 14:08:08.215681+00:00: manual__2023-08-22T14:08:08.215681+00:00, state:running, queued_at: 2023-08-22 14:08:08.235228+00:00. externally triggered: True>: 3 task(s)
Aug 22 14:08:59 frt-airflow-5d444c6969-n9hlk python[34]: [2023-08-22 14:08:59,602] {dagrun.py:708} DEBUG - number of scheduleable tasks for <DagRun airflow_test_dag @ 2023-08-22 14:08:08.215681+00:00: manual__2023-08-22T14:08:08.215681+00:00, state:running, queued_at: 2023-08-22 14:08:08.235228+00:00. externally triggered: True>: 3 task(s)
Aug 22 14:08:59 frt-airflow-5d444c6969-n9hlk python[34]: [2023-08-22 14:08:59,603] {taskinstance.py:1097} DEBUG - <TaskInstance: airflow_test_dag.download_s3_image2 manual__2023-08-22T14:08:08.215681+00:00 [None]> dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying.
Aug 22 14:08:59 frt-airflow-5d444c6969-n9hlk python[34]: [2023-08-22 14:08:59,603] {taskinstance.py:1097} DEBUG - <TaskInstance: airflow_test_dag.download_s3_image2 manual__2023-08-22T14:08:08.215681+00:00 [None]> dependency 'Trigger Rule' PASSED: True, The task instance did not have any upstream tasks.
Aug 22 14:08:59 frt-airflow-5d444c6969-n9hlk python[34]: [2023-08-22 14:08:59,612] {taskinstance.py:1087} DEBUG - Dependencies all met for <TaskInstance: airflow_test_dag.download_s3_image2 manual__2023-08-22T14:08:08.215681+00:00 [None]>
Aug 22 14:08:59 frt-airflow-5d444c6969-n9hlk python[34]: [2023-08-22 14:08:59,613] {taskinstance.py:1097} DEBUG - <TaskInstance: airflow_test_dag.starting manual__2023-08-22T14:08:08.215681+00:00 [None]> dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying.
Aug 22 14:08:59 frt-airflow-5d444c6969-n9hlk python[34]: [2023-08-22 14:08:59,613] {taskinstance.py:1097} DEBUG - <TaskInstance: airflow_test_dag.starting manual__2023-08-22T14:08:08.215681+00:00 [None]> dependency 'Trigger Rule' PASSED: True, The task instance did not have any upstream tasks.
Aug 22 14:08:59 frt-airflow-5d444c6969-n9hlk python[8789]: [2023-08-22T14:08:59.613+0000] {settings.py:407} DEBUG - Disposing DB connection pool (PID 8789)
Aug 22 14:08:59 frt-airflow-5d444c6969-n9hlk python[34]: [2023-08-22 14:08:59,617] {taskinstance.py:1087} DEBUG - Dependencies all met for <TaskInstance: airflow_test_dag.starting manual__2023-08-22T14:08:08.215681+00:00 [None]>
Aug 22 14:08:59 frt-airflow-5d444c6969-n9hlk python[34]: [2023-08-22 14:08:59,617] {taskinstance.py:1097} DEBUG - <TaskInstance: airflow_test_dag.ending manual__2023-08-22T14:08:08.215681+00:00 [None]> dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying.
Aug 22 14:08:59 frt-airflow-5d444c6969-n9hlk python[8792]: [2023-08-22T14:08:59.617+0000] {settings.py:407} DEBUG - Disposing DB connection pool (PID 8792)
Aug 22 14:08:59 frt-airflow-5d444c6969-n9hlk python[34]: [2023-08-22 14:08:59,617] {taskinstance.py:1097} DEBUG - <TaskInstance: airflow_test_dag.ending manual__2023-08-22T14:08:08.215681+00:00 [None]> dependency 'Trigger Rule' PASSED: True, The task instance did not have any upstream tasks.
Aug 22 14:08:59 frt-airflow-5d444c6969-n9hlk python[34]: [2023-08-22 14:08:59,621] {taskinstance.py:1087} DEBUG - Dependencies all met for <TaskInstance: airflow_test_dag.ending manual__2023-08-22T14:08:08.215681+00:00 [None]>

[snippins]

Hmm, I seem to have found the problem, for some reason the posgresql database clock is 50 seconds slower than the actual time. I'll try to fix the problem with the database soon and report back.

[potiuk]

Nice. Very interesting side effect.

[snippins]

Everything works as expected after enable ntp service on postgresql server.