wklken opened a new issue, #13961: URL: https://github.com/apache/apisix/issues/13961
### Current Behavior After upgrading our APISIX-based deployment from 3.16 to 3.18, one Pod started exhibiting recurring high CPU utilization across multiple workers. Other Pods in the deployment were less affected. The production traffic was reported as unchanged across the upgrade; this was not a controlled replay benchmark. Two low-frequency profiles of the same worker identified the mutex of **`prometheus-metrics`** as a substantial CPU hotspot. We traced the mutex pointer to the actual shared-memory zone and verified its name from the zone's management metadata. Comparing the Prometheus dependency versions revealed a possible regression mechanism: **re-adding an expired indexed metric now increments `delete_count`, causing other workers to scan the entire historical index through `sync_range(0, N)`**. The affected Pod has an index high-water counter of approximately 192,000. We can establish the lock identity, deployed dependency, configuration, index size, and source-level amplification mechanism. **We have not captured a Lua stack proving that `sync_range()` was executing during these CPU spikes, and have not completed a controlled A/B test.** We are reporting an observed performance problem with a specific, evidence-backed hypothesis, rather than claiming that a particular commit has been conclusively proven responsible. > Disclosure note: infrastructure identifiers, exact timestamps, runtime addresses, and application label values are omitted. Internal index counters are explicitly rounded. Public source revisions and sampling counts are retained. ## CPU trend The cropped dashboard below shows the affected Pod's elevated green CPU series alongside the other Pods. Identifying legends are omitted. This is a dashboard observation, separate from the single-worker perf sample percentages reported below. <img width="1602" height="468" alt="CPU utilization across Pods, with one green series showing recurring elevated CPU" src="https://github.com/user-attachments/assets/f7205178-e9f2-42ab-b07b-5ddf00ed6fd9"; /> ## Evidence 1: the dependency changed, and the new deployed files were verified | Official APISIX release | Pinned `nginx-lua-prometheus-api7` version | |---|---| | [3.16.0 rockspec](https://github.com/apache/apisix/blob/f9c4ee37170bdfe075c846973c1be65a582a0c4f/apisix-master-0.rockspec#L54) | `0.20250302-1` | | [3.18.0 rockspec](https://github.com/apache/apisix/blob/0796d9c2cbedb1f8bf8194292ff526599f4fde20/apisix-master-0.rockspec#L57) | `1.0.0-1` | The dependency repository is `api7/nginx-lua-prometheus`: - Old version: `f86aa3ef2249e2dce4312e549ab45ad79203634f` (`0.20250302`). - New version: `bc04f9daa8f8da0f8f8165687c9e53136f9c50f5` (`1.0.0`). SHA-256 hashes of the three deployed files match `1.0.0`: ```text e8f909659a3a53bf11bdf908c7f68a709b74641102fb74b030c2d10a9fea58e1 prometheus.lua 91ae2b17b138602b7388f840177fbec9bf5516e2c3730b4c36224f1ba8bb3497 prometheus_keys.lua 749ecb10c6dd2060dbf081c93005a87f757679ff2eb81c99989a2553bd96bb01 prometheus_resty_counter.lua ``` The previous production image's files have not been independently verified; the old-side comparison uses the official 3.16.0 dependency pin. Between these two dependency tags, `prometheus.lua` and `prometheus_resty_counter.lua` are unchanged. The runtime code differences are in `prometheus_keys.lua`. ## Evidence 2: repeated CPU samples identify the same metric-zone mutex We sampled one serving worker from its host, using the same parameters twice: user-space `cpu-clock:u`, 19 Hz, 12 seconds, no inherited tasks, and the `BX` user register. A one-second CPU observation immediately before the second profile showed that worker at 99% CPU. | Profile | Total decoded samples | Samples in the inspected spin loop | Sample share | |---|---:|---:|---:| | First | 118 | 47 | 39.8% | | Second | 105 | 54 | 51.4% | All selected spin-loop samples in both profiles contained the same mutex pointer. Exact runtime addresses are omitted. The attribution was verified as follows: 1. Disassembly of the **actual worker executable** showed that `ngx_shmtx_lock()` saves its mutex argument from `RDI` in `RBX` and retains it in the sampled spin loop. The sampled instructions were matched to that inspected spin loop. 2. `/proc/<host-worker-pid>/maps` placed that mutex inside a shared mapping of size 128 MiB. 3. The actual binary's shared-dict initializer showed the `log_ctx` field offset. A bounded read of the zone header and its context string returned: ```text zone_context = in lua_shared_dict zone "prometheus-metrics" ``` This identifies the dictionary by its actual name, not just by matching its configured size. The [module's initialization code](https://github.com/api7/apisix-nginx-module/blob/1.19.9/src/meta/ngx_meta_lua_shdict.c#L234-L241) explains this name field. Earlier native profiles also showed `ngx_meta_lua_shdict_lookup` and `lj_str_new` as hotspots. Those symbols are consistent with repeated dictionary lookup and string construction, but are not unique to `KeyIndex:sync_range()`. **Interpretation limit:** these percentages describe the selected worker's samples, not total Pod CPU, measured lock-hold duration, or a throughput regression percentage. We have no valid Lua call chain from these profiles. The sampled worker may be a lock waiter rather than the worker causing a long hold. <details> <summary>Profiling method</summary> The capture used the following command shape, with a verified host worker PID substituted for `WORKER_PID`: ```bash timeout -s INT -k 2s 16s perf record -q -N -B -o - \ -p "$WORKER_PID" -e cpu-clock:u -F 19 -m 16 \ --no-inherit --user-regs=bx -- sleep 12 | timeout -s INT -k 2s 22s perf script -i - -F time,ip,uregs ``` The decoded output was retained in shell memory for analysis. The spin-loop filter used instruction addresses verified against the actual executable. Exact addresses are omitted; instruction addresses and structure offsets are binary-specific and must not be reused blindly with other builds. Metadata inspection used read-only `/proc/<pid>/mem` access without attaching a debugger, stopping a worker, injecting code, or calling the live shared-dict API. Profiling and inspection have some overhead; we did not establish zero request-latency impact. The collectors exited and all eight workers remained present afterward. </details> ## Evidence 3: expiry is configured and the historical index is large Two bounded read-only lookups of the internal numeric keys produced the following state. Values are intentionally rounded for disclosure; these are summarized observations, not raw output: | Relative time | `__ngx_prom__key_count` | `__ngx_prom__delete_count` | |---|---:|---:| | T | approximately 192,000 | approximately 6,100 | | T + 1 second | approximately 192,000 | approximately 6,100 | These were non-atomic snapshots of the running process, with exact key-name/type checks. Less than 6 KiB of tree/entry metadata was read in total; no full key enumeration was performed. Important distinctions: - `key_count` is an index-allocation counter/high-water value, **not the current live series count**. Normal deletion does not compact the scan range; counter eviction/recreation is a separate exceptional case. - `delete_count` is a cumulative notification counter, **not the number of full scans**. Explicit deletions can also increase it. - The allocation counter increased slightly, while the deletion counter did not change between these two snapshots. Rounding masks the small allocation increase. These readings establish state and scale, not an expiry/re-add event during that particular second or during the earlier profiles. ## Source-level hypothesis: expired re-adds amplify full historical resynchronization The relevant change is [api7/nginx-lua-prometheus#14](https://github.com/api7/nginx-lua-prometheus/pull/14), commit [`845084f`](https://github.com/api7/nginx-lua-prometheus/commit/845084f47417f722918f7ea6ec28721fa8f31215). Its purpose is to fix duplicate metric exposition following expired-key re-addition. In the [old version](https://github.com/api7/nginx-lua-prometheus/blob/f86aa3ef2249e2dce4312e549ab45ad79203634f/prometheus_keys.lua#L114-L142), failure to renew an expired index slot clears local state and registers a new slot. It does not increment `delete_count` on this branch. In the [new version](https://github.com/api7/nginx-lua-prometheus/blob/bc04f9daa8f8da0f8f8165687c9e53136f9c50f5/prometheus_keys.lua#L155-L175), `err == "not found"` additionally executes: ```lua self.deleted = self.deleted + 1 local _, incr_err, forcible = self.dict:incr(self.delete_count, 1, 0) ``` Another worker's next [`KeyIndex:sync()`](https://github.com/api7/nginx-lua-prometheus/blob/bc04f9daa8f8da0f8f8165687c9e53136f9c50f5/prometheus_keys.lua#L71-L108) then takes the existing full-sync branch: ```lua local delete_count = self.dict:get(self.delete_count) or 0 local N = self.dict:get(self.key_count) or 0 if self.deleted ~= delete_count then self:sync_range(0, N) self.deleted = delete_count end ``` `sync_range()` iterates every index in that numeric range, constructs `self.key_prefix .. i`, calls `dict:get()` for each slot, and conditionally calls `dict:ttl()`. It includes historical empty slots and has no explicit yield in the loop. This can execute on the request path: [`lookup_or_create()`](https://github.com/api7/nginx-lua-prometheus/blob/bc04f9daa8f8da0f8f8165687c9e53136f9c50f5/prometheus.lua#L415-L424) calls `KeyIndex:add()` even on a local lookup-cache hit when positive expiry is configured. `add()` calls `sync()` before updating the slot. ```text metric update with expiry configured → lookup_or_create / KeyIndex:add → expired indexed metric is re-added → shared delete_count increases [new behavior] → other workers observe the notification → sync_range(0, historical key_count) → many string constructions and shared-dict get/ttl operations → potential cross-worker mutex contention and request-path CPU amplification ``` At the observed, rounded N≈192,000, **one** full sync executes approximately 192,000 index `get()` calls, plus conditional TTL reads. Across multiple workers, the operation count can reach the million range for an invalidation observed by all of them. Notifications can coalesce; we have not measured the actual scan frequency and do not multiply the cumulative deletion counter by N. This provides a mechanism for increased CPU with unchanged traffic: the work performed for the same expired-metric reappearance changed, and its cost depends on accumulated index history. It does not yet explain why only one Pod is much more affected; per-Pod index history and expiry/re-add behavior have not been compared. ## Secondary hypothesis: periodic full shared-dict reclamation [api7/nginx-lua-prometheus#18](https://github.com/api7/nginx-lua-prometheus/pull/18), commit [`5f68f6c`](https://github.com/api7/nginx-lua-prometheus/commit/5f68f6ca40d98de506c65c4990461a23351abf9c), adds an unconditional `self.dict:flush_expired()` after local expired-index cleanup. For the initialization path observed in our deployment, `Prometheus.init(dict, string_prefix)` supplies the library's **3600-second** cleanup interval. Therefore the `or 600` fallback in `KeyIndex.new()` is not the effective interval here. This is separate from the 15-second exporter refresh and 300/600-second metric TTLs. The [apisix-nginx-module 1.19.9 implementation](https://github.com/api7/apisix-nginx-module/blob/1.19.9/src/meta/ngx_meta_lua_shdict.c#L558-L646) holds the zone mutex while traversing the LRU. With no argument, reclamation is not count-limited. This is a plausible source of periodic long holds, but we have not correlated its execution with the CPU spikes and do not attribute all recurring spikes to it. Also, a finite `flush_expired(n)` bounds successfully freed entries, not necessarily nodes visited, so it would not by itself establish a strict traversal-time bound. ## Questions for maintainers 1. Is broadcasting a full historical resync on expired-key re-addition expected at this index scale, or could api7/nginx-lua-prometheus#14 introduce this performance regression under expiry/re-add churn? 2. Could the consistency fix use bounded/incremental invalidation or index compaction while retaining duplicate-free exposition? 3. Should the new reclamation path have single-worker ownership and a bounded amount of work, given that it shares the serving workers' metric-zone mutex? We are not proposing simply removing either correctness fix: removing the broadcast can reintroduce duplicate metrics, and removing reclamation can reintroduce retained expired entries. We would appreciate guidance on a bounded implementation and the most useful additional evidence to distinguish these two paths. ### Expected Behavior Reintroducing an expired metric should preserve index consistency and avoid duplicate exposition without causing excessive request-path work across workers as the historical index grows. Background reclamation should also avoid excessive shared-dict lock hold times. ### Error Logs No error-log excerpt is attached. The evidence above consists of CPU samples, native symbol/disassembly analysis, and bounded read-only shared-memory metadata inspection. We did not change production log levels. ### Steps to Reproduce We do not yet have an executed minimal reproduction. We avoided changing production code/configuration or enabling in-worker instrumentation to obtain one. The production observation is recurring CPU spikes after upgrading our customized APISIX deployment from 3.16 to 3.18, with traffic reported as unchanged; this was not a controlled replay. A focused isolated validation could compare the two dependency versions under the same conditions: 1. Create two or more independent KeyIndex instances sharing one dictionary, representing workers with separate local index state. 2. Build a large historical index, sync both instances, and let an indexed metric expire while retaining its local cached index entry. 3. Re-add that metric through one instance. 4. Update an existing metric through the other instance; count sync_range() calls and dictionary get/ttl operations. 5. Compare incremental versus full historical scans, and verify duplicate-free exposition and expiry correctness. Then repeat with real workers to measure CPU, mutex contention, and request latency. Validate the periodic cleanup path separately. This is a proposed validation procedure, **not an experiment already performed**. ### Environment - APISIX-based **customized build**, upgraded from 3.16 to 3.18. - Eight NGINX workers; container CPU quota equivalent to eight cores. - Linux 5.4-based kernel; x86-64, LuaJIT-enabled OpenResty. Vendor-specific build details are omitted. - `lua_shared_dict prometheus-metrics 128m`. - Exporter refresh interval: 15 seconds. - Enabled bandwidth metrics expire after 300 seconds; several other configured metrics expire after 600 seconds. - Additional application-specific labels are present. - Our customized exporter disables the official HTTP status/latency updates and enables bandwidth/LLM updates. These switches are customization details, **not stock APISIX configuration fields**. The contribution of AI-specific metrics has not been measured. - The underlying `prometheus.lua`, `prometheus_keys.lua`, and `prometheus_resty_counter.lua` files are byte-for-byte identical to the dependency's `1.0.0` release. The customized exporter and the lack of a controlled traffic replay are relevant limitations when attributing the issue to an upstream change. -- 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]
