Log files are still being cached causing ever-growing memory usage when scheduler is running

[zachliu]

Apache Airflow version

2.4.1

What happened

My Airflow scheduler memory usage started to grow after I turned on the dag_processor_manager log by doing

export CONFIG_PROCESSOR_MANAGER_LOGGER=True

see the red arrow below

By looking closely at the memory usage as mentioned in #16737 (comment), I discovered that it was the cache memory that's keep growing:

Then I turned off the dag_processor_manager log, memory usage returned to normal (not growing anymore, steady at ~400 MB)

This issue is similar to #14924 and #16737. This time the culprit is the rotating logs under ~/logs/dag_processor_manager/dag_processor_manager.log*.

What you think should happen instead

Cache memory shouldn't keep growing like this

How to reproduce

Turn on the dag_processor_manager log by doing

export CONFIG_PROCESSOR_MANAGER_LOGGER=True

in the entrypoint.sh and monitor the scheduler memory usage

Operating System

Debian GNU/Linux 10 (buster)

Versions of Apache Airflow Providers

No response

Deployment

Other Docker-based deployment

Deployment details

k8s

Anything else

I'm not sure why the previous fix #18054 has stopped working 🤔

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

[potiuk]

I've addded a PR that should address it in #27223 @zachliu - would it be possible that you test it in your installation?

[zachliu]

I've addded a PR that should address it in #27223 @zachliu - would it be possible that you test it in your installation?

sure thing 👍

[zachliu]

@potiuk the cache memory is still growing 😿

[potiuk]

Maybe The rotating file handler has another place where it copies files and leaves them behind. Not the end of the world (as you know this is no-harm-at-all and perfecrly normal to happen)/

Maybe i will take a look soon (or maybe you can @zahchliu - you could see how I've done that and you could potentially iterate on it and verify it in your test system and make a PR after you test it ? How about that?

Also there are ways you can check if this might be the cause. Just delete the rotated files and see if that causes drrop in cache memory used.

[potiuk]

Would be great contribution back :) ?

[zachliu]

yeah, the root cause of this might be somewhere else. here are the facts:

• setting CONFIG_PROCESSOR_MANAGER_LOGGER=True does make the cache increase
• deleting files under ~/logs/dag_processor_manager has no effect on cache memory usage, also there are cache files i cannot delete
  

[potiuk]

You can always drop the whole cache to verify what causes it:

https://linuxhint.com/clear_cache_linux/

Also you can do some trial/error to see which files are in the cache as explained in this answer:
https://serverfault.com/questions/278454/is-it-possible-to-list-the-files-that-are-cached

Seems this is not easy to get list of files which contribute to cache, but if you have some guesses you might try to find out by using fntools.

[zachliu]

the 2 .nfs* files at ~/logs/dag_processor_manager do add up to my current cache memory usage 🤔

.nfsbf1544f7b7af29ea00000002 has been written to an actual file. but it was not removed properly
.nfsd261bc9d96a5d91200000001 keeps growing

[Taragolis]

.nfs* files should be related to NFS not to Airflow.

[potiuk]

Very much so. This is the choice of using NFS to store logs :)

[zachliu]

wait i'm confused, so it is NFS design choice not to remove the cache file after it's written to an actual file?

[Taragolis]

wait i'm confused, so it is NFS design choice not to remove the cache file after it's written to an actual file?

https://nfs.sourceforge.net/#faq_d2

[potiuk]

silly rename 🤣

[potiuk]

Nothing we can do about it :). But I am not sure if those are the culprits - accoding to the descriptions those should be removed when airflow stops keeping the file unless client crashes

[Taragolis]

I also mount default logs directory to NFS (AWS EFS) so I could only suggest my personal configuration which use for a long time

1. Change default dag processor manager log location outside of NFS, e.g. AIRFLOW__LOGGING__DAG_PROCESSOR_MANAGER_LOG_LOCATION = "/tmp/airflow/logs/dag_processor_manager/dag_processor_manager.log"
2. Increase print stats interval AIRFLOW__SCHEDULER__PRINT_STATS_INTERVAL = 300 which could reduce final size of file

