wookiist commented on issue #30593:
URL: https://github.com/apache/airflow/issues/30593#issuecomment-1506368751
Thanks for looking, @potiuk !
## 1. could you please increase log level for dag file processor to debug
Yes, I tested it on dev airflow cluster, and here is the log file.
### log file
```
[2023-04-13T04:52:47.287+0000] {retries.py:80} DEBUG - Running
DagFileProcessorManager._fetch_callbacks_with_retries with retries. Try 1 of 3
[2023-04-13T04:52:47.287+0000] {manager.py:680} DEBUG - Fetching callbacks
from the database.
[2023-04-13T04:52:47.294+0000] {retries.py:80} DEBUG - Running
DagWarning._purge_inactive_dag_warnings_with_retry with retries. Try 1 of 3
[2023-04-13T04:52:47.306+0000] {manager.py:1055} DEBUG - Started a process
(PID: 37) to generate tasks for /opt/airflow/dags/data/
[2023-04-13T04:52:47.307+0000] {manager.py:979} DEBUG - Processor for
/opt/airflow/dags/data/ finished
[2023-04-13T04:52:47.309+0000] {processor.py:296} DEBUG - Waiting for
<ForkProcess name='DagFileProcessor7-Process' pid=36 parent=9 stopped
exitcode=0>
[2023-04-13T04:52:47.310+0000] {manager.py:1019} DEBUG - 1/2 DAG parsing
processes running
[2023-04-13T04:52:47.310+0000] {manager.py:1021} DEBUG - 35 file paths
queued for processing
[2023-04-13T04:52:47.324+0000] {manager.py:864} INFO -
================================================================================
DAG File Processing Stats
File Path
PID Runtime # DAGs # Errors Last Runtime Last Run
-------------------------------------------------------------------------------------
----- --------- -------- ---------- -------------- -------------------
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
37 0.01s 0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
0 0
/opt/airflow/dags/data/
1 0 5.01s
2023-04-13T04:52:37
/opt/airflow/dags/data/
1 0 5.02s
2023-04-13T04:52:42
/opt/airflow/dags/data/
1 0 5.02s
2023-04-13T04:52:22
/opt/airflow/dags/data/
1 0 5.01s
2023-04-13T04:52:27
/opt/airflow/dags/data/
1 0 5.12s
2023-04-13T04:52:17
/opt/airflow/dags/data/
1 0 5.03s
2023-04-13T04:52:32
/opt/airflow/dags/data/
1 0 5.04s
2023-04-13T04:52:47
/opt/airflow/dags/data/
1 0 5.18s
2023-04-13T04:52:17
================================================================================
[2023-04-13T04:52:47.810+0000] {settings.py:408} DEBUG - Disposing DB
connection pool (PID 37)
[2023-04-13T04:52:52.300+0000] {base_job.py:240} DEBUG - [heartbeat]
[2023-04-13T04:52:52.301+0000] {retries.py:80} DEBUG - Running
DagFileProcessorManager._fetch_callbacks_with_retries with retries. Try 1 of 3
[2023-04-13T04:52:52.301+0000] {manager.py:680} DEBUG - Fetching callbacks
from the database.
[2023-04-13T04:52:52.308+0000] {retries.py:80} DEBUG - Running
DagWarning._purge_inactive_dag_warnings_with_retry with retries. Try 1 of 3
[2023-04-13T04:52:52.343+0000] {manager.py:1055} DEBUG - Started a process
(PID: 38) to generate tasks for /opt/airflow/dags/data/B
[2023-04-13T04:52:52.344+0000] {manager.py:979} DEBUG - Processor for
/opt/airflow/dags/data/C finished
[2023-04-13T04:52:52.345+0000] {processor.py:296} DEBUG - Waiting for
<ForkProcess name='DagFileProcessor8-Process' pid=37 parent=9 stopped
exitcode=0>
[2023-04-13T04:52:52.346+0000] {manager.py:1019} DEBUG - 1/2 DAG parsing
processes running
[2023-04-13T04:52:52.346+0000] {manager.py:1021} DEBUG - 34 file paths
queued for processing
[2023-04-13T04:52:52.513+0000] {settings.py:408} DEBUG - Disposing DB
connection pool (PID 38)
[2023-04-13T04:52:57.299+0000] {base_job.py:240} DEBUG - [heartbeat]
[2023-04-13T04:52:57.300+0000] {retries.py:80} DEBUG - Running
DagFileProcessorManager._fetch_callbacks_with_retries with retries. Try 1 of 3
[2023-04-13T04:52:57.300+0000] {manager.py:680} DEBUG - Fetching callbacks
from the database.
[2023-04-13T04:52:57.305+0000] {retries.py:80} DEBUG - Running
DagWarning._purge_inactive_dag_warnings_with_retry with retries. Try 1 of 3
[2023-04-13T04:52:57.316+0000] {manager.py:1055} DEBUG - Started a process
(PID: 39) to generate tasks for /opt/airflow/dags/data/A.py
[2023-04-13T04:52:57.319+0000] {manager.py:979} DEBUG - Processor for
/opt/airflow/dags/data/B.py finished
[2023-04-13T04:52:57.320+0000] {processor.py:296} DEBUG - Waiting for
<ForkProcess name='DagFileProcessor9-Process' pid=38 parent=9 stopped
exitcode=0>
[2023-04-13T04:52:57.321+0000] {manager.py:1019} DEBUG - 1/2 DAG parsing
processes running
[2023-04-13T04:52:57.321+0000] {manager.py:1021} DEBUG - 33 file paths
queued for processing
[2023-04-13T04:52:57.516+0000] {settings.py:408} DEBUG - Disposing DB
connection pool (PID 39)
[2023-04-13T04:53:02.314+0000] {base_job.py:240} DEBUG - [heartbeat]
[2023-04-13T04:53:02.314+0000] {retries.py:80} DEBUG - Running
DagFileProcessorManager._fetch_callbacks_with_retries with retries. Try 1 of 3
[2023-04-13T04:53:02.315+0000] {manager.py:680} DEBUG - Fetching callbacks
from the database.
[2023-04-13T04:53:02.319+0000] {retries.py:80} DEBUG - Running
DagWarning._purge_inactive_dag_warnings_with_retry with retries. Try 1 of 3
[2023-04-13T04:53:02.328+0000] {manager.py:1055} DEBUG - Started a process
(PID: 40) to generate tasks for /opt/airflow/dags/data/D.py
[2023-04-13T04:53:02.329+0000] {manager.py:979} DEBUG - Processor for
/opt/airflow/dags/data/A.py finished
[2023-04-13T04:53:02.329+0000] {processor.py:296} DEBUG - Waiting for
<ForkProcess name='DagFileProcessor10-Process' pid=39 parent=9 stopped
exitcode=0>
[2023-04-13T04:53:02.330+0000] {manager.py:1019} DEBUG - 1/2 DAG parsing
processes running
[2023-04-13T04:53:02.330+0000] {manager.py:1021} DEBUG - 32 file paths
queued for processing
[2023-04-13T04:53:02.471+0000] {settings.py:408} DEBUG - Disposing DB
connection pool (PID 40)
[2023-04-13T04:53:07.321+0000] {base_job.py:240} DEBUG - [heartbeat]
[2023-04-13T04:53:07.322+0000] {retries.py:80} DEBUG - Running
DagFileProcessorManager._fetch_callbacks_with_retries with retries. Try 1 of 3
[2023-04-13T04:53:07.322+0000] {manager.py:680} DEBUG - Fetching callbacks
from the database.
[2023-04-13T04:53:07.326+0000] {retries.py:80} DEBUG - Running
DagWarning._purge_inactive_dag_warnings_with_retry with retries. Try 1 of 3
```
## 2. Can you please take a look at the setting of scheduler
'max_callbacks_for_loop configuration (default is 20) .
I think you're probably referring to the `max_callbacks_per_loop` value, and
I changed that to 5.
This is the log file after I change the value. And this is the graph change.
### log file
```
[2023-04-13T05:15:43.600+0000] {base_job.py:240} DEBUG - [heartbeat]
[2023-04-13T05:15:43.601+0000] {retries.py:80} DEBUG - Running
DagFileProcessorManager._fetch_callbacks_with_retries with retries. Try 1 of 3
[2023-04-13T05:15:43.601+0000] {manager.py:680} DEBUG - Fetching callbacks
from the database.
[2023-04-13T05:15:43.611+0000] {retries.py:80} DEBUG - Running
DagWarning._purge_inactive_dag_warnings_with_retry with retries. Try 1 of 3
[2023-04-13T05:15:43.630+0000] {manager.py:1055} DEBUG - Started a process
(PID: 185) to generate tasks for /opt/airflow/dags/data/A.py
[2023-04-13T05:15:43.632+0000] {manager.py:979} DEBUG - Processor for
/opt/airflow/dags/data/0.py finished
[2023-04-13T05:15:43.637+0000] {processor.py:296} DEBUG - Waiting for
<ForkProcess name='DagFileProcessor91-Process' pid=184 parent=6 stopped
exitcode=0>
[2023-04-13T05:15:43.637+0000] {manager.py:1019} DEBUG - 1/2 DAG parsing
processes running
[2023-04-13T05:15:43.637+0000] {manager.py:1021} DEBUG - 29 file paths
queued for processing
[2023-04-13T05:15:43.684+0000] {manager.py:864} INFO -
================================================================================
DAG File Processing Stats
File Path
PID Runtime # DAGs # Errors Last Runtime Last Run
-------------------------------------------------------------------------------------
----- --------- -------- ---------- -------------- -------------------
/opt/airflow/dags/data/
0 1 5.04s
2023-04-13T05:14:43
/opt/airflow/dags/data/
0 0 5.21s
2023-04-13T05:10:53
/opt/airflow/dags/data/
0 0 4.89s
2023-04-13T05:10:58
/opt/airflow/dags/data/
0 0 5.15s
2023-04-13T05:14:53
/opt/airflow/dags/data/
0 0 5.01s
2023-04-13T05:11:08
/opt/airflow/dags/data/
0 0 5.03s
2023-04-13T05:11:03
/opt/airflow/dags/data/
0 0 5.08s
2023-04-13T05:11:13
/opt/airflow/dags/data/
0 0 5.02s
2023-04-13T05:11:18
/opt/airflow/dags/data/
0 1 5.01s
2023-04-13T05:13:13
/opt/airflow/dags/data/
0 0 5.61s
2023-04-13T05:14:38
/opt/airflow/dags/data/
0 1 5.07s
2023-04-13T05:13:18
/opt/airflow/dags/data/
0 1 5.05s
2023-04-13T05:13:38
/opt/airflow/dags/data/
0 1 4.99s
2023-04-13T05:13:43
/opt/airflow/dags/data/
0 1 8.10s
2023-04-13T05:13:51
/opt/airflow/dags/data/
0 1 4.99s
2023-04-13T05:13:23
/opt/airflow/dags/data/
1 0 18.92s
2023-04-13T05:14:43
/opt/airflow/dags/data/
1 0 5.09s
2023-04-13T05:14:17
/opt/airflow/dags/data/
1 0 5.08s
2023-04-13T05:14:17
/opt/airflow/dags/data/
1 0 5.06s
2023-04-13T05:13:33
/opt/airflow/dags/data/
1 0 17.68s
2023-04-13T05:14:06
/opt/airflow/dags/data/
1 0 5.14s
2023-04-13T05:12:43
/opt/airflow/dags/data/
1 0 4.92s
2023-04-13T05:12:48
/opt/airflow/dags/data/
1 0 5.02s
2023-04-13T05:13:08
/opt/airflow/dags/data/
1 0 5.09s
2023-04-13T05:12:53
/opt/airflow/dags/data/
1 0 5.02s
2023-04-13T05:12:38
/opt/airflow/dags/data/
1 0 5.01s
2023-04-13T05:12:33
/opt/airflow/dags/data/
1 0 5.02s
2023-04-13T05:13:03
/opt/airflow/dags/data/
1 0 5.01s
2023-04-13T05:12:58
/opt/airflow/dags/data/
1 0 5.05s
2023-04-13T05:15:23
/opt/airflow/dags/data/
1 0 4.99s
2023-04-13T05:15:28
/opt/airflow/dags/data/
185 0.02s 1 0 5.03s
2023-04-13T05:12:13
/opt/airflow/dags/data/
1 0 5.09s
2023-04-13T05:15:08
/opt/airflow/dags/data/
1 0 5.04s
2023-04-13T05:12:18
/opt/airflow/dags/data/
1 0 4.99s
2023-04-13T05:15:38
/opt/airflow/dags/data/
1 0 5.06s
2023-04-13T05:15:13
/opt/airflow/dags/data/
1 0 5.01s
2023-04-13T05:12:23
/opt/airflow/dags/data/
1 0 5.03s
2023-04-13T05:12:28
/opt/airflow/dags/data/
1 0 5.12s
2023-04-13T05:15:03
/opt/airflow/dags/data/
1 0 5.05s
2023-04-13T05:15:43
/opt/airflow/dags/data/
1 0 4.99s
2023-04-13T05:15:18
/opt/airflow/dags/data/
1 0 5.05s
2023-04-13T05:15:33
/opt/airflow/dags/data/
1 0 4.91s
2023-04-13T05:14:58
/opt/airflow/dags/data/
1 0 9.75s
2023-04-13T05:14:06
/opt/airflow/dags/data/
1 0 5.02s
2023-04-13T05:13:28
================================================================================
[2023-04-13T05:15:43.853+0000] {settings.py:408} DEBUG - Disposing DB
connection pool (PID 185)
[2023-04-13T05:15:48.616+0000] {base_job.py:240} DEBUG - [heartbeat]
[2023-04-13T05:15:48.617+0000] {retries.py:80} DEBUG - Running
DagFileProcessorManager._fetch_callbacks_with_retries with retries. Try 1 of 3
[2023-04-13T05:15:48.618+0000] {manager.py:680} DEBUG - Fetching callbacks
from the database.
[2023-04-13T05:15:48.645+0000] {retries.py:80} DEBUG - Running
DagWarning._purge_inactive_dag_warnings_with_retry with retries. Try 1 of 3
[2023-04-13T05:15:48.657+0000] {manager.py:1055} DEBUG - Started a process
(PID: 186) to generate tasks for /opt/airflow/dags/data/B.py
[2023-04-13T05:15:48.658+0000] {manager.py:979} DEBUG - Processor for
/opt/airflow/dags/data/A.py finished
[2023-04-13T05:15:48.660+0000] {processor.py:296} DEBUG - Waiting for
<ForkProcess name='DagFileProcessor92-Process' pid=185 parent=6 stopped
exitcode=0>
[2023-04-13T05:15:48.661+0000] {manager.py:1019} DEBUG - 1/2 DAG parsing
processes running
[2023-04-13T05:15:48.661+0000] {manager.py:1021} DEBUG - 28 file paths
queued for processing
[2023-04-13T05:15:48.974+0000] {settings.py:408} DEBUG - Disposing DB
connection pool (PID 186)
[2023-04-13T05:15:53.671+0000] {base_job.py:240} DEBUG - [heartbeat]
[2023-04-13T05:15:53.684+0000] {retries.py:80} DEBUG - Running
DagFileProcessorManager._fetch_callbacks_with_retries with retries. Try 1 of 3
[2023-04-13T05:15:53.686+0000] {manager.py:680} DEBUG - Fetching callbacks
from the database.
[2023-04-13T05:15:53.708+0000] {retries.py:80} DEBUG - Running
DagWarning._purge_inactive_dag_warnings_with_retry with retries. Try 1 of 3
[2023-04-13T05:15:53.742+0000] {manager.py:1055} DEBUG - Started a process
(PID: 187) to generate tasks for /opt/airflow/dags/data/C.py
[2023-04-13T05:15:53.757+0000] {manager.py:979} DEBUG - Processor for
/opt/airflow/dags/data/B.py finished
[2023-04-13T05:15:53.758+0000] {processor.py:296} DEBUG - Waiting for
<ForkProcess name='DagFileProcessor93-Process' pid=186 parent=6 stopped
exitcode=0>
[2023-04-13T05:15:53.762+0000] {manager.py:1019} DEBUG - 1/2 DAG parsing
processes running
[2023-04-13T05:15:53.762+0000] {manager.py:1021} DEBUG - 27 file paths
queued for processing
[2023-04-13T05:15:54.682+0000] {settings.py:408} DEBUG - Disposing DB
connection pool (PID 187)
[2023-04-13T05:15:58.656+0000] {base_job.py:240} DEBUG - [heartbeat]
[2023-04-13T05:15:58.657+0000] {retries.py:80} DEBUG - Running
DagFileProcessorManager._fetch_callbacks_with_retries with retries. Try 1 of 3
[2023-04-13T05:15:58.658+0000] {manager.py:680} DEBUG - Fetching callbacks
from the database.
[2023-04-13T05:15:58.664+0000] {retries.py:80} DEBUG - Running
DagWarning._purge_inactive_dag_warnings_with_retry with retries. Try 1 of 3
```
### graph
<img width="1898" alt="image"
src="https://user-images.githubusercontent.com/16011260/231660733-0d3eaaf3-283c-472f-abbf-216531cdaf77.png";>
Unfortunately, it looks like the value actually increased after the change.
I'm of the same opinion. It's unfortunate that I can't drill down and see
the metrics, but I was suspecting that something in the retry logic was adding
multiple behaviors.
Unfortunately I couldn't get the database logs, and based on the dag
processor debug logs alone, I'm wondering if there's something wrong with the
retry logic as well. Please correct me if I'm misinterpreting the log files.
By any chance, could you explain what callbacks are involved in the DAG?
And [here](https://github.com/apache/airflow/pull/30079/files) I see that
the @provide_session and @retry_db_transaction decorators are used in separate
functions, but it's still possible to call a function with the
@retry_db_transaction decorator within a function with the @provide_session
decorator.
Is there anything going on here that could be causing the problem?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
![https://user-images.githubusercontent.com/16011260/231660733-0d3eaaf3-283c-472f-abbf-216531cdaf77.png"](https://user-images.githubusercontent.com/16011260/231660733-0d3eaaf3-283c-472f-abbf-216531cdaf77.png"){kind=link}