nic-6443 commented on issue #12275:
URL: https://github.com/apache/apisix/issues/12275#issuecomment-4988690889
I spent some time on this and I believe the root cause is an infinite busy
loop in the `nginx-lua-prometheus` key index. It exists unchanged from 2.15
(upstream `0.20220527`) through 3.15 (`nginx-lua-prometheus-api7 0.20240201`),
3.17 (`0.20250302`) and current master (`0.20260623`) — neither #13088 nor
#13602 touches it, which is consistent with @shlok-srivastava hitting it again
after upgrading to 3.17.
The library tracks metric names in a key index stored in the same shared
dict: slots `__ngx_prom__key_1 .. key_N` plus a counter
`__ngx_prom__key_count`. Every new time series goes through `KeyIndex:add()` in
`prometheus_keys.lua`:
```lua
while true do
local N = self:sync() -- 2x dict:get (delete_count,
key_count)
if self.index[key] ~= nil then break end
N = N + 1
local ok, err = self.dict:add(self.key_prefix .. N, key) -- 1x dict:add
if ok then
self.dict:incr(self.key_count, 1, 0) -- key_count only advances on
success
...
break
elseif err ~= "exists" then
return "Unexpected error adding a key: " .. err
end
-- err == "exists": retry the same slot, forever
end
```
The loop only makes progress if slot `key_count + 1` is free, and a full
dict breaks that invariant. When a full dict needs room, lua-nginx-module
force-evicts the LRU-tail node (`ngx_http_lua_shdict_expire(ctx, 0)`, "deletes
oldest entry by force") on every set/add/incr. `__ngx_prom__key_count` is an
ordinary evictable node, and it is only refreshed when a worker registers/looks
up a *new* key through the index — under steady traffic with a stable set of
series nothing touches it, so it ages to the LRU tail and eventually gets
evicted (that narrow timing window is also why this takes hours and only hits
some instances — 2/38 above). After that `sync()` reads it as `nil → 0`, and if
one add does succeed, `dict:incr(key_count, 1, 0)` re-creates it at **1**, far
below the surviving slots. The next new series then does
`dict:add("__ngx_prom__key_1", ...)` against a slot that still exists →
`"exists"` → same N → `"exists"` → forever. (The key_count rewind also silently
c
orrupts the index — duplicate/missing series, the milder symptom family that
0.20260623 tried to address.)
Two properties make it exactly what you both captured:
- the loop never yields, so the worker never returns to the event loop: 100%
CPU forever, completely traffic-independent — removing traffic can't help
because the stuck request never finishes. Any other worker that later registers
any new series joins the spin. Only a restart recovers: reload keeps the shm
zone, and `Prometheus.init()` itself calls `key_index:add()` from init_worker,
so reloaded workers can get stuck before serving a single request.
- every failed `dict:add()` does a lookup on the blocking slot, which moves
that node to the LRU *head* — the node blocking progress becomes the
most-recently-used one and can never be evicted. The poisoned state is
self-sustaining.
The loop body is 2 gets + 1 store per iteration, and the flamegraph in the
original report confirms it: extracting the numbers from the SVG gives
`ngx_meta_lua_ffi_shdict_get` 65.78% vs `ngx_meta_lua_ffi_shdict_store` 32.68%
— a 2.01:1 ratio, with `ngx_shmtx_lock` under both. There is **no
`ffi_shdict_incr` frame anywhere** in that flamegraph, which rules out metric
write pressure (counter/histogram flushes go through `dict:incr`): those
workers weren't recording metrics at all, they were spinning in this loop. The
remaining symbols are the loop too — `ngx_crc32_short`/`ngx_memn2cmp` (key
hashing/comparison) and `lj_strfmt_wint`/`lj_str_new` (the `key_prefix .. N`
concat each iteration).
Repro, takes seconds, no APISIX needed — drives the real library:
```bash
git clone https://github.com/api7/nginx-lua-prometheus
resty -I nginx-lua-prometheus --shdict 'prometheus_metrics 10m' repro.lua
```
<details><summary>repro.lua</summary>
```lua
local KeyIndex = require("prometheus_keys")
local dict = ngx.shared.prometheus_metrics
-- 50 series registered through the public API
local ki = KeyIndex.new(dict, "__ngx_prom__")
for i = 1, 50 do
ki:add('apisix_http_status{route="' .. i .. '"}', "dict full")
end
-- Stand-in for the one thing the shared dict does on its own under memory
-- pressure: forcible eviction of the LRU-tail node, which is key_count
-- whenever no new series has been registered for a while.
dict:delete("__ngx_prom__key_count")
-- watchdog: abort instead of hanging the process forever
local count = 0
local proxy = setmetatable({}, { __index = function(_, method)
return function(_, ...)
if method == "add" then
count = count + 1
if count > 200000 then error("SPIN", 0) end
end
return dict[method](dict, ...)
end
end })
ki.dict = proxy
-- one brand-new series arrives...
local t0 = ngx.now()
local ok, err = pcall(ki.add, ki, 'apisix_http_status{route="brand-new"}',
"dict full")
ngx.update_time()
if not ok and err == "SPIN" then
print(string.format("infinite loop: 200000 failed dict:add() on the same
slot in %.2fs, add() never returns", ngx.now() - t0))
else
print("add() returned normally")
end
```
</details>
Output on both `0.20250302` (3.17.0's dep) and current master `0.20260623`:
the watchdog fires after 200k failed `add()` in ~0.3s; without it the call
never returns. The 2.15-era upstream lib has the identical loop, and so does
upstream knyar/nginx-lua-prometheus master.
I also ran the uncapped version inside a 4-worker openresty (apisix-runtime)
and profiled the stuck workers to compare with your captures:
```
perf (self time) 2.15 report 3.15 report this repro
ngx_shmtx_lock 70.8% 75.6% 75.3%
ffi_shdict_get 3.9% 6.2% 11.2%
ffi_shdict_store 2.0% 2.8% 3.6%
shdict_lookup 2.3% 4.0% 2.0%
shdict_expire 2.2% 1.2% 1.1%
ngx_shmtx_unlock 10.1% 4.3% 5.6%
```
strace on a stuck worker shows the same `futex(FUTEX_WAKE)` / `FUTEX_WAIT =
EAGAIN` flood as the original screenshot (the shdict mutex semaphore under
contention), and the workers stayed pegged at ~100% with zero traffic until
killed.
For the fix, I think `KeyIndex:add()` has to stop trusting `key_count`
unconditionally: when `add()` returns `"exists"`, key_count has fallen behind
an occupied slot, so advance it / adopt the occupant into the local index
instead of retrying the same slot forever — plus a hard iteration cap that
degrades to the existing "dict full" error rather than spinning. I validated
that locally: with the same poisoned state a guarded `add()` returns in ~3ms,
places the key and repairs key_count.
Until then the practical mitigation is what @moonming said: keep
`prometheus-metrics` large enough that it never actually fills (the spin can
only arm on a full dict — worth alerting on `free_space()` reaching 0);
`expire`/fewer labels/smaller bucket sets slow the fill but don't remove the
loop.
Happy to submit a PR (fix in api7/nginx-lua-prometheus + dependency bump
here) if this direction makes sense.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
