Profiles will not work with a traces_sampler instead of traces_sample_rate

How do you use Sentry?

Sentry Saas (sentry.io)

Version

1.12.1

Steps to Reproduce

Pass a TracesSampler instead of setting traces_sample_rate
Set _experiments['profiles_sample_rate'] to 1.0

Expected Result

Every request with a trace also has a corresponding profile

Actual Result

No profiles are being recorded

P.S. From glancing at the code it doesn't look like there is a hard dependency on the more "dumb" traces_sample_rate over a TracesSampler. It's just that init checks for traces_sample_rate instead of doing the more thorough check of has_tracing_enabled which will check either option.

As a workaround I seem to be able to just pass a dummy fixed sampling rate, since the TracesSampler always takes priority.

P.P.S. Looks like the workaround might not actually work, since I'm still seeing no profiles for traced transactions. Unless they take a while to process. But I will try some alternative sampling methods for the profiler before giving up.

As a side note: I am using gevent which has caused issues with the default HTTPTransport in the past, so I'm currently using a manually patched HTTPTransport that does work (It's possible that this workaround is no longer necessary, but seeing as traces and exceptions are still being sent to the API just fine I'm leaving it as it is for now)

It's possible the workaround does not work for me due to gevent, but seeing as the code sentry's profiler was based off was originally written to be used with gevent I hope that's not the case.

I didn't manage to make the workaround work using any of the timing methods. Some debug logging statements (like with tracing) would be helpful to know whether or not profiling has been attempted at all.

Also on a more general note: Have you considered integrating with an existing profiler that is both more feature complete and imposes less of a performance overhead? I specifically have scalene in mind, which can also do memory debugging and can measure how much time is spent in native code as opposed to the Python interpreter (e.g. for C extensions) and will work with multiprocessing (i.e. most of the profiling work could then run on a separate CPU thread, without affecting the main application).

It might be a little bit more difficult to achieve though, seeing as scalene has to hook into the application very early on, before anything else gets loaded to achieve its low overhead. But making the profiler as accurate and feature complete as possible should be a win for everybody.

@Daverball

@Daverball profiling is currently only on for WSGI, ASGI support has an open pull request. What framework/server are you using?

@sl0thentr0py

@sl0thentr0py I'm using my own framework (unfortunately I currently cannot share the source code), but it is WSGI and using the SentryWsgiMidleware along with a couple of custom hooks to extract information from the request and any SQL queries.

@Daverball

As a side note: I am using gevent which has caused issues with the default HTTPTransport in the past, so I'm currently using a manually patched HTTPTransport that does work (It's possible that this workaround is no longer necessary, but seeing as traces and exceptions are still being sent to the API just fine I'm leaving it as it is for now)

It's possible the workaround does not work for me due to gevent, but seeing as the code sentry's profiler was based off was originally written to be used with gevent I hope that's not the case.

@Daverball There are some gevent specific changes that need to be ported for the profiler to collect samples correctly that is being looked into but the profile should still be sent to sentry. Are you not seeing any profiles being sent at all? You can confirm this by enabling debug mode and looking for a debug log like

 [sentry] DEBUG: Sending envelope [envelope with 2 items (profile, transaction)] project:XXX host:oXXX.ingest.sentry.io

If there are envelopes being sent with 2 items and one of them being a profile, it is correctly being sent to Sentry. After that, you should check the stats page from the side bar in Sentry and look at the profiles category. It's possible that the profiles you're sending are being dropped, potentially due to them containing only a single sample. For context, if a profile being sent contains only a single sample (taken at ~10ms intervals), it will be rejected.

I didn't manage to make the workaround work using any of the timing methods. Some debug logging statements (like with tracing) would be helpful to know whether or not profiling has been attempted at all.

Yes, this is something that will be added to help with debugging.

Also on a more general note: Have you considered integrating with an existing profiler that is both more feature complete and imposes less of a performance overhead? I specifically have scalene in mind, which can also do memory debugging and can measure how much time is spent in native code as opposed to the Python interpreter (e.g. for C extensions) and will work with multiprocessing (i.e. most of the profiling work could then run on a separate CPU thread, without affecting the main application).

It might be a little bit more difficult to achieve though, seeing as scalene has to hook into the application very early on, before anything else gets loaded to achieve its low overhead. But making the profiler as accurate and feature complete as possible should be a win for everybody.

