apache / apache/airflow

DogStatsD backend emits `Stats.timer()` metrics in seconds instead of milliseconds

Open Beginner friendly
#72,110 0 comments 0 reactions 0 assignees View on GitHub
area:metrics kind:bug needs-triage
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

Open the contributing 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.