DogStatsD backend emits `Stats.timer()` metrics in seconds instead of milliseconds
- Dominant language
- Python
- Stars
- 46.9k
- Forks
- 17.8k
- Avg merge
- 2d 10h
- Merged PRs (30d)
- 483
Description
### Under which category would you file this issue?
Airflow Core
### Apache Airflow version
3.3.1
### What happened and how to reproduce it?
When we moved from the older statsd metrics to the new ones, the values for some metrics changed from ms to s.
AI-analysis:
With `[metrics] statsd_datadog_enabled = True`, every metric emitted via `Stats.timer()` is
under-reported by 1000x. `Stats.timing()` metrics are unaffected, so units become inconsistent
between metrics on the same backend.
Airflow's own `Timer` computes its duration in milliseconds, but delegates the actual send to the
backend timer — `_shared/observability/metrics/protocols.py`:
```python
def stop(self, send: bool = True) -> None:
if self._start_time is not None:
self.duration = 1000.0 * (time.perf_counter() - self._start_time) # Convert to milliseconds.
if send and self.real_timer:
self.real_timer.stop()
```
For the DogStatsD backend that `real_timer` is a datadogpy `TimedContextManagerDecorator`, created
without `use_ms` — `_shared/observability/metrics/datadog_logger.py`:
```python
return Timer(self.dogstatsd.timed(stat, tags=tags_list, **kwargs)) # timer()
```
`DogStatsd.use_ms` defaults to `False` and `get_dogstatsd_logger()` never sets it, so
`datadog/dogstatsd/context.py` sends elapsed **seconds** under the `|ms` type:
```python
elapsed = monotonic() - start
use_ms = self.use_ms if self.use_ms is not None else self.statsd.use_ms
elapsed = round(1000 * elapsed) if use_ms else elapsed
self.timing_func(self.metric, elapsed, self.tags, self.sample_rate)
```
The sibling `timing()` method in the same class converts correctly, which is why only `timer()` is
affected:
```python
if isinstance(dt, datetime.timedelta):
dt = dt.total_seconds() * 1000.0
return self.dogstatsd.timing(metric=stat, value=dt, tags=tags_list)
```
### What you think should happen instead?
All stats should be in ms. In theory fixable with one change in `get_dogstatsd_logger()`:
```python
dogstatsd = DogStatsd(**dogstatsd_kwargs, use_ms=True)
```
Im willing to submit a PR if this is the correct solution. However, i imagine this is a breaking change that may not be desirable?
### Operating System
_No response_
### Deployment
Official Apache Airflow Helm Chart
### Apache Airflow Provider(s)
_No response_
### Versions of Apache Airflow Providers
_No response_
### Official Helm Chart version
1.22.0 (latest released)
### Kubernetes Version
_No response_
### Helm Chart configuration
_No response_
### Docker Image customizations
_No response_
### Anything else?
Some AI-generated analysis:
### Measured
Production deployment, hourly buckets, switching `statsd_datadog_enabled` off → on:
| metric | path | before | after |
|---|---|---|---|
| `scheduler.scheduler_loop_duration.95percentile` | `timer()` | ~1100 | **1.13** |
| `kubernetes_executor.pod_creation.avg` | `timer()` | 23.5 | **0.0240** |
| `dagrun.schedule_delay.95percentile` | `timing()` — control | 1.9–4.6e8 | unchanged |
`pod_creation` times a single `create_namespaced_pod` API call: 23.5 ms is plausible, 0.024 ms is
not — confirming milliseconds was the correct unit.
### How to reproduce
1. `[metrics] statsd_on = True`, `[metrics] statsd_datadog_enabled = True`.
2. Compare `scheduler.scheduler_loop_duration` against `dagrun.schedule_delay`; the former is 1000x
below its true value.
3. Setting `statsd_datadog_enabled = False` restores the correct magnitude for `timer()` metrics.
### Anything else
No configuration-only workaround: `use_ms` has no environment variable, Airflow never sets it, and
`[metrics] statsd_custom_client_path` is read only by `statsd_logger.py`, not the DogStatsD backend.
Introduced by #15132 (merged 2021-04-01), which fixed DogStatsD mode by changing
`self.dogstatsd.timer(...)` to `self.dogstatsd.timed(...)`. `timed()` defaults to seconds where
`timing()` takes milliseconds, so the unit regression came in with that fix and affects every
release since.
Distinct from #10629 / #20804, which concern *callers* passing seconds into `timing()`. One instance
of that does still exist independently of this issue: `dag_processing.last_duration` passes
`time.monotonic()` seconds straight into `stats.timing()`, so it is 1000x low on both backends.
### Are you willing to submit PR?
- [x] Yes I am willing to submit a PR!
### Code of Conduct
- [x] I agree to follow this project's [Code of Conduct](https://github.com/apache/airflow/blob/main/CODE_OF_CONDUCT.md)
Contributor guide
Research direction
Start in _shared/observability/metrics/datadog_logger.py and inspect get_dogstatsd_logger(), then compare the timer() and timing() paths with _shared/observability/metrics/protocols.py and datadog/dogstatsd/context.py. Verify that DogStatsD timer metrics use the same millisecond units as timing() metrics, while preserving the existing behavior of the other metrics paths.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- python
- Domain
- observability-sre
- Issue type
- Bug
- Difficulty
- 2/5
- Estimated time
- 1-3 hours
- Activity status
- Active
- Clarity
- Clearly specified
- Newbie friendliness
- 78/100