Airflow triggerer memory is increasing continously

[deepak4babu]

Apache Airflow version

Other Airflow 2 version (please specify below)

If "Other Airflow 2 version" selected, which one?

2.8.3

What happened?

We started to use deferrable operators and sensors from 2 weeks back. As part of it, we started using triggerer. The triggerer container memory is increasing steadily, even when no triggers are running.

What you think should happen instead?

Memory consumption of idle triggerer should be less and does not increase

How to reproduce

Deploy triggerer in kubernetes with airflow version 2.8.3. Monitor for 24hrs

Operating System

kubernetes

Versions of Apache Airflow Providers

apache-airflow-providers-celery==3.6.1
apache-airflow-providers-common-io==1.4.0
apache-airflow-providers-common-sql==1.11.1
apache-airflow-providers-ftp==3.7.0
apache-airflow-providers-http==4.10.0
apache-airflow-providers-imap==3.5.0
apache-airflow-providers-smtp==1.8.0
apache-airflow-providers-sqlite==3.7.1

Deployment

Other

Deployment details

Airflow version: 2.8.3
Python version: 3.9.x
Database: Postgres 13

Kubernetes details:
Azure kubernetes service
Kustomize Version: v5.0.4-0.20230601165947-6ce0bf390ce3
k8s Server Version: v1.29.4

Dags are packaged as python packages and installed in the airflow base image. Airflow triggerer is deployed using our custom helm chart, which is just a modified version of official one.

Anything else?

No response

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

[gopidesupavan]

@deepak4babu there are some optimizations made around this area, it will be available in coming airflow release 2.10.3. FYI #40487.

[boris-tumbev]

@deepak4babu there are some optimizations made around this area, it will be available in coming airflow release 2.10.3. FYI #40487.

It does not fix the problem unfortunately, in our setup the memory still get higher and higher and the triggerer eventually restarts

[potiuk]

@deepak4babu there are some optimizations made around this area, it will be available in coming airflow release 2.10.3. FYI #40487.

It does not fix the problem unfortunately, in our setup the memory still get higher and higher and the triggerer eventually restarts

Can you do some memory check using https://github.com/bloomberg/memray for example and see what causes the memory leak?

[arkadiuszbach]

Had the same issue with Triggerer and Scheduler on AKS and apache/airflow:2.10.2-python3.9:

• At first I thought it is something with Log Groomer as I didn't use it before, but even though it was disabled, memory usage was still growing and it was growing on main container not on the groomer itself.

• So then I thought maybe memory leak is within airflow processes runing in the container. I saved memory usage by all processes within container with ps aux, waited for two days and checked its output again - it didn't change

• Then I searched the internet for how is it possible that memory usage for the container is growing even though for the processes it is not, it was clear that something is leaking in the kernel. I found that I can check /sys/fs/cgroup/memory.stat for memory usage statistics within container and I found that slab memory is growing.

• Checked internet how I can find what is leaking in the slabs, found slabtop and /proc/slabinfo but when tried using it I got 'Permisison denied' error, so I started the container as root user instead of airflow and when I did the memory leak was gone

• When it was resolved when running as root i thought maybe that is because on root all linux capabilities are available and it manages memory differently, I tried enabling all capabilities when running with airflow user but it didnt fix the issue.

• So to figure out what exactly is leaking I enabled sudo within the container (to still run as airflow and be able to sudo su):

   USER root
   RUN usermod -aG sudo airflow
   RUN echo "airflow:airflow" | chpasswd
   USER airflow
  

• Then wrote bash script to take dumps of /proc/slabinfo, didn't wait for long, but seemed that dentry memory usage was growing, checked the internet, chatgpt and it said that it may be growing when there are a lot of directory operations and files operations with dynamic names. Somehow I stumbled into strace which can display system calls specific process is making, i.e. open file, create file, directories system calls, memory allocation, etc. So I started checking Airflow processes with strace ( strace -T -e trace=desc,open,mkdir,rmdir,unlink,rename --decode-fds=all -p {process_id}) to verify if they are making system calls related with files and directories - they didn't, except liveness probe which was making a lot of file related system calls as it is started over and over again, so I disabled it in helm chart and memory leak was gone:

  livenessProbe:
    command:
      - "/bin/true"
  

