Incorrect Duration for Celery Monitoring

[rjo100]

How do you use Sentry?

Sentry Saas (sentry.io)

Version

1.21.1

Steps to Reproduce

Sentry SDK is reporting large, negative durations for terminal check-ins (DONE/FAILED). now() is called here for example to get the current timestamp:

sentry-python/sentry_sdk/integrations/celery.py

Line 452 in 81afcea

duration=now() - start_timestamp_s,

However, that uses perf_counter() underneath the hood.

sentry-python/sentry_sdk/utils.py

Line 1326 in 81afcea

return time.perf_counter()

As per python docs, the reference point is undefined, so somehow the initial check-in and closing check-in are running across different threads or systems perhaps, resulting in large negative durations using different reference points
https://docs.python.org/3/library/time.html#time.perf_counter

Expected Result

No issues generated in sentry

Actual Result

Can link to sentry issue

[evanpurkhiser]

This makes a lot of sense, because we're storing the timestamp in the celery task header, which gets serialized across system boundaries usually.

[antonpirker]

Yes, that makes sense. The start and the end are happening in different processes (start in the celery beat process, and end in a celery worker process)

We will need to change from perf_counter to a wall-clock time to make this work.