[potiuk]

3. Write a custom handler to rotate the logs outside.
4. Use externa service for logging (CloudWatch etc.) for storing them remotely.

[potiuk]

5. Stop worrying about it. The fact that Unix cache grows has only one drawback - it will show up when you choose to in your monitoring service. You should monitor other parameters - it's perfectly OK that cache grows up until all available memory - it has no negative consequences

[zachliu]

i'm also using AWS EFS 🤝

i think i'll try 1 (2 seems redundant if we're moving it out of NFS), they seem to be the easiest except 5, which involves educating all current/future maintainers to understand memory nuances 😅

[potiuk]

BTW. I've heard VERY bad things about EFS when EFS is used to share DAGs. It has profound impact on stability and performance of Airlfow if you have big number of DAGs unless you pay big bucks for IOPS. I've heard that from many people.

This is the moment when I usually STRONGLY recommend GitSync instead: https://medium.com/apache-airflow/shared-volumes-in-airflow-the-good-the-bad-and-the-ugly-22e9f681afca

[potiuk]

5, which involves educating all current/future maintainers to understand memory nuances sweat_smile

As counterintuitive as it is, I know what you are talking about :)

[Taragolis]

BTW. I've heard VERY bad things about EFS when EFS is used to share DAGs. It has profound impact on stability and performance of Airlfow if you have big number of DAGs unless you pay big bucks for IOPS. I've heard that from many people.
This is the moment when I usually STRONGLY recommend GitSync instead: https://medium.com/apache-airflow/shared-volumes-in-airflow-the-good-the-bad-and-the-ugly-22e9f681afca

It's always it depends on configuration and monitoring. I personally have this issue might be in Airflow 2.1.x and I do not know is it actually related to Airflow itself or some other stuff. Work with EFS definitely take more effort rather than GitSync.

Just for someone who might found this thread in the future with EFS performance degradation might help:

Disable save python bytecodes inside of NFS (AWS EFS) mount

• Mount as Read-Only
• Disable Python bytecode by set PYTHONDONTWRITEBYTECODE=x
• Or set location for bytecodes by set PYTHONPYCACHEPREFIX for example to /tmp/pycaches

Throughput in mode Bursting in first looks like miracle but when all Bursting Capacity go to zero it could turn into your life into the hell. Each newly created EFS share has about 2.1 TB BurstingCreditBalance.

What could be done here:

• Switch to Provisional Throughput mode permanently which might cost a lot, something like 6 USD per 1 MiB/sec without VAT, so 100 MiB/Sec would cost more than 600 USD per month.
• Switch to Provisional Throughput mode only when BurstingCreditBalance less than some amount, like 0.5 TB, and switch back when BurstingCreditBalance exceed limit 2.1 TB. Unfortunately there is no autoscaling so it would be manual or combination of CloudWatch Alerting + AWS Lambda.

[potiuk]

This is very close to what I've heard! Good one @Taragolis! And yeah PYTHONDONTWRITEBYTECODE is also my typical recommendation.

[zachliu]

i moved the dag_processor_manager logs from /user/local/airflow/logs/ (NFS) to /tmp/airflow/logs/ (local), but the cache memory still keeps growing 😿

so it is still using cache somewhere but not the .nfs*** silly-rename cache files 🤔

[potiuk]

So I guess the quest shoudl continue :)/ But let me repeat again - if you have anything that creates files continuously and those files are not deleted and there is no advice from the kernel to not use cache - they will increase the cache memory used. You will likely never get it to 0 growth over time. Likely just ssh to your system and saving your history when you type in a command will increase cache used. And this is normal. So you are likely chasing a red herring.

[zachliu]

worse than a red herring, this is a mirage 😆
can't change the kernel's behavior, i'll just change meself:

LOGGING_CONFIG["handlers"]["processor_manager"].update(
    {
        'maxBytes': 10485760,  # 10M
        "backupCount": 3,
    }
)

this makes the cache memory usage cap at 40~50Mb