[BUG]: DD_PROFILING_MEMORY_ENABLED=true slows down application significantly

[bmalehorn]

Tracer Version(s)

ddtrace 3.6.0

Python Version(s)

Python 3.10.6

Pip Version(s)

pip 22.3.1

Bug Report

Hello,

We've noticed a significant slowdown in one of our applications in production that seems to be related to memory size.

This application pulls in quite a lot of data, and stores it all in memory. Specifically it fetches about 1 million rows of a table, in batches of 10k at a time, and stores them as ORM objects in a big list. Additionally the slowdown increases over time, with the queries starting out fairly fast, but each query gets slower and slower over time.

I reproduced this in my local environment and ultimately made a 5x speedup by disabling the memory profiler via DD_PROFILING_MEMORY_ENABLED=false - see below for some evidence.

Discussed on the public Datadog Slack here: https://datadoghq.slack.com/archives/C0633E2KH16/p1746038872275079 and in a private message with @taegyunkim.

Org id: 550746 (Lumos)

Reproduction Code

I have a reproduction in my local environment. With memory profiling turned off:

env | grep DD_PROFILING
DD_PROFILING_MEMORY_ENABLED=false
DD_PROFILING_ENABLE_CODE_PROVENANCE=true
DD_PROFILING_ENABLED=true
DD_PROFILING_STACK_V2_ENABLED=true
DD_PROFILING_MAX_FRAMES=256

cd /workflows && ENVIRONMENT=LOCAL /usr/local/bin/pip show ddtrace
Name: ddtrace
Version: 3.6.0

I log how long each batch takes, and each batch runs fairly quickly:

...
elapsed=0.426
elapsed=0.197
elapsed=0.224
...

total time to load 1009015 rows: 108 seconds

When I run with memory profiling enabled:

env | grep DD_PROFILING
DD_PROFILING_MEMORY_ENABLED=true
DD_PROFILING_ENABLE_CODE_PROVENANCE=true
DD_PROFILING_ENABLED=true
DD_PROFILING_STACK_V2_ENABLED=true
DD_PROFILING_MAX_FRAMES=256

cd /workflows && ENVIRONMENT=LOCAL /usr/local/bin/pip show ddtrace
Name: ddtrace
Version: 3.6.0

Running the job, it starts out fast:

21:44:56.047: elapsed=0.256
21:44:56.368: elapsed=0.134
21:44:56.725: elapsed=0.175
...

but after running for several minutes, it's quite slow, and getting slower over time:

21:48:05.580: elapsed=4.788
21:48:14.728: elapsed=5.256
21:48:23.544: elapsed=4.784

total time to load 1009015 rows: 507 seconds

Error Logs

Here are some relevant links for myself & others:

• datadog: prod profile
• datadog: my run with DD_PROFILING_MEMORY_ENABLED=false individual profile
• datadog: my run with DD_PROFILING_MEMORY_ENABLED=true individual profile
• [personal] my run with DD_PROFILING_MEMORY_ENABLED=false: http://localhost:8082/runs/8206e632-db85-463a-8662-34e464fa1198
• [personal] my run with DD_PROFILING_MEMORY_ENABLED=true: http://localhost:8082/runs/cf9638f7-0c02-4591-a636-c19fb53e91f0
• [personal] my branch upgrading to 3.6.0: brian/profiler-perf-all-ddtrace-3.6.0

Libraries in Use

Relevant libraries used in this reproduction:

SQLAlchemy==1.3.16
mysqlclient==2.2.7
ddtrace==3.6.0

Operating System

Linux 8ea13d816b46 6.10.14-linuxkit #1 SMP Fri Nov 29 17:22:03 UTC 2024 aarch64 GNU/Linux

[taegyunkim]

@bmalehorn thanks again for trying different configurations with the latest ddtrace version. It helped us to narrow down the root cause. The heap allocation profiler keeps a list of samples it has seen, and it does O(samples) scan for every free. Probably this is why it's fast for first few batches and it's much slower on the later ones. We will prioritize fixing this issue.

