This is an automated email from the ASF dual-hosted git repository. Yilialinn pushed a commit to branch codex/add-apisix-throughput-regression-blog in repository https://gitbox.apache.org/repos/asf/apisix-website.git
commit f01562efa474ae1e94cd543f1c07a49c2cd8d71d Author: Yilia Lin <[email protected]> AuthorDate: Mon Aug 31 11:26:07 2026 +0800 blog: refine throughput regression wording --- .../28/debugging-apisix-throughput-regression.md | 62 +++++------ .../28/debugging-apisix-throughput-regression.md | 114 ++++++++++----------- 2 files changed, 88 insertions(+), 88 deletions(-) diff --git a/blog/en/blog/2026/08/28/debugging-apisix-throughput-regression.md b/blog/en/blog/2026/08/28/debugging-apisix-throughput-regression.md index 92c831125cd..a6dad29b8f0 100644 --- a/blog/en/blog/2026/08/28/debugging-apisix-throughput-regression.md +++ b/blog/en/blog/2026/08/28/debugging-apisix-throughput-regression.md @@ -15,15 +15,15 @@ keywords: - LuaJIT - performance optimization - throughput regression -description: "An APISIX throughput regression showed why the widest path in the flame graph is not always the real bottleneck—and how CPU data, call stacks, LuaJIT events, and paired A/B tests exposed it." +description: "An APISIX throughput regression showed why the widest flame-graph path did not explain the full throughput drop—and how CPU data, call stacks, LuaJIT events, and paired A/B tests exposed costs that hotspot ranking missed." tags: [Ecosystem] --- -The flame graph didn't lie, but it didn't point to the bottleneck either. In this APISIX throughput regression, the widest path was not the one that mattered. The two paths worth investigating accounted for only 3.0% and 3.9% of the Lua samples. +The flame graph didn't lie, but it didn't explain the full throughput drop either. In this APISIX regression, two additional paths worth investigating had Lua self-time shares of only 3.0% and 3.9% among samples with Lua context. <!--truncate--> -Ranked by hotspot size alone, neither path would have made the first optimization shortlist. Finding them required a sequence of checks: confirm that the worker is CPU-bound, compare flame-graph widths, follow repeated call paths, inspect LuaJIT compilation and aborts when the numbers stop adding up, then use per-request call counts and paired A/B tests to measure the impact. +If we had ranked hotspots by size alone, neither path would have been investigated first. We found them by following a sequence of checks: confirm that the worker is CPU-bound, compare flame-graph widths, follow repeated call paths, inspect LuaJIT compilation and aborts when the flame graph does not explain the end-to-end throughput gap, then use per-request call counts and paired A/B tests to measure the impact. > **Data scope:** The data below comes from one internally customized APISIX > build in the same controlled environment, with more than 100 plugins loaded. > Throughput is normalized and shown only to explain how we isolated the > cause. It does not represent the general performance of Apache APISIX OSS > under other hardware, configurations, or workloads. @@ -43,13 +43,13 @@ If any of these conditions is not met, start with connections, the network, the ## 2. Read Width, Not Rank -We used eBPF to sample C and Lua call stacks simultaneously at 500 Hz. Here is the actual Lua on-CPU flame graph from the investigation. +We used eBPF to sample C and Lua call stacks simultaneously at 500 Hz. Here is the Lua on-CPU flame graph from the investigation.  -Figure 1: Global view of the actual flame graph. Searching for `run_global_rules` produced 3 matches, none of which stood out in the full graph. The original profile contained 2,446 samples; process PIDs were removed from the screenshot. +Figure 1: Full view of the Lua on-CPU flame graph. Searching for `run_global_rules` produced 3 matches, none of which stood out in the full graph. The original profile contained 2,446 samples; process PIDs were removed from the screenshot. -In a flame graph, x-axis position does not imply order. Width reflects how many samples landed on a path. Ranked by Lua self time, the first shortlist looked like this: +In a flame graph, x-axis position does not imply order. Width reflects how many samples landed on a path. Ranked by Lua self time, the initial candidates were: | Candidate location | Lua self time | Initial assessment | |---|---:|---| @@ -65,19 +65,19 @@ This ranking has four blind spots: 1. When LuaJIT executes interpreted code, different Lua code paths may collapse into shared `lj_BC_*` and `lj_vm_*` symbols. 2. Compiled JIT traces cannot always be fully expanded by conventional stack unwinding, so observable JIT samples provide only a lower bound. 3. Costs such as table lookups, memory allocation, and garbage collection are attributed to C symbols rather than to the Lua lines that triggered them. -4. A call can change the caller's JIT state, making the resulting cost appear at the head of the caller function. +4. A call can change the caller's JIT state, making the resulting cost appear at the caller's function entry. -There was another clue: `run_global_rules` did not form one large column. It appeared across stacks from several request phases. No single occurrence was wide, but the combined cost could still be substantial. +There was another clue: `run_global_rules` did not appear as one obvious hotspot. It appeared across stacks from several request phases. No single occurrence was wide, but the combined cost could still be substantial. -## 3. Follow the Stack to See How 3% Gets Amplified +## 3. How a 3.0% Lua Self-Time Share Gets Amplified -Select a `run_global_rules` frame and follow the stack upward. The request-phase entry point sits at the bottom, followed by `common_phase`, Global Rule plugin filtering, dispatch, and finally individual plugin execution. +When we selected a `run_global_rules` frame and followed the stack upward, we saw the request-phase entry point at the bottom, followed by `common_phase`, Global Rule plugin filtering, dispatch, and finally individual plugin execution.  Figure 2: Interactive zoomed view after selecting one `run_global_rules` stack. The selected stack is stretched to fill the canvas, so its width is normalized and must not be interpreted as its share of total CPU time. Click the image to view it at full size. -Stack height does not represent elapsed time. It shows where the cost enters, who invokes it, and why it keeps coming back. +Stack height does not represent elapsed time. It shows where the cost enters, who invokes it, and why the path executes repeatedly. Before the fix, `run_global_rules()` called `_M.filter()` in several request phases. `_M.filter()` iterated through every loaded plugin and checked each one to determine whether it had been configured in the Global Rule: @@ -99,7 +99,7 @@ Two factors amplified the cost: 1. The cost of each filtering pass increased with the number of loaded plugins. 2. The same filtering result was regenerated across request phases. The `body_filter` and `delayed_body_filter` phases could also be entered multiple times for response-body chunks. -In this test configuration, one request triggered 9 filtering passes. The same request scanned more than 100 loaded plugins for the same small configured set 9 times. +In this test configuration, one request triggered 9 filtering passes. The same request scanned more than 100 loaded plugins 9 times to find the same small set of configured plugins. This explains why a Lua-level self time of 3.0% understated the cost of the entire path: @@ -108,29 +108,29 @@ This explains why a Lua-level self time of 3.0% understated the cost of the enti | The loop itself | Corresponding location in `plugin.lua` | | Large numbers of table lookups | `lj_BC_TGETS` | | Temporary table allocation | `lj_alloc_malloc` | -| Temporary object reclamation | `gc_sweep` | +| Garbage collection of temporary objects | `gc_sweep` | | Uncompiled interpreter dispatch | `lj_vm_*` / `lj_BC_*` | At 3% self time, this path looked minor. Following the stack showed that it sat on a shared path entered repeatedly. The fix was to reuse the filtered plugin set within the same request whenever the Global Rule and matched route had not changed, rather than rebuild it in every phase. -## 4. When the Flame Graph Doesn't Add Up, Check LuaJIT +## 4. When the Flame Graph Cannot Explain the Gap, Check LuaJIT -The second lead came from a custom observability component. Neither the component nor its logging bypass is part of APISIX OSS, but the failure mode matters to APISIX plugins and OpenResty extensions: a call that looks cheap can add direct cost and change whether subsequent caller code runs in the interpreter or as machine code. +The second lead came from a custom observability component. Neither the component nor its logging bypass is part of APISIX OSS, but the failure mode matters to APISIX plugins and OpenResty extensions: a seemingly inexpensive call can add direct cost and change how subsequent caller code executes—through the interpreter or as machine code. ### 4.1 Interpreter Dispatch Was Abnormally Active -After reclassifying the C-level samples by runtime category, the most notable signal was not any individual Lua line, but the relationship between interpreter execution and JIT execution: +After reclassifying the C-level samples by runtime category, the clearest signal was how much time appeared under interpreter dispatch compared with observable JIT execution: | Runtime category | CPU time per request | Share of samples | |---|---:|---:| | Interpreter dispatch: `lj_BC_*` / `lj_vm_*` | 5.86 μs | 29.6% | | Observable JIT trace execution | 2.55 μs | 12.9% | -JIT traces do not always unwind cleanly, so 12.9% is only a lower bound. Still, the amount of interpreter dispatch in the same environment was a strong signal that some high-frequency paths might not be running consistently as machine code. +JIT traces do not always unwind cleanly, so 12.9% is only a lower bound. Even so, interpreter dispatch remained high enough to suggest that some high-frequency paths might not be running consistently as machine code. More traces would not necessarily be better. Initialization code does not need to be compiled, and trace costs vary widely. Compilation results are worth investigating only when the CPU is saturated, the path is hot, and interpreter dispatch is unusually active. -### 4.2 `jit.v` Raised the Alarm—and Caused the First Misdiagnosis +### 4.2 What `jit.v` Revealed—and Why We Misread It With `jit.v` enabled, one short load test reported 417 successful trace compilations and 493 aborts. After aggregation by source location, a group of paths each stopped at exactly 11 aborts. @@ -146,7 +146,7 @@ At first, we read “0 appearances as a starting point” as “the whole functi ### 4.3 Correlate `start`, `stop`, and `abort` by Trace Start -To learn what failed to compile and why, we needed the event stream from LuaJIT itself. Store each `start` location by trace ID, then map the matching `stop` or `abort` back to that same starting point: +To learn what failed to compile and why, we needed the event stream from LuaJIT itself. We stored each `start` location by trace ID, then mapped the matching `stop` or `abort` back to that same starting point: ```lua -- Simplified illustration; actual callback arguments and parsing are more complex @@ -167,11 +167,11 @@ end, "trace") The real probe also needs `jit.util.funcinfo` to resolve source locations and `jit.vmdef.traceerr` to recover abort reasons. With that data, we can compare the component's enabled and disabled states: which starting points compile, which repeatedly abort, and whether a trace flush occurs. -In the LuaJIT build used here, the failure penalty started at 72 and doubled after each failure. It was 36,864 on the 10th failure and reached 73,728 on the 11th, above the 60,000 limit. Several starting points stopped at exactly 11 aborts and never entered the compiled set; no trace flush occurred during collection. The number of live traces in both test variants remained below the cache limit, ruling out trace-cache exhaustion. Together, the evidence showed that LuaJIT had abandoned fu [...] +In the LuaJIT build used here, the failure penalty started at 72 and doubled after each failure. It was 36,864 on the 10th failure and reached 73,728 on the 11th, above the 60,000 limit. Several starting points stopped at exactly 11 aborts and never entered the compiled set. No trace flush occurred during collection, and the number of live traces in both test variants remained below the cache limit, ruling out trace-cache exhaustion. Together, the evidence showed that LuaJIT had abandone [...] That still does not mean LuaJIT abandoned those functions entirely. Other parts could have been inlined into different traces. -When the data was grouped by caller, every affected phase-entry and orchestration function passed through the same custom logging bypass. When the log level was too low to emit output, this path still inspected the request phase, call stack, and request context. The added call did not produce a wide column of its own, but it changed the JIT outcome of its callers, making part of the cost appear at the heads of ordinary request-processing functions. +When the data was grouped by caller, every affected phase-entry and orchestration function passed through the same custom logging bypass. Even when the log level was too low to emit output, this path still inspected the request phase, call stack, and request context. The added call did not appear as an obvious hotspot. Instead, it changed the JIT outcome of its callers, making part of the cost appear at function entry in ordinary request-processing functions. ```lua -- Simplified custom extension, not an APISIX OSS implementation @@ -182,34 +182,34 @@ if log_level_is_suppressed then end ``` -The JIT data did two jobs: it exposed costs the flame graph could not attribute cleanly, and it showed that toggling the feature changed how hot paths executed. It still could not quantify the throughput loss. The goal was not to force every function to compile; it was to remove work that should never happen when the feature is disabled. +The JIT data exposed costs the flame graph could not attribute cleanly and confirmed that toggling the feature changed how hot paths executed. It still could not quantify the throughput loss. The relevant fix was not to force every function to compile, but to skip the unnecessary work entirely when the feature was disabled. -One more trap: install the probe before loading the module under observation. A module can capture a function reference during `require`; replacing that function later leaves the captured reference untouched. Our late probe saw 1 call per request. Moving it before `require("apisix")` exposed the real rate: 5 calls per request. +Probe placement also mattered. A module can capture a function reference during `require`; replacing that function later leaves the captured reference untouched. Our late probe saw 1 call per request. Moving it before `require("apisix")` exposed the real rate: 5 calls per request. ## 5. Use Paired A/B Tests to Measure the Impact -The flame graph identified candidate locations, the call stacks showed why costs repeated, and the LuaJIT events explained why some costs appeared elsewhere. We still needed paired A/B tests to measure the throughput impact. +The flame graph identified candidate locations, the call stacks showed why paths executed repeatedly, and the LuaJIT events explained why some CPU samples could not be attributed cleanly or were not visible in the flame graph. We still needed paired A/B tests to measure the throughput impact. -For the Global Rule path, we kept the same dispatch and configuration but returned immediately after entering the Prometheus business function. This helped distinguish the cost of the plugin's business logic from that of the shared path before plugin entry. To avoid presenting absolute RPS from a customized environment as an APISIX OSS benchmark, we normalized throughput with Prometheus disabled to 100: +For the Global Rule path, we kept the same dispatch and configuration but made the Prometheus handler return immediately at function entry. This helped distinguish the cost of the plugin's processing logic from that of the shared path before plugin entry. To avoid presenting absolute RPS from a customized environment as an APISIX OSS benchmark, we normalized throughput with Prometheus disabled to 100: | Internal A/B scenario | Relative throughput index | Relative to Prometheus disabled | |---|---:|---:| | Prometheus disabled | 100.0 | Baseline | -| Plugin and dispatch retained; business function returns immediately | 77.2 | -22.8% | +| Plugin and dispatch retained; Prometheus handler returns at entry | 77.2 | -22.8% | | Complete Prometheus Global Rule | 56.9 | -43.1% | -The gap remained even after short-circuiting the plugin's business code. The experiment did not identify a single expensive line, but it showed that metric calculation was not the only source of overhead. Together with the 9 filtering passes per request, the call stacks, and the C-level cost distribution, this result explained the throughput gap. +The gap remained even after short-circuiting the Prometheus processing code. The experiment did not identify a single expensive line, but it showed that metric calculation was not the only source of overhead. Together with the 9 filtering passes per request, the call stacks, and the C-level cost distribution, this result showed that repeated filtering and the shared pre-plugin path contributed materially to the throughput drop. -We used the same method for the custom observability component. With workload and configuration held constant, we collected compilation events, per-request call counts, throughput, and response correctness with the component on and off. JIT events explained why no wide new column appeared in the graph; the end-to-end A/B test measured the actual cost. +We used the same method for the custom observability component. With workload and configuration held constant, we collected compilation events, per-request call counts, throughput, and response correctness with the component on and off. JIT events explained why the feature did not appear as a single obvious hotspot in the flame graph; the end-to-end A/B test measured its effect on normalized throughput in this customized environment. -The investigation comes down to five steps: +The investigation can be summarized in five steps: | Step | Core question | Evidence | |---|---|---| | 1. Verify the worker is CPU-bound | Can the flame graph explain this regression? | Worker saturation, CPU pinning, upstream, network, and load-generator headroom, and stable reproduction | | 2. Compare widths | Where do samples accumulate? | Global flame graph and candidate ranking | | 3. Follow stacks | What multiplies a small local cost? | Request phases, shared functions, and per-request call counts | -| 4. Inspect LuaJIT | Why does cost appear elsewhere or go missing? | `start`, `stop`, `abort`, `flush`, and `jit.dump` | +| 4. Inspect LuaJIT | Why are some CPU samples misattributed or absent from the flame graph? | `start`, `stop`, `abort`, `flush`, and `jit.dump` | | 5. Run paired A/B tests | How large is the effect, and is it causal? | Throughput, latency, call counts, error rate, and response consistency | A few limits on what this shows: @@ -222,7 +222,7 @@ A few limits on what this shows: The flame graph was not wrong. Width showed where CPU samples accumulated, and call stacks showed how shared paths amplified the cost. But when that cost was attributed to interpreter symbols, JIT traces, the allocator, or caller functions, the graph no longer tied all of it back to the code that caused it. -When that happens, stop guessing which Lua line should be faster. Collect LuaJIT compilation events, count calls per request, and use paired A/B tests to measure the path's actual cost. The best optimization target is often not the widest column, but work that the evidence shows should not repeat at all. +When that happens, collect LuaJIT compilation events, count calls per request, and use paired A/B tests to measure the path's effect on normalized throughput in the same environment rather than infer the cause from individual Lua lines. In this investigation, the evidence pointed to eliminating unnecessary repeated work rather than simply optimizing the widest flame-graph path. ## References diff --git a/blog/zh/blog/2026/08/28/debugging-apisix-throughput-regression.md b/blog/zh/blog/2026/08/28/debugging-apisix-throughput-regression.md index cbe01895d43..51e4d1fe310 100644 --- a/blog/zh/blog/2026/08/28/debugging-apisix-throughput-regression.md +++ b/blog/zh/blog/2026/08/28/debugging-apisix-throughput-regression.md @@ -1,5 +1,5 @@ --- -title: "火焰图没撒谎，但没直接指出瓶颈在哪：一次 APISIX 吞吐回退排查" +title: "火焰图没撒谎，却没直接指出瓶颈：一次 APISIX 吞吐回退排查" authors: - name: "Xin Rong" title: "Author" @@ -15,43 +15,43 @@ keywords: - LuaJIT - 性能优化 - 吞吐回退 -description: "火焰图没有撒谎，却也没有直接指出 APISIX 吞吐回退的瓶颈。本文沿 CPU、调用栈和 LuaJIT 证据链逐步排查，并通过每请求调用次数和配对 A/B 实验，解释为什么最宽的热点未必最值得优化。" +description: "一次 APISIX 吞吐回退排查中，火焰图中最宽的热点无法解释全部回退。本文结合 CPU 采样、调用栈、LuaJIT 编译事件、每请求调用次数和配对 A/B 实验，说明如何识别被公共路径放大、却容易被热点排序忽略的性能成本。" tags: [Ecosystem] --- -火焰图没有撒谎，却也没有直接指出 APISIX 吞吐回退的瓶颈。本文沿 CPU、调用栈和 LuaJIT 证据链逐步排查，并通过每请求调用次数和配对 A/B 实验，解释为什么最宽的热点未必最值得优化。 +一次 APISIX 吞吐回退中，火焰图最宽的路径无法解释全部回退。另有两条值得追查的路径，其 Lua self time 在带 Lua 上下文的样本中分别只占 3.0% 和 3.9%。 <!--truncate--> -一次吞吐回退中，火焰图最宽的路径并不是最终瓶颈。真正值得追查的两个位置，在 Lua 采样里只有 3.0% 和 3.9%。如果按热点排序，它们根本进不了第一轮优化名单。 +按热点大小排序，这两个位置根本进不了第一轮优化名单。 -这次排查最有价值的不是某个补丁，而是一条证据链：先确认 CPU 确实是瓶颈，再横向看火焰图宽度，圈定候选位置。然后沿调用栈纵向追，看重复调用和公共路径如何放大成本；当火焰图解释不了端到端差距时，继续查 LuaJIT 编译与中断事件；最后用每请求调用次数和配对 A/B 实验定量。 +这次排查按以下顺序展开：先确认 CPU 确实是瓶颈，再根据火焰图宽度圈定候选位置；然后沿调用栈追查重复调用和公共路径如何放大成本；如果火焰图无法解释端到端差距，就继续检查 LuaJIT 编译与中断事件；最后通过每请求调用次数和配对 A/B 实验量化实际影响。 -> 数据范围：下文数据来自同一受控环境中的一个 APISIX 内部定制构建，其中加载了 100 余个插件。吞吐统一归一化，只用于说明定位方法与因果链，不代表 Apache APISIX OSS 在其他硬件、配置或负载下的通用表现。 +> 数据范围：下文数据来自同一受控环境中的一个 APISIX 内部定制构建，其中加载了 100 余个插件。文中的吞吐数据均经过归一化，只用于说明定位过程和判断依据，不代表 Apache APISIX OSS 在其他硬件、配置或负载下的通用表现。 -## 1. 先确认 CPU 瓶颈，而不是上来就看火焰图 +## 1. 先确认瓶颈是否在 CPU -火焰图显示的是采样期间 CPU 在执行什么。只有目标 worker 的 CPU 接近饱和、吞吐受这个核限制时，火焰图的宽度才能解释性能回退。 +火焰图显示的是采样期间 CPU 在执行什么。只有目标 worker 的 CPU 接近饱和、吞吐受这个核限制时，才能用火焰图的宽度解释这次性能回退。 我们在采样前固定了这些条件： - APISIX 单 worker 并绑定独占物理核； - 上游服务和压测端使用其他核，避免 CPU 争抢； - 请求模型、配置、响应内容保持一致； -- 吞吐回退可稳定复现，错误率和响应结果没有偏移； +- 吞吐回退可稳定复现，错误率稳定，响应结果一致； - 目标 worker 持续接近饱和，上游、网络、压测端仍有余量。 如果不满足这些前提，首先应该查连接、网络、上游或压测端，而不是在 on-CPU 火焰图里找答案。 -## 2. 横向看宽度，而不是排名 +## 2. 根据宽度筛选候选 我们使用 eBPF 以 500 Hz 同时采集 C 和 Lua 调用栈。下面是排查中的真实 Lua on-CPU 火焰图。 - + -*搜索 `run_global_rules` 后命中 3 处，但这些位置在整张图里并不醒目。原始采样共 2,446 个样本；截图已移除进程 PID。* +*图 1：Lua on-CPU 火焰图全局视图。搜索 `run_global_rules` 命中 3 处，但在整张图中并不醒目。原始采样共 2,446 个样本；截图已移除进程 PID。* -横向看火焰图，看的是宽度，不是 x 轴顺序。宽度越大，采样落在该路径上的次数越多。初步候选位置按 Lua self time 排序： +火焰图的 x 轴没有先后关系，真正有意义的是宽度：路径越宽，落在其中的样本越多。按 Lua self time 排序后，初步候选位置如下： | 候选位置 | Lua self time | 初判 | |---|---:|---| @@ -60,7 +60,7 @@ tags: [Ecosystem] | 自定义日志旁路 | 3.9% | 很容易被忽略 | | `run_global_rules` | 3.0% | 很容易被忽略 | -这里的 self time 指：在带 Lua 上下文的样本中，直接落在这个位置上的比例，不是总 CPU 占比。本次采样约 19.6% 的样本缺失 Lua 上下文，所以这些百分比只用于选候选，不能直接预测吞吐收益。 +这里的 self time 是指在带 Lua 上下文的样本中，直接落在这个位置上的比例，而不是总 CPU 占比。本次采样约有 19.6% 的样本缺失 Lua 上下文，所以这些百分比只用于筛选候选，不能直接预测吞吐收益。 这个排名有四个盲区： @@ -69,17 +69,17 @@ tags: [Ecosystem] 3. 表查找、内存分配、GC 等成本会记在 C 符号上，而不是触发的 Lua 行上。 4. 一个调用可能改变调用方的 JIT 状态，使成本看起来落在调用方函数的头上。 -`run_global_rules` 还有一个特征：它没有形成一根大柱子，而是散在多个请求阶段的调用栈里。单处不宽，不等于合起来不贵。 +`run_global_rules` 还有一个特征：它没有形成单个显著热点，而是散在多个请求阶段的调用栈里。单个位置都不宽，但累计成本可能并不低。 -## 3. 纵向沿栈看，3% 如何被公共路径放大 +## 3. 沿调用栈追查：3.0% 的 Lua self time 如何被放大 -选中某个 `run_global_rules` 方块后，纵向看调用栈：底部是请求阶段入口，向上经过 `common_phase`、Global Rule 插件筛选、调度，再到具体插件执行。 +选中某个 `run_global_rules` 方块并沿调用栈向上追踪，可以看到底部的请求阶段入口，以及后续的 `common_phase`、Global Rule 插件筛选、调度和具体插件执行。 - + -*所选栈会被重新铺满画布，因此图中的宽度已经归一化，不能再当作它占总 CPU 的比例。* +*图 2：选中一条 `run_global_rules` 调用栈后的放大视图。所选栈会被重新铺满画布，因此宽度已经归一化，不能视为其占总 CPU 的比例。点击图片可查看大图。* -纵向高度本身不代表耗时。它的作用是看清成本从哪里进入、被谁调用、为什么反复出现。 +调用栈的高度本身不代表耗时。沿栈展开可以看清成本从哪里进入、由谁调用，以及为什么会反复出现。 修复前，`run_global_rules()` 会在请求的多个阶段调用 `_M.filter()`。`_M.filter()` 遍历所有已加载插件，再逐个判断该插件是否被 Global Rule 配置： @@ -96,14 +96,14 @@ for _, plugin_obj in ipairs(local_plugins) do end ``` -两个放大器都在这里： +这段逻辑通过两个因素放大了成本： 1. 单次过滤的成本随已加载插件数量增长。 2. 相同过滤结果跨请求阶段重复生成；`body_filter` 与 `delayed_body_filter` 还可能按响应块多次进入。 -本次测试配置中，一个请求实际触发了 **9 次过滤**。也就是说，“从 100+ 插件中找出已配置的少量插件”这件事，同一个请求重复做了 9 次。 +本次测试配置中，一个请求实际触发了 **9 次过滤**。也就是说，同一个请求把“从 100 多个插件中找出已配置插件”这项工作重复做了 9 次。 -这解释了为什么 Lua 层 3.0% 会低估整条路径成本： +这也解释了为什么 Lua 层 3.0% 会低估整条路径成本： | 实际工作 | 火焰图常见归属 | |---|---| @@ -113,42 +113,42 @@ end | 临时对象回收 | `gc_sweep` | | 未编译解释器派发 | `lj_vm_*` / `lj_BC_*` | -横向看，它只是 3% 的候选；纵向看，才会发现它位于一条被反复进入的公共路径。优化方向也很直接：同一请求内，如果 Global Rule 和匹配路由没有变化，就复用已筛选的插件集合，而不是每个阶段重新生成。 +虽然 self time 只有 3%，但调用栈表明它位于一条会被反复进入的公共路径。对应的优化方式是：同一请求内，只要 Global Rule 和匹配路由没有变化，就复用已筛选的插件集合，而不是在每个阶段重新生成。 ## 4. 火焰图解释不了差距时，查 LuaJIT 编译事件 -第二条路径来自自定义观测组件。它和日志旁路不属于 APISIX OSS，但揭示的问题对 APISIX 插件和 OpenResty 扩展有参考价值：一次看似很轻的调用，既可能产生直接成本，也可能改变调用方之后是以解释器还是以机器码运行。 +第二条路径来自自定义观测组件。它和日志旁路不属于 APISIX OSS，但揭示的问题对 APISIX 插件和 OpenResty 扩展有参考价值：一次看似开销不大的调用，不仅会产生直接成本，还可能改变调用方后续代码的执行方式，使其由解释器执行或以机器码运行。 ### 4.1 解释器派发异常活跃 -把 C 层样本按运行时类型重新分类，最值得注意的不是某行 Lua，而是解释器与 JIT 的关系： +把 C 层样本按运行时类型重新分类后，最明显的信号来自解释器执行与 JIT 执行的比例： | 运行类别 | 每请求 CPU 时间 | 占本次样本 | |---|---:|---:| | 解释器派发：`lj_BC_*` / `lj_vm_*` | 5.86 μs | 29.6% | | 可观察到的 JIT trace 执行 | 2.55 μs | 12.9% | -JIT trace 难以完整 unwind，12.9% 只能看作下界。但在同一环境中，解释器派发如此活跃，已经构成强信号：某些高频路径可能没有稳定地跑在机器码里。 +JIT trace 的调用栈不一定能完整 unwind，因此 12.9% 只能视为下界。即便如此，同一环境中的解释器派发占比仍然很高，说明某些高频路径可能没有稳定运行在机器码中。 -这不等于 trace 越多越好。初始化代码不需要追求编译，不同 trace 的成本差异也很大。只有在 CPU 饱和、路径高频、解释器派发异常时，编译结果才值得深挖。 +trace 数量并非越多越好。初始化代码不需要追求编译，不同 trace 的成本差异也很大。只有在 CPU 饱和、路径高频、解释器派发异常时，编译结果才值得深入检查。 -### 4.2 `jit.v` 发出警报，也制造了第一次误判 +### 4.2 `jit.v` 暴露异常，也导致了第一次误判 -开启 `jit.v` 后，一次短时压测输出中看到 417 次 trace 编译成功、493 次 abort。按位置聚合后，一批路径的 abort 次数整齐停在 11。 +开启 `jit.v` 后，一次短时压测记录了 417 次 trace 编译成功和 493 次 abort。按位置聚合后，一批路径的 abort 次数都停在 11。 -但这是编译事件数，不是去重后的函数个数、覆盖率或 CPU 时间。`jit.v` 有几个边界： +但这些数字是编译事件次数，不是去重后的函数个数、覆盖率或 CPU 时间。使用 `jit.v` 时还要注意： - abort 行显示的是 trace 中断位置，而惩罚记在 trace 起点，两者可能不是同一行。 - 某函数从未成为 trace 起点，不代表它没有被编译，函数体可能已被内联进父 trace。 -- 文本日志很难在功能开启和关闭两组结果之间做稳定的集合比较。 +- 仅凭文本日志，很难稳定比较功能开启和关闭两组结果的差异。 -我们一开始也把“起点出现次数为 0”误读成“整个函数都在解释执行”。后来用 `jit.dump` 字节码模式复核，才发现多个函数入口没有成为 root trace，但函数体已多次进入其他 trace。真正反复失败的是阶段入口和编排函数。 +我们一开始把“起点出现次数为 0”误读成“整个函数都在解释执行”。后来用 `jit.dump` 字节码模式复核后发现，多个函数入口虽然没有成为 root trace，但函数体已多次进入其他 trace。真正反复失败的是阶段入口和编排函数。 > 看不到 trace 起点，只能证明这里没有成为 root trace 锚点；不能证明整个函数没有进入机器码。 -### 4.3 把 `start`、`stop`、`abort` 归回同一起点 +### 4.3 按 trace 起点关联 `start`、`stop` 和 `abort` -要回答“哪段代码没有编译、为什么”，需要让 LuaJIT 自己交事件流。核心做法是按 trace id 保存 `start` 的位置，再把后续 `stop` 或 `abort` 归回同一个起点： +要确认哪段代码没有编译以及原因，需要直接采集 LuaJIT 的事件流。具体做法是按 trace id 保存 `start` 的位置，再把后续 `stop` 或 `abort` 关联到同一个起点： ```lua -- 简化示意，实际回调参数和解析逻辑更复杂 @@ -167,13 +167,13 @@ jit.attach(function(what, trace_id, func, pc, err_code) end, "trace") ``` -实际探针还要用 `jit.util.funcinfo` 解析源位置，用 `jit.vmdef.traceerr` 还原 abort 原因。这样就能比较开启和关闭自定义组件时的差异：哪些起点进入 compiled 集合，哪些反复 abort，以及是否发生 trace flush。 +实际探针还要用 `jit.util.funcinfo` 解析源位置，用 `jit.vmdef.traceerr` 还原 abort 原因。这样就能比较自定义组件开启和关闭时的差异：哪些起点进入 compiled 集合，哪些反复 abort，以及是否发生 trace flush。 -在本次 LuaJIT 构建中，失败惩罚从 72 开始逐次翻倍：第 10 次是 36,864，第 11 次达到 73,728，超过 60,000 上限。多个起点的 abort 次数恰好停在 11 次，之后不再增加；它们没有进入 compiled 集合，采集期间也没有 trace flush。两组存活 trace 数均低于缓存上限，因此排除了 trace 缓存被挤爆的可能。这些证据共同说明：LuaJIT 已经放弃编译这些 trace 起点。 +在本次 LuaJIT 构建中，失败惩罚从 72 开始逐次翻倍：第 10 次是 36,864，第 11 次达到 73,728，超过 60,000 上限。多个起点的 abort 次数恰好停在 11 次，之后不再增加，也没有进入 compiled 集合；采集期间未发生 trace flush。两组存活 trace 数均低于缓存上限，因此可以排除 trace 缓存被挤爆的可能。这些证据说明，LuaJIT 已经放弃继续编译这些 trace 起点。 -仍然不能扩大结论：被放弃的是 trace 起点，不一定是整个函数体；其他部分仍可能被内联进别的 trace。 +这并不意味着整个函数体都被放弃；函数的其他部分仍可能被内联进别的 trace。 -按调用来源聚合后，受影响的阶段入口和编排函数都经过同一条自定义日志旁路：日志级别不足时虽不输出，但仍会检查请求阶段、调用栈和请求上下文。新增调用本身没有形成大柱子，却改变了调用方的 JIT 结果，使部分成本看起来落在正常请求函数头上。 +按调用来源聚合后，受影响的阶段入口和编排函数都经过同一条自定义日志旁路。即使日志级别不足、不产生输出，这条路径仍会检查请求阶段、调用栈和请求上下文。新增调用本身没有形成显著热点，但它改变了调用方的 JIT 结果，使部分成本看起来落在正常请求处理函数的入口处。 ```lua -- 自定义扩展的简化示意，不是 APISIX OSS 实现 @@ -184,47 +184,47 @@ if log_level_is_suppressed then end ``` -JIT 数据在这里承担两个职责：发现火焰图无法正确归属的成本，验证功能开关确实改变了高频路径的执行状态。但它不能直接告诉我们吞吐损失多大；真正的方向也不是“强迫所有函数编译”，而是让关闭状态下本来不该发生的工作根本不执行。 +JIT 数据既能发现火焰图无法正确归属的成本，也能验证功能开关确实改变了高频路径的执行状态。但这些数据不能直接量化吞吐损失；优化目标也不是“强迫所有函数编译”，而是在功能关闭时彻底跳过本不该发生的工作。 -还有一个容易让结论失真的陷阱：探针必须装在被观测模块加载之前。如果模块在 `require` 时保存了函数引用，之后替换原函数，计数器只能看到少量没被快照走的调用。本次探针注入较晚时测到 1 次/请求；把它前移到 `require("apisix")` 之前，才确认真实值是 5 次/请求。 +探针的安装时机也会影响结论。探针必须装在被观测模块加载之前；如果模块在 `require` 时保存了函数引用，之后替换原函数，计数器只能看到少量仍然经过替换后函数的调用。本次探针注入较晚时测到 1 次/请求；把它前移到 `require("apisix")` 之前，才确认真实值是 5 次/请求。 -## 5. 用配对 A/B 定量：这条路径到底值多少 +## 5. 用配对 A/B 实验量化吞吐影响 -火焰图给位置，调用栈给放大链，LuaJIT 事件解释错位成本。最终还要靠配对实验定量。 +火焰图用于定位可疑路径，调用栈揭示成本如何被放大，LuaJIT 事件解释部分 CPU 样本为何无法准确归属或未出现在火焰图中。最终还需要通过配对 A/B 实验量化这些路径对吞吐的影响。 -以 Global Rule 路径为例，我们保留相同的调度和配置，只让 Prometheus 业务函数进入后立即返回，用来区分“插件业务逻辑慢”和“进入插件前的公共路径慢”。为避免把定制环境的绝对 RPS 当成 APISIX OSS benchmark，我们把关闭 Prometheus 时的吞吐归一化为 100： +以 Global Rule 路径为例，我们保留相同的调度和配置，只让 Prometheus 处理函数在入口处立即返回，用来区分“插件处理逻辑慢”和“进入插件前的公共路径慢”。为避免把定制环境的绝对 RPS 当成 APISIX OSS benchmark，我们把关闭 Prometheus 时的吞吐归一化为 100： | 内部 A/B 场景 | 相对吞吐指数 | 相对关闭 Prometheus | |---|---:|---:| | 关闭 Prometheus | 100.0 | 基准 | -| 保留插件与调度，业务函数立即返回 | 77.2 | -22.8% | +| 保留插件与调度，Prometheus 处理函数在入口处返回 | 77.2 | -22.8% | | 完整 Prometheus Global Rule | 56.9 | -43.1% | -即使插件业务代码被短路，差距仍然显著。这个实验不能把成本定位到某一行，但足以证明损耗不只来自指标计算，进入插件前的公共路径本身就值得追查。再结合每请求 9 次过滤、纵向调用栈和 C 层成本分布，这条放大链才算说得通。 +即使 Prometheus 处理代码被短路，差距仍然显著。这个实验不能把成本定位到某一行，但足以证明损耗不只来自指标计算，进入插件前的公共路径本身就值得追查。结合每请求 9 次过滤、调用栈和 C 层成本分布，可以判断重复过滤和插件执行前的公共路径是吞吐回退的重要影响因素。 -自定义观测组件也用同样方法：保持负载与配置一致，分别采集开启和关闭下的编译事件、每请求调用次数、吞吐和响应正确性。JIT 事件解释“为什么图上没有足够宽的新柱子”，端到端 A/B 回答“这条路径到底值多少钱”。 +自定义观测组件也采用同样的方法：保持负载和配置不变，分别在开启和关闭组件时采集编译事件、每请求调用次数、吞吐和响应正确性。JIT 事件用于解释为什么该功能没有在火焰图中表现为单个显著热点，端到端 A/B 实验则用于量化这条路径在本次定制环境中对归一化吞吐的影响。 -整个排查可以压缩成五步： +整个排查过程可以归纳为五步： | 步骤 | 核心问题 | 证据 | |---|---|---| | 1. 确认 CPU 前提 | 火焰图能否解释这次回退？ | worker 饱和、绑核、上下游余量、稳定复现 | -| 2. 横向看宽度 | 样本主要落在哪里？ | 全局火焰图与候选排序 | -| 3. 纵向沿栈看 | 小成本为何被放大？ | 调用阶段、公共函数、每请求调用次数 | -| 4. 检查 LuaJIT | 成本为何错位或消失？ | `start`、`stop`、`abort`、`flush` 与 `jit.dump` | -| 5. 配对 A/B 定量 | 真实量级与因果是什么？ | 吞吐、延迟、调用次数、错误率与响应一致性 | +| 2. 根据宽度筛选候选 | 样本主要落在哪些路径？ | 全局火焰图与候选排序 | +| 3. 沿调用栈追查 | 小成本为什么会被放大？ | 调用阶段、公共函数、每请求调用次数 | +| 4. 检查 LuaJIT | 部分 CPU 样本为何无法准确归属或未出现在火焰图中？ | `start`、`stop`、`abort`、`flush` 与 `jit.dump` | +| 5. 用配对 A/B 量化 | 实际影响有多大，因果关系是否成立？ | 吞吐、延迟、调用次数、错误率与响应一致性 | -这些结论必须留在明确边界内： +使用这些结论时还需注意以下限制： - 火焰图宽度、Lua self time 与吞吐变化的分母不同，不能直接相减或相除。 - 自定义观测组件不属于 APISIX OSS，只用于说明自定义扩展可能遇到的通用问题。 -- 29.6%、12.9%、417、493 和 abort ×11 都属于本次构建和采集窗口，不能外推。 +- 29.6%、12.9%、417、493 和 abort ×11 仅适用于本次构建和采集窗口，不能外推。 - “没有成为 trace 起点”不等于“函数没有编译”，必须检查函数体是否进入其他 trace。 -- JIT 编译结果是定位信号，不是最终性能指标；优化仍需验证吞吐、延迟、错误率、响应内容和资源回收。 +- JIT 编译结果是定位信号，不是最终性能指标；优化后仍需验证吞吐、延迟、错误率、响应内容和 GC 行为。 -火焰图没有撒谎。宽度告诉我们 CPU 样本聚集在哪，调用栈告诉我们这些成本如何被公共路径放大。但成本一旦被记到解释器符号、JIT trace、内存分配器或者调用方头上，火焰图给出的归属就不再完整。 +火焰图的宽度能显示 CPU 样本的聚集位置，调用栈能显示公共路径如何放大成本。但当成本被记到解释器符号、JIT trace、内存分配器或调用方函数的入口处时，火焰图就无法把所有成本都对应到真正触发它们的代码。 -这时候最有效的做法不是继续猜哪行 Lua 应该更快，而是让 LuaJIT 交出编译事件，再用每请求调用次数和配对 A/B 实验把这条路径的真实开销测出来。最终值得优化的，往往不是最宽的柱子，而是那些有证据表明根本不需要反复执行的工作。 +遇到这种情况，应直接采集 LuaJIT 编译事件，再结合每请求调用次数和配对 A/B 实验，量化这条路径在同一环境中对归一化吞吐的影响，而不是仅凭单行 Lua 代码推断原因。本次排查的证据表明，应优先消除不必要的重复工作，而不是只处理火焰图中最宽的路径。 ## 参考资料