We have looked into existing profilers but many of them are not very suitable for production profiling as they induce a rather large overhead. Scalene seems to use a similar approach we use here. This current implementation of the profiler has deviated quite significantly from what we based it on and looking at Scalene, it seems that they are actually similar in the way CPU profiling is done (I'll need to look at it in more detail to see how they differ). Our implementation is also tuned to better suit the way Sentry process profiles server side so we likely will not be integrating existing profilers directly into the SDK but in terms of overhead, we are aiming for ~5%-10% in most cases.

@Zylphrex

It's possible that the profiles you're sending are being dropped, potentially due to them containing only a single sample. For context, if a profile being sent contains only a single sample (taken at ~10ms intervals), it will be rejected.
@Zylphrex That sounds like that's probably why then, because I was testing on a view that takes <20ms. So even if the samples were collected correctly, there would only be one sample. I don't think I was seeing envelopes with 2 items though, but I will try it again when I find the time (probably this weekend at the earliest).

10ms as a sampling interval seems a bit high. I was expecting something in the neighbourhood of 1-2ms, but I suppose part of the theory is that aggregating a bunch of profiles with a low sampling rate given enough requests will eventually yield a profile that is just as detailed and accurate as one taken at a higher sampling rate, although I'm not fully convinced that still is true if you go below a certain sampling rate since the likelihood of missing certain parts of the code completely increases the larger the gap between samples is, although in most cases those parts probably wouldn't contribute to the total runtime in any significant way anyways. But I will have to play around with it myself and compare it with scalene's results to find out.

although in most cases those parts probably wouldn't contribute to the total runtime in any significant way anyways

This is precisely the reason why we started with a 10ms sampling interval. At the current 10ms interval, we've already seen success with identifying bottlenecks down to lines of code.

It's definitely possible that some of the more shorter calls will be missed but to be able to sample at 1-2ms intervals in production, the overhead naturally will increase. So that's not something that we'll be changing in the near future, but that may change in the future.

This issue has gone three weeks without activity. In another week, I will close it.

But! If you comment or otherwise update it, I will reset the clock, and if you label it Status: Backlog or Status: In Progress, I will leave it alone ... forever!

"A weed is but an unloved flower." ― Ella Wheeler Wilcox 🥀

Are you able to create a reproduction that you can share? I know you mentioned you use your own framework but perhaps it's you can reproduce it with uwsgi + gevent somehow? That help me a lot in debugging this.

repro.py

from gevent import monkey; monkey.patch_all()
import sentry_sdk
from sentry_sdk.integrations.wsgi import SentryWsgiMiddleware
from time import sleep

SENTRY_DSN = 'https://{}.ingest.sentry.io/{}'
sentry_sdk.init(
    dsn=SENTRY_DSN,
    environment='development',
    traces_sample_rate=1.0,
    _experiments={
        'profiles_sample_rate': 1.0,
    }
)


# Main WSGI application
def application(env, start_response):
    response = b'Hello world'
    for byte in response:
        sleep(0.1)

    start_response('200 OK', [
        ('Content-Type', 'text/plain'),
        ('Content-Length', str(len(response)))
    ])
    return [response]


application = SentryWsgiMiddleware(application)

repro.ini

[uwsgi]
http = :9090
wsgi-file = repro.py
gevent = 100

uwsgi --ini repro.ini

Although I'm not sure sentry-sdk will work at all, because the default transport complains about disabled threading in uwsgi, but you are not allowed to turn on uwsgi threads if you enable gevent. I've implemented my own transport that works with uwsgi and gevent. This however does not change whether or not Python threads are supported.

Actually it looks like the minimal repro does not actually reproduce the problem and does record samples periodically, like it's supposed to, although the profiles are completely useless because the frame only shows what the Hub greenlet is doing. But it's at least good to know, that I no longer need my custom transport. Looks like the default transport works just fine now with my setup.

@Zylphrex

@Zylphrex Alright I think it might be related to uwsgi's builtin static mapping and/or cache. If I enable them for the minimal repro case, then profiles stop working as well:

repro.ini

[uwsgi]
http = :9090
wsgi-file = repro.py
gevent = 100
enable-threads = True
cache2 = name=default,items=1000,purge_lru=True
static-map = /static=data/static
static-gzip-all = True
static-cache-paths = 60

Yes, If I remove the static mapping and cache from my application, then profiles start working there as well. I assume the way uwsgi forks the processes happens a bit differently with static maps.

@Zylphrex

@Zylphrex I've made a little proof-of-concept for sampling all the currently active greenlets. It's a little bit messy still, but it works. Cleaning it up properly will probably require some backend-support for an optional second identifier in addition to the thread_id for a fiber-like (i.e. in this case a greenlet) within a thread. Right now i'm just concatenating the two numbers into a string, if I add a hyphen or dot to separate the two ids, the Backend will reject the profile, if I try to generate a unique integer from the two integers instead of a string there also seem to be some problems on the backend, so right now there is some use of Union that is not very pretty for get_current_thread_id and related members/functions.
Daverball@e7d7dcd

@Zylphrex

@Zylphrex I've made a little proof-of-concept for sampling all the currently active greenlets. It's a little bit messy still, but it works. Cleaning it up properly will probably require some backend-support for an optional second identifier in addition to the thread_id for a fiber-like (i.e. in this case a greenlet) within a thread. Right now i'm just concatenating the two numbers into a string, if I add a hyphen or dot to separate the two ids, the Backend will reject the profile, if I try to generate a unique integer from the two integers instead of a string there also seem to be some problems on the backend, so right now there is some use of Union that is not very pretty for get_current_thread_id and related members/functions.
Daverball@e7d7dcd

@Daverball Thanks for this and the repro! I'll take a look this soon

@Daverball

Hey @Daverball, I'm still looking into a more permanent solution into this issue but I think I've narrowed down what's happening.

When running uwsgi with master mode, which your cache options implicitly enables, threads that were started in the master process do not run in the forked worker processes. This means that the sample only runs in the master process while the profiles are being pushed on the the queue in the worker process so no samples are ever taken.

As a short term solution, you can potentially try enabling lazy-apps in uwsgi (see uwsgi docs) which will delay the loading of the app and correctly start the profiler thread on the worker processes.

I'll look into a more permanent fix to this issue. Let me know if that works for you in the mean time. And I'll also be looking into your poc with the greenlets soon!

@Daverball

@Daverball if you are able to test this out this branch to see if it solves your problem that'd be much appreciated 😄

@Zylphrex

@Zylphrex Looks like delaying the start of the sampler thread does indeed do the trick.

This issue has gone three weeks without activity. In another week, I will close it.

But! If you comment or otherwise update it, I will reset the clock, and if you label it Status: Backlog or Status: In Progress, I will leave it alone ... forever!

"A weed is but an unloved flower." ― Ella Wheeler Wilcox 🥀

@Zylphrex

@Zylphrex Since the original issue has been resolved I will close the issue. I may open another one for greenlet tracking improvements.

I might take a look at the backend code myself to see what's needed there to support tracking fibers in addition to threads.

Yes, do open a separate issue and we can discuss how we can improve greenlet tracking there 👍

Navigation Menu

Repository navigation

Profiles will not work with a `traces_sampler` instead of `traces_sample_rate` #1813

How do you use Sentry?

Version

Steps to Reproduce

Expected Result

Actual Result

12 remaining items

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Profiles will not work with a traces_sampler instead of traces_sample_rate #1813

Description

How do you use Sentry?

Version

Steps to Reproduce

Expected Result

Actual Result

Activity

Daverball commented on Dec 29, 2022

Daverball commented on Jan 2, 2023

sl0thentr0py commented on Jan 3, 2023

Daverball commented on Jan 3, 2023

Zylphrex commented on Jan 3, 2023

Daverball commented on Jan 3, 2023

Zylphrex commented on Jan 3, 2023

github-actions commented on Jan 25, 2023

12 remaining items

Zylphrex commented on Feb 12, 2023

Daverball commented on Feb 12, 2023

Daverball commented on Feb 12, 2023

Daverball commented on Feb 12, 2023

Daverball commented on Feb 12, 2023

Daverball commented on Feb 13, 2023

Zylphrex commented on Feb 14, 2023

Zylphrex commented on Feb 14, 2023

Zylphrex commented on Feb 14, 2023

Daverball commented on Feb 15, 2023

github-actions commented on Mar 9, 2023

Daverball commented on Mar 10, 2023

Zylphrex commented on Mar 10, 2023

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions

Profiles will not work with a `traces_sampler` instead of `traces_sample_rate` #1813