GraphQL (graphene) transactions are slow with newrelic from v6.6.0.162 and above

[trimailov]

Description

Upgrading anything above v6.6.0.162 will make our GraphQL endpoints slower by some margin.

From stable ~30ms to hovering between 50-100ms.

Also CPU and RAM utilization is also noticable - RAM use increased by ~20% from previous total and CPU use is additional ~5%. So for example if we used 50% RAM - we now use 60% and if we used 20% CPU - we now use 25% CPU.

I have tried to run these newrelic agent versions: v7.16.0.178, v7.14.0.177, v6.10.0.165, v6.6.0.162 - all impacted response times in same way.

I was upgrading from: v6.2.0.156 and settled at v6.4.4.161 which is latest version without graphql support (to my knowledge), but it is not impacting my applications performance.

Also - important to note that <= v6.4.4.161 reports graphql transactions as web transaction named as GraphQL endpoint view class (i.e. Django view class that serves GraphQL API), which is expected, though versions with GraphQL support (>v6.6.0.162) are reporting graphql transactions as graphene.types.resolver:dict_or_attr_resolver.

Expected Behavior

There shouldn't be noticable changes in our web servers response times and CPU/RAM utilization.

Troubleshooting or NR Diag results

Output from NR Diag. I think it's all OK, as .NET errors or Java warnings are not relevant for the project.

> ./nrdiag_x64 -c newrelic.ini

Check Results
-------------------------------------------------

Info     Base/Env/CollectEnvVars [Gathered Environment variables of current shell.]
Success  Base/Config/Collect
Success  Base/Config/Validate
Success  Base/Config/LicenseKey
Success  Base/Config/AppName
Success  Python/Config/Agent
Success  Base/Log/Copy
Info     Python/Env/Dependencies [Collected pip freeze. See pipFreeze.txt for more i...]
Info     Base/Containers/DetectDocker [Docker Daemon is Running]
Info     Base/Env/HostInfo [Collected host information]
Error    DotNetCore/Env/Versions
Success  Base/Config/ValidateLicenseKey
Info     Base/Config/RegionDetect [1 unique New Relic region(s) detected from config.]
Info     Python/Env/Version [3.9.2]
Success  Base/Collector/ConnectEU
Warning  Java/AppServer/WebSphere
Success  Base/Config/ValidateHSM
Success  Python/Requirements/Webframework

Steps to Reproduce

I will try to create minimal example application to be able to reproduce this, but it's a Django application with graphene-django used for implementing GraphQL API, with minimal djangorestframework endpoint to serve it.

Your Environment

Basic app package requirements (python 3.9.2):

graphene==2.1.8
graphene-django==2.13.0
graphql-core==2.3.2
graphql-relay==2.0.0
gunicorn==19.9.0
newrelic==7.16.0.178   # as said above behavior can be reproduce with anything from v6.6.0.162
Django==3.1.7  # I know it's old, but I was in process of upgrading packages, that's how I caught this problem
djangorestframework==3.12.1

Web app is served with gunicorn and started with newrelic-admin:

NEW_RELIC_ENVIRONMENT=$ENV NEW_RELIC_CONFIG_FILE=newrelic.ini newrelic-admin run-program gunicorn -c ./gunicorn.conf.py app.wsgi:application

To my understanding newrelic.ini is not configured beyond default, setting up API key and enabling environments for staging and production.

Additional context

Looking at newrelic's transaction details I notice that the mentioned graphene.types.resolver:dict_or_attr_resolver is called hundreds of times.

I am not sure if this is newrelic's bug or (more likely) misimplementation of our graphene application that breaks newrelic.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[Ak-x]

Hey @trimailov; is this still an issue? Have you been able to recreate a sharable environment to validate this?

[trimailov]

It's still an issue, though have no shareable environment at hand :(

[Ak-x]

@trimailov without a sharable environment this will be difficult for our team to debug. I will close this ticket until we have more data, additional users are experiencing the issue, or we have an environment our team can work with.

[tdg5]

I believe I am having this issue as well. I also don't have a sharable environment I can offer at this point, but I added new relic to a graphene application today and found that all graphql requests are 3-6x slower. An example request goes from taking about 2s without newrelic to 8-10s with new relic.

It seems like it is a problem even with a lot of the new relic agent disabled. Currently I disable all these things in my newrelic.ini and I still suffer a significant performance regression:

application_logging.enabled = false
attributes.enabled = false
browser_monitoring.auto_instrument = false
code_level_metrics.enabled = false
cross_application_tracer.enabled = false
custom_insights_events.enabled = false
distributed_tracing.enabled = false
error_collector.enabled = false
event_loop_visibility.enabled = false
span_events.enabled = false
strip_exception_messages.enabled = false
thread_profiler.enabled = false
transaction_events.enabled = false
transaction_tracer.explain_enabled = false
transaction_tracer.enabled = false

Is there more I could try disabling? If I set monitor_mode = false the problem goes away, but I can't make it go away otherwise.

[tdg5]

@Ak-x , may I request that this issue be reopened? Here's an example project where I've tried to reproduce the issue: https://github.com/tdg5/newrelic-python-agent-graphene-issue#results-with-new_relic_license_key-ouch

I was able to reliably achieve a slowdown >10x for the 99 percentile. I will try to simplify the example further as time allows.

Thanks to @Anton-Karpenko for putting together the basic application structure so I could try to reproduce the problem!

I spent a couple of hours looking for clues in one of the packages involved, but didn't find a smoking gun.

If I can offer any additional guidance or assistance, please let me know.

[rajanbharti]

I think, this is still an issue, we are using strawberry with fastapi, facing same problem. response time increased from ~50ms to ~300ms