• I went through strace output a little bit for liveness probe and messages like below got my attention:

    Line 19609: mkdir("/opt/airflow/config/__pycache__", 0777) = -1 EACCES (Permission denied) <0.000028>
    Line 22139: openat(AT_FDCWD</opt/airflow>, "/usr/local/lib/python3.9/concurrent/futures/__pycache__/process.cpython-39.pyc.140482203662256", O_WRONLY|O_CREAT|O_EXCL|O_CLOEXEC, 0644) = -1 EACCES (Permission denied) <0.000035>
    Line 22155: openat(AT_FDCWD</opt/airflow>, "/usr/local/lib/python3.9/multiprocessing/__pycache__/queues.cpython-39.pyc.140482203662768", O_WRONLY|O_CREAT|O_EXCL|O_CLOEXEC, 0644) = -1 EACCES (Permission denied) <0.000033>
    Line 22622: openat(AT_FDCWD</opt/airflow>, "/usr/local/lib/python3.9/__pycache__/sched.cpython-39.pyc.140482203590416", O_WRONLY|O_CREAT|O_EXCL|O_CLOEXEC, 0644) = -1 EACCES (Permission denied) <0.000035>
  

  There are only few entries like this, but maybe this somehow is causing the leak as airflow user does not have access, don't know, files names seems dynamic.

  Got an idea to do chmod -R 777 on /opt/airflow/config and /usr/local/lib/python3.9 to verify, but didn't want to spend more time on this as seems like python leaves something behind when started over and over again and the liveness probe in python always felt too heavy to me(i can see increase in CPU by 20% of one vcore and memory usage by 100mb-200mb when it starts, it takes 4-5 secs to execute), so I rewrote it to golang instead with chatgpt.

[potiuk]

HEy @arkadiuszbach -> thanks A LOT for such a detailed investigation. This is a great find and I think that one is fully actionable on our side - we might want to rethink on how our liveness probe is implemented and recommended in our helm chart. You are a hero!

[rurouni-najeeb]

Hi 👋
I was wondering if this issue is still open or has been resolved in version 3.x?

[potiuk]

Hi 👋 I was wondering if this issue is still open or has been resolved in version 3.x?