[bmalehorn]

No problem!

To confirm more and build confidence to re-enable once fixed, I profiled the C stack frames by running a command like this:

perf record -p <pid> -F 100 -g -- sleep 10

With memory profiling turned on:

I see 77% of time was spent in memalloc_heap_untrack. That definitely sounds like the bug you're describing, and the proposed fix #13317 changes this exact function to use a hash map instead. Great!

And with memory profiling turned off:

memalloc_heap_untrack does not appear in the stack traces.

Versions used in this test:

Name: ddtrace
Version: 2.11.8

[nsrip-dd]

Thanks for getting all this data @bmalehorn! Would you be willing to try out the PR with your setup? Here are a few links to get the wheels from CI, depending on which os/architecture you're running on:

• https://github.com/DataDog/dd-trace-py/actions/runs/14796031101/artifacts/3050804160 - 3.10, manylinux, x86_64
• https://github.com/DataDog/dd-trace-py/actions/runs/14796031101/artifacts/3050801850 - 3.10, manylinux, aarch64
• https://github.com/DataDog/dd-trace-py/actions/runs/14796031101/artifacts/3050815073 - 3.10, musllinux, x86_64
• https://github.com/DataDog/dd-trace-py/actions/runs/14796031101/artifacts/3050805536 - 3.10, musllinux, aarch64
• https://github.com/DataDog/dd-trace-py/actions/runs/14796031101/artifacts/3050796866 - 3.10, macos, arm64
• https://github.com/DataDog/dd-trace-py/actions/runs/14796031101/artifacts/3050825449 - 3.10, macos, x86_64

The performance looks good for my local setup, but it'd be great to have confirmation from your setup as well.

[bmalehorn]

Hey @nsrip-dd , thanks for the links.

I tried testing this out:

RUN poetry install
+RUN poetry run pip install /common/ddtrace-3.7.0.dev47+g5eaa19d9c-cp310-cp310-manylinux_2_17_aarch64.manylinux2014_aarch64.whl

root@ce1d6dfda1bb:/opt/dagster/dagster_home# cd /workflows && ENVIRONMENT=LOCAL /usr/local/bin/pip show ddtrace
Name: ddtrace
Version: 3.7.0.dev47+g5eaa19d9c

root@ce1d6dfda1bb:/workflows# env | grep DD_PROF
DD_PROFILING_MEMORY_ENABLED=true
DD_PROFILING_ENABLE_CODE_PROVENANCE=true
DD_PROFILING_ENABLED=true
DD_PROFILING_STACK_V2_ENABLED=true
DD_PROFILING_MAX_FRAMES=256

in the repro:

print("{ddtrace._version.__version__=}")

ddtrace._version.__version__='3.7.0.dev47+g5eaa19d9c'

It does run faster, but now profiles do not show any heap live size information:
https://app.datadoghq.com/profiling/profile/AZaShXG9AAAetiaF3f4MBgAA?query=env:brians-macbook-pro.local&agg_m=count&agg_m_source=base&agg_t=count&event=AwAAAZaShW-fBtX98QAAABhBWmFTaFhHOUFBQWV0aWFGM2Y0TUJnQUEAAAAkMDE5NjkyODUtYTJiOS00NGQ3LTk3YjktNDA1NDIwOTJhNTk4AAAA-g&fromUser=true&my_code=disabled&viz=stream&from_ts=1746211324343&to_ts=1746214924343&live=true

is that expected?

I also tried running with Profiler(_memory_collector_enabled=True) to force memory profiling on, but that didn't have any effect either.

I also checked profiles I got from running on 3.6.0 today. They did contain heap live size:

https://app.datadoghq.com/profiling/profile/AZaSfEkjAAAC958wpR-zsAAA?query=env:brians-macbook-pro.local&agg_m=count&agg_m_source=base&agg_t=count&event=AwAAAZaSfEepMoZ4DwAAABhBWmFTZkVrakFBQUM5NTh3cFItenNBQUEAAAAkMDE5NjkyODItNmJkMy00NzM2LThhZGEtMzc1OGVhNDFiZWY0AAA1ag&fromUser=true&my_code=disabled&viz=stream&from_ts=1746211324343&to_ts=1746214924343&live=true

[nsrip-dd]

@bmalehorn Thanks a bunch for trying it out! That is definitely not expected. I suspect that you might be running into issues linking the C++ library at run time (the memalloc import currently fails silently). To confirm, could try import ddtrace.profiling.collector._memalloc? I'm betting that'll give you some errors. We're working on ironing out the issues with the build. The way I've currently implemented this is a bit unusual, mixing C and C++. I'll try to have something ready early next week. Sorry for the trouble!

Edit: I've tried out using a C hash table instead to get rid of the C++ dependency, so if that is the issue you ran into, and you're up for trying another version, this build should work better: wheels-cp310-manylinux_aarch64.

[bmalehorn]

@nsrip-dd Ah yep, it was an import error:

>>> import ddtrace
>>> import ddtrace.profiling.collector._memalloc
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/local/lib/python3.10/site-packages/ddtrace/internal/module.py", line 239, in _create_module
    return self.loader.create_module(spec)
ImportError: /usr/local/lib/python3.10/site-packages/ddtrace/profiling/collector/_memalloc.cpython-310-aarch64-linux-gnu.so: undefined symbol: __gxx_personality_v0

I tried installing the new wheel:

ENVIRONMENT=LOCAL /usr/local/bin/poetry run pip install /ddtrace-3.8.0.dev10+gcd8620f72-cp310-cp310-manylinux_2_17_aarch64.manylinux2014_aarch64.whl
root@ce1d6dfda1bb:/workflows# cd /workflows && ENVIRONMENT=LOCAL /usr/local/bin/poetry run python
Skipping virtualenv creation, as specified in config file.
Python 3.10.6 (main, Aug 23 2022, 09:47:38) [GCC 8.3.0] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import ddtrace
>>> import ddtrace._version
>>> ddtrace._version.__version__
'3.8.0.dev10+gcd8620f72'
>>> import ddtrace.profiling.collector._memalloc
>>> 

Looks like the import is OK.

Running the reproduction, now we do see memory profiles:
https://app.datadoghq.com/profiling/profile/AZaSv4wNAABYWlElQ6jibgAA?query=env:brians-macbook-pro.local&agg_m=count&agg_m_source=base&agg_t=count&event=AwAAAZaSv4lt4XCGIAAAABhBWmFTdjR3TkFBQllXbEVsUTZqaWJnQUEAAAAkMDE5NjkyYmYtYTBlYy00ZjIwLWJhNWItY2MwNjQwNzRlNWU1AAAAcw&fromUser=false&my_code=disabled&profile_type=heap-live-size&viz=stream&from_ts=1746215185576&to_ts=1746218785576&live=true

And it did indeed run faster!

elapsed=0.127
elapsed=0.221
elapsed=0.137
...

total time to load 1009015 rows: 92 seconds

I captured a profile during that time:

Only 0.7% of time was spent in memalloc_heap_untrack, down from 77% I saw earlier. So it definitely seems fixed! The C hash map is more than sufficient to fix this issue, but if you want to go out of your way to use a faster C++ hash map I'm not going to complain.

I'll try to have something ready early next week. Sorry for the trouble!

No rush on our end, we probably are not going to upgrade ddtrace immediately. We're mostly just happy to have identified the issue & have a fix in progress that we'll pick up when we upgrade ddtrace.

[bmalehorn]

On a related note about the upgrades, will this bug fix be ported back to ddtrace 2?

[nsrip-dd]

On a related note about the upgrades, will this bug fix be ported back to ddtrace 2?

Yeah, we'll backport this to 2.21