[Bug] BE /metrics stalls 0.5 s every 15 s and up to 15 s: metric hooks run under MetricRegistry lock; stream load blocks HTTP worker
- Dominant language
- Java
- Stars
- 15.9k
- Forks
- 3.9k
- Avg merge
- 2d 23h
- Merged PRs (30d)
- 520
Description
### Search before asking
- [x] I had searched in the [issues](https://github.com/apache/doris/issues?q=is%3Aissue) and found no similar issues.
### Version
`doris-4.1.3-rc02-7126cf65d96 (Cloud Mode)`, official aarch64 build. 5 BE i8g.4xlarge (16 vCPU/128 GB, 3 TB file cache) + MS + FDB, Amazon Linux 2023, kernel 6.18. BE config defaults (`enable_metric_calculator=true`, `webserver_num_workers=128`).
### What's Wrong?
`GET :8040/metrics` (~100 KB) takes ~7 ms normally, but stalls **every 15 s for 0.4–0.6 s** and a few times per hour for **2–15 s** (10.9 s, 14.8 s seen); Prometheus scrapes time out. 1 sample/s:
```
05:57:25.864 0.377946
05:57:41.436 10.754890
05:57:57.252 0.222413
05:58:12.673 0.464823 # 60 samples: avg 0.20 s, max 10.75 s
```
Watching thread `calculate_metrics_thread` via `/proc//task//{stat,wchan,syscall,stack}` for 8 min shows two mechanisms:
**A. Every 15 s the hook run holds the registry lock for ~0.6 s.** The thread wakes every 15 s and runs 0.57–0.68 s in state R; every `/metrics` request arriving in that window blocks until it ends (30 of 480 samples, 0.4–0.6 s). Kernel stack during the run: `__do_sys_newfstatat → vfs_fstatat → vfs_statx → filename_lookup`. From the 4.1.3-rc02 source:
- `Daemon::calculate_metrics_thread` → `MetricRegistry::trigger_all_hooks(true)` holds `MetricRegistry::_lock` for the whole hook run ([metrics.cpp#L315-L321](https://github.com/apache/doris/blob/4.1.3-rc02/be/src/common/metrics/metrics.cpp#L315-L321)). `to_prometheus()` (the `/metrics` handler) takes the same lock ([#L323-L326](https://github.com/apache/doris/blob/4.1.3-rc02/be/src/common/metrics/metrics.cpp#L323-L326)) and holds it while serializing; concurrent scrapes serialize too (40 parallel curls: 0.007, 0.014, 0.020 … 0.238 s).
- The expensive hook is `DorisMetrics::_update_process_fd_num()` ([doris_metrics.cpp#L479](https://github.com/apache/doris/blob/4.1.3-rc02/be/src/common/metrics/doris_metrics.cpp#L479)): `directory_iterator("/proc/self/fd")` + `entry.is_regular_file()` per entry. Every entry is a symlink, so `is_regular_file()` follows it with a `stat()`: **one `newfstatat` per open fd**. This BE holds ~197k fds (`doris_be_process_fd_num_used 195746`, `doris_be_local_file_open_reading 195503`, file cache readers) → ~197k stat() per run. The same loop in Python on this host: 0.66 s; plain readdir (`ls /proc//fd | wc -l`): 0.14 s.
**B. Rare multi-second stalls while the hook thread sleeps.** In the same 8 min `/metrics` took 2.917 s, 1.761 s and 9.097 s while `calculate_metrics_thread` was inside its 15 s `futex` wait, so no metrics lock was involved. All handlers run inline on the 128 libevent worker threads (`EvHttpServer::on_request` → `handler->handle()`), and `StreamLoadAction` blocks its thread: `_handle()` does `body_sink->finish()` → `ctx->future.get()` → `pre_commit_txn()/commit_txn()` synchronously ([stream_load.cpp#L168-L200](https://github.com/apache/doris/blob/4.1.3-rc02/be/src/service/http/action/stream_load.cpp#L168-L200)), and `on_chunk_data()` → `StreamLoadPipe::_append()` waits on `_put_cond` when the pipe is full. Any connection already accepted by that worker (e.g. a `/metrics` scrape) waits until the handler returns; ~22 stream loads are in flight here. A second 400 s run sampling `/metrics`, `?type=core` and `/api/health` in parallel confirms it: `/api/health` (no lock at all) stalled 8.561 s at the same moment as the other two; `/metrics` also hit 14.8 s twice.
### What You Expected?
`/metrics` answers in milliseconds regardless of hooks or stream loads on the same webserver; fd counting is not O(fds) `stat()` calls; scrapes do not serialize on one mutex.
### How to Reproduce?
1. Cloud-mode BE with many open fds (large file cache, ~200k here), default config, stream loads running.
2. `for i in $(seq 60); do date -u +%T.%N|cut -c1-12|tr '\n' ' '; curl -s -o /dev/null -w '%{time_total}\n' 127.0.0.1:8040/metrics; sleep 1; done | awk '$2>0.05'` → one 0.4–0.6 s stall every 15 s, sometimes several seconds.
3. `TID=$(grep -l '^calculate_metri' /proc/$PID/task/*/comm | awk -F/ '{print $(NF-1)}'); cat /proc/$PID/task/$TID/{wchan,stack}` during a run → `newfstatat`.
4. Hook cost alone: `python3 -c "import os,time;t=time.time();print(sum(1 for e in os.scandir('/proc/PID/fd') if e.is_file()),time.time()-t)"` → 195962 files, 0.66 s.
### Anything Else?
Suggestions: (1) `trigger_all_hooks` should copy the entity list and run hooks outside `MetricRegistry::_lock`, or `/metrics` should serve a snapshot refreshed by the calculator thread; (2) `_update_process_fd_num` should count entries without following symlinks (5x cheaper) or run less often; (3) blocking stream-load work (`future.get()`, `commit_txn`, pipe back-pressure) should leave the libevent worker threads, or `/metrics` should get a dedicated worker.
#16381 removed the jemalloc call from `trigger_all_hooks` for this same contention. No clean workaround: `enable_metric_calculator=false` just moves the 0.6 s hook run into every scrape.
### Are you willing to submit PR?
- [ ] Yes I am willing to submit a PR!
### Code of Conduct
- [x] I agree to follow this project's [Code of Conduct](https://www.apache.org/foundation/policies/conduct)
Contributor guide
Research direction
Start with be/src/common/metrics/metrics.cpp and doris_metrics.cpp, tracing calculate_metrics_thread, trigger_all_hooks, to_prometheus, and _update_process_fd_num; then inspect stream_load.cpp and the referenced StreamLoadPipe path. Run the provided /metrics timing loop with concurrent stream loads. Done means scrapes remain fast during hooks and loads, fd counting avoids per-entry stat calls, and scrapes do not serialize on one mutex.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- cpp, linux, prometheus
- Domain
- backend, observability-sre, performance
- Issue type
- Bug
- Difficulty
- 5/5
- Estimated time
- Over a week
- Activity status
- Active
- Clarity
- Mostly clear
- Newbie friendliness
- 45/100