We did remove some memory issues in 3.1.1 and some are still to be fixed in 3.1.2 (for example #57334 ) - so ... maybe,... I think likely answer can be given by those who upgrade and observed it before. Highly recomended @rurouni-najeeb

[arkadiuszbach]

I gave it another shot and i think was able to figure this out, was checking on apache/airflow:3.1.3-python3.12

This is happening: https://lwn.net/Articles/814535/:

• airflow user does not have permission to write into __pycache__ subdirectories under: /usr/local/lib/python3.xx/

• for most of the libararies there are already precompiled .pyc files, but if there isn't then when importing/starting, python will try creating such

  • first it checks if compiled .pyc file exists. it tries to read it:
    openat(AT_FDCWD</opt/airflow>, "/usr/local/lib/python3.12/encodings/__pycache__/__init__.cpython-312.pyc", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000152>
  • if it didnt exists then creates the .pyc file with number suffix after .pyc, some intermediate compiled file (This creates negative dentry):
    openat(AT_FDCWD</opt/airflow>, "/usr/local/lib/python3.12/encodings/__pycache__/__init__.cpython-312.pyc.136405097451568", O_WRONLY|O_CREAT|O_EXCL|O_CLOEXEC, 0644) = 3</usr/local/lib/python3.12/encodings/__pycache__/__init__.cpython-312.pyc.136405097451568> <0.004813>
  • then it renames the file (removes the number suffix), probably so that next runs of other python processes won't have to compile the same file again when importing

    newfstatat(3</usr/local/lib/python3.12/encodings/__pycache__/__init__.cpython-312.pyc.136405097451568>, "", {st_mode=S_IFREG|0644, st_size=0, ...}, AT_EMPTY_PATH) = 0 <0.000136>
    write(3</usr/local/lib/python3.12/encodings/__pycache__/__init__.cpython-312.pyc.136405097451568>, "\313\r\r\n\0\0\0\0\277\306Hh\374\26\0\0\343\0\0\0\0\0\0\0\0\0\0\0\0\6\0\0"..., 5781) = 5781 <0.000161>
    close(3</usr/local/lib/python3.12/encodings/__pycache__/__init__.cpython-312.pyc.136405097451568>) = 0 <0.000091>
    rename("/usr/local/lib/python3.12/encodings/__pycache__/__init__.cpython-312.pyc.136405097451568", "/usr/local/lib/python3.12/encodings/__pycache__/__init__.cpython-312.pyc") = 0 <0.000239>
    

    __init__.cpython-312.pyc.136405097451568 was renamed to __init__.cpython-312.pyc

• airflow user is not able to create the file, each time healthprobe is triggered python generates different intermediate name for the .pyc file, each gets its entry in the Dentries, hence the slow memory increase

Possible fixes:

• disable precompilation entirely via https://docs.python.org/3/using/cmdline.html#envvar-PYTHONDONTWRITEBYTECODE - but the probe is already heavy, so doesn't seem like a good idea
• precompile the files within Docker image: sudo python3 -m compileall /usr/local/lib/python3.12 - maybe it would improve performance a bit as scheduler is spawning python processes, on my computer probe executes faster after compileall:

  #before
  real    0m3.632s
  user    0m3.201s
  sys     0m0.421s
  
  #after:
  real    0m2.855s
  user    0m2.438s
  sys     0m0.405s
  

• give airflow user write permission to all of the pycache directories under /usr/local/lib/python3.12

The commands i used to figure this out:

• cat /sys/fs/cgroup/memory.stat | grep slab - container slab memory usage (dentry is part of slab)
• cat /proc/sys/fs/dentry-state - https://www.kernel.org/doc/html/v6.6/admin-guide/sysctl/fs.html#dentry-state, used to track negative dentries count
• strace -T -e trace=desc,open,mkdir,rmdir,unlink,rename --decode-fds=all python - display file operations by command, search for dynamic file names
• trace dentries add/kill requests via bpftrace

    # required by bpftrace 
    sudo mkdir -p /sys/kernel/tracing
    sudo mount -t tracefs nodev /sys/kernel/tracing
    sudo mkdir -p /sys/kernel/debug
    sudo mount -t debugfs nodev /sys/kernel/debug
   
    sudo bpftrace -e '
    #define TARGET_COMM "python" 
    kprobe:d_alloc
    /(comm == TARGET_COMM)/
    {
        $dentry = (struct dentry *)arg0;
        $parent_name = str($dentry->d_parent->d_name.name);
        $parent_parent_name = str($dentry->d_parent->d_parent->d_name.name);
        @add_process[comm] = count();
        printf("ADD | PARENT: %s/%s | FILE: %s | Negative?: %p | Dentry Addr: %p | Caller: %s(%d)\n",
               $parent_parent_name,
               $parent_name,
               str($dentry->d_name.name),
               $dentry->d_inode,
               arg0,
               comm,
               pid);
        
    }
    
    kprobe:__dentry_kill
    /(comm == TARGET_COMM)/
    {
        $main = (struct dentry *)arg0;
        @delete_process[comm] = count();
        printf("KILL %s; negative?: %p; a: %p; caller: %s(%d)\n",
               str($main->d_name.name), $main->d_inode, arg0, comm, pid);
    
    }
    '
  

To verify:

• log into Airflow scheduler container
• make sure scheduler is the only airflow container that is running and without any probes
• run cat /proc/sys/fs/dentry-state to check negative dentry count
• run airflow jobs check --job-type SchedulerJob --local
• again check /proc/sys/fs/dentry-state, dentry count is increased by around 400
• now run PYTHONDONTWRITEBYTECODE=1 airflow jobs check --job-type SchedulerJob --local
• its only increased by 1, the last negative dentry is due to tempfile.gettempdir as it runs for each airflow command
  • tempfile.gettempdir is checking all candidate temp directories via os.open with random file name (hence the negative dentry), first time it is triggered, see: https://github.com/python/cpython/blob/a183a11db8bc2520c52814635de2df118d2d7e8c/Lib/tempfile.py#L183
  • to prevent this tempfile.tempdir should be set as soon as possible before below runs:

    • airflow/airflow-core/src/airflow/utils/db.py

      Line 569 in 1c98f57

      host=os.path.join(gettempdir(), "sqlite_default.db"),

    • airflow/airflow-core/src/airflow/dag_processing/bundles/base.py

      Line 51 in 1c98f57

      return Path(tempfile.gettempdir(), "airflow", "dag_bundles")

    • https://github.com/uqfoundation/dill/blob/d948ecd748772f2812361982ec1496da0cd47b53/dill/session.py#L25

[potiuk]

WHOA... What a deep dive... I will take a look shortly. That needs a focused deep-dive :). cc: @ashb ... Another interesting case for deep engineering dive.

[potiuk]

I wonder how it happens that we do not have .pyc files in there. I wonder if the new way we are building docker images, will be a different. Docker images of ours as of recently are not using the python images, but we compile and install Python on our own. Maybe we can check if the new image has all .pyc files @arkadiuszbach ?

It should be possible to build generally even older python versions using the latest Dockerfile - > https://airflow.apache.org/docs/docker-stack/build.html#customizing-the-image -> maybe you can try this one :) ?