Airflow Webserver slow to start up

[gdevanla]

Apache Airflow version:
2.0.0

Kubernetes version (if you are using kubernetes) (use kubectl version):

Environment:

• Cloud provider or hardware configuration:

• OS (e.g. from /etc/os-release): "18.04.1 LTS (Bionic Beaver)"

• Kernel (e.g. uname -a): 4.15.0-130-generic SLA bugfix #134-Ubuntu

• Install tools:

• Others:

What happened:

I am observing real slow start up time when starting the webserver (compared to startup time from previous versions). With one workers, than start up time is close to 2 minutes.

Some observations, as I look at the logs (attached)

1. Registering routes seems to take ~25 seconds
2. Adding security decorators seems to take ~12 seconds

Then, I see this message:

[2021-02-02 06:36:45,875] {security.py:398} DEBUG - Cleaning faulty perms
Running the Gunicorn Server with:
Workers: 1 sync
Host: 0.0.0.0:8080
Timeout: 120
Logfiles: - -
Access Logformat: 
=================================================================            
[2021-02-02 06:36:46,059] {cli_action_loggers.py:84} DEBUG - Calling callbacks: []
[2021-02-02 06:36:46,063] {settings.py:290} DEBUG - Disposing DB connection pool (PID 24448)
[2021-02-02 06:36:46,487] {settings.py:208} DEBUG - Setting up DB connection pool (PID 24684)
[2021-02-02 06:36:46,487] {settings.py:273} DEBUG - settings.prepare_engine_args(): Using pool settings. pool_size=5, max_overflow=10, pool_recycle=1800, pid=24684

3. After that, the Registering route routines kickin for the second time and the entire process repeats once more.

So, effectively, we are re-running all startup related process twice.

What you expected to happen:

Could be useful if we could speed this up. Helps in iterative development of plugins.

I think I may be missing some timeout value, which is causing the process to recycle in a minute.

How to reproduce it:

airflow_webserver -w 1

As minimally and precisely as possible. Keep in mind we do not have access to your cluster or dags.

If you are using kubernetes, please attempt to recreate the issue using minikube or kind.

Anything else we need to know:

The attached logs has more details on the summary I provided above.

airflow_web_non_debug.log

[potiuk]

@mik-laj -> that looks like registration of API routes and security decorators. It look that if takes > 2 minutes to start the whole process indeed seems to restar. I cannot see though why It's so slow. I think this might be caused by some network configuration executing some roundtrip network operation with every route adding ? This certainly looks like it and maybe we can somewhat prevent it from happening

[zachliu]

i noticed the same issue on airflow 2.0.0, and i have 4 worker processes for the webserver

# Number of workers to run the Gunicorn web server
workers = 4

[mik-laj]

Can you check how long it takes to display all routes?

time bash -c "AIRFLOW__LOGGING__LOGGING_LEVEL=debug FLASK_APP=airflow.www.app:create_app flask routes"

For me:

real	0m16.187s
user	0m8.826s
sys	0m0.973s

[zachliu]

where should i insert this line in my entrypoint.sh? i suppose right after

    exec airflow webserver

?

[mik-laj]

If you are using Docker, you can check it with this command.

time docker run -rm <IMAGE_NAME> bash -c "AIRFLOW__LOGGING__LOGGING_LEVEL=debug FLASK_APP=airflow.www.app:create_app flask routes"

[gdevanla]

This is what I get:

bash -c   8.49s user 1.89s system 10% cpu 1:41.12 total

[zachliu]

i had to do

time docker run --rm <IMAGE_NAME> bash -c "airflow db init && EXECUTOR=Sequential AIRFLOW__LOGGING__LOGGING_LEVEL=debug FLASK_APP=airflow.www.app:create_app flask routes"

i got

0.07s user 0.08s system 0% cpu 21.182 total

but this doesn't mimic our production environment which uses the CeleryExecutor

[i2gor87]

My output of command on airflow 2.0.1, docker-compose.yml from airflow docs:
My webserver isn't starting at all, constantly spamming [CRITICAL] WORKER TIMEOUT (pid:364)

Server stats:

CPU utilization ~19.8% (AWS monitor)
Memory consumption 2.17G/3.81G (htop)

time docker-compose run {CONTAINER_NAME} bash -c "AIRFLOW__LOGGING__LOGGING_LEVEL=debug FLASK_APP=airflow.www.app:create_app flask routes"

On new container(docker-compose run airflow-worker)

real    5m30.802s
user    0m1.193s
sys     0m0.259s

On existing container:

real    13m23.415s
user    0m1.095s
sys     0m0.217s