Skip to content

Commit 7f0e06f

Browse files
committed
feat(batch-processor): add max_buffer_bytes to bound buffered/in-flight memory
Logger plugins buffer log entries (which may hold full request/response bodies) until the sink drains them. The batch processor only bounded the per-batch entry count, not total bytes nor the number of in-flight batches, so a slow sink combined with large bodies let the backlog grow until OOM (#11244). Add an opt-in max_buffer_bytes budget (default 0 = disabled, preserving the previous behaviour) that caps the bytes held by a processor across both buffered and in-flight entries. When exceeded, new entries are dropped with a warning and counted via a new batch_process_dropped_entries metric so operators can alert on log loss.
1 parent c205da9 commit 7f0e06f

3 files changed

Lines changed: 178 additions & 4 deletions

File tree

apisix/utils/batch-processor-manager.lua

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -142,6 +142,7 @@ function _M:add_entry_to_new_processor(conf, entry, ctx, func, max_pending_entri
142142
retry_delay = conf.retry_delay,
143143
buffer_duration = conf.buffer_duration,
144144
inactive_timeout = conf.inactive_timeout,
145+
max_buffer_bytes = conf.max_buffer_bytes,
145146
route_id = ctx.var.route_id,
146147
server_addr = ctx.var.server_addr,
147148
}

apisix/utils/batch-processor.lua

Lines changed: 103 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -29,6 +29,7 @@ local batch_processor_mt = {
2929
local execute_func
3030
local create_buffer_timer
3131
local batch_metrics
32+
local batch_dropped_metrics
3233
local prometheus
3334
if ngx.config.subsystem == "http" then
3435
prometheus = require("apisix.plugins.prometheus.exporter")
@@ -44,6 +45,15 @@ local schema = {
4445
buffer_duration = {type = "integer", minimum = 1, default= 60},
4546
inactive_timeout = {type = "integer", minimum = 1, default= 5},
4647
batch_max_size = {type = "integer", minimum = 1, default= 1000},
48+
-- Upper bound, in bytes, on the data buffered by this processor
49+
-- (entries waiting in the buffer plus those still in-flight to the
50+
-- sink). When exceeded, new entries are dropped with a warning instead
51+
-- of being buffered. 0 (default) disables the check, preserving the
52+
-- previous count-only behaviour. This caps memory when entries are
53+
-- large (e.g. logging big response bodies) and the sink cannot keep up,
54+
-- which otherwise lets the in-flight backlog grow without bound. See
55+
-- apache/apisix#11244.
56+
max_buffer_bytes = {type = "integer", minimum = 0, default = 0},
4757
}
4858
}
4959
batch_processor.schema = schema
@@ -76,6 +86,24 @@ local function set_metrics(self, count)
7686
end
7787

7888

89+
-- count an entry dropped because max_buffer_bytes was exceeded, so operators
90+
-- can alert on log loss. Registered lazily (same pattern as batch_metrics) and
91+
-- recorded even without route_id/server_addr (e.g. global rules) via fallbacks.
92+
local function incr_dropped_metric(self)
93+
if not (prometheus and prometheus.get_prometheus()) then
94+
return
95+
end
96+
if not batch_dropped_metrics then
97+
batch_dropped_metrics = prometheus.get_prometheus():counter(
98+
"batch_process_dropped_entries",
99+
"dropped entries because max_buffer_bytes was exceeded",
100+
{"name", "route_id", "server_addr"})
101+
end
102+
batch_dropped_metrics:inc(1,
103+
{self.name or "", self.route_id or "", self.server_addr or ""})
104+
end
105+
106+
79107
local function slice_batch(batch, n)
80108
local slice = {}
81109
local idx = 1
@@ -87,6 +115,41 @@ local function slice_batch(batch, n)
87115
end
88116

89117

118+
-- Approximate the in-memory footprint of an entry by summing the byte length
119+
-- of its string leaves (the dominant cost for log entries is the request /
120+
-- response body strings). Numbers/booleans are counted as a small fixed size
121+
-- and the walk is depth-bounded to stay cheap and cycle-safe.
122+
local function estimate_entry_bytes(v, depth)
123+
local t = type(v)
124+
if t == "string" then
125+
return #v
126+
elseif t == "number" then
127+
return 8
128+
elseif t == "boolean" then
129+
return 1
130+
elseif t == "table" and (depth or 0) < 8 then
131+
local n = 0
132+
for k, val in pairs(v) do
133+
n = n + estimate_entry_bytes(k, (depth or 0) + 1)
134+
+ estimate_entry_bytes(val, (depth or 0) + 1)
135+
end
136+
return n
137+
end
138+
return 0
139+
end
140+
141+
142+
-- Release the bytes accounted for a batch once it leaves the buffer/in-flight
143+
-- accounting (processed successfully or dropped). Clamped at 0 so accounting
144+
-- drift can never make the budget reject forever.
145+
local function release_bytes(self, bytes)
146+
self.buffer_bytes = self.buffer_bytes - (bytes or 0)
147+
if self.buffer_bytes < 0 then
148+
self.buffer_bytes = 0
149+
end
150+
end
151+
152+
90153
function execute_func(premature, self, batch)
91154
-- In case of "err" and a valid "first_fail" batch processor considers, all first_fail-1
92155
-- entries have been successfully consumed and hence reschedule the job for entries with
@@ -98,24 +161,35 @@ function execute_func(premature, self, batch)
98161
#batch.entries + 1 - first_fail, "/", #batch.entries ,"]: ", err)
99162
batch.entries = slice_batch(batch.entries, first_fail)
100163
self.processed_entries = self.processed_entries + first_fail - 1
164+
-- the successfully consumed prefix is gone; re-account the bytes
165+
-- still held by the remaining (to-be-retried) entries.
166+
local remaining = 0
167+
for _, e in ipairs(batch.entries) do
168+
remaining = remaining + estimate_entry_bytes(e)
169+
end
170+
release_bytes(self, (batch.bytes or 0) - remaining)
171+
batch.bytes = remaining
101172
else
102173
core.log.error("Batch Processor[", self.name,
103174
"] failed to process entries: ", err)
104175
end
105176

106177
batch.retry_count = batch.retry_count + 1
107178
if batch.retry_count <= self.max_retry_count and #batch.entries > 0 then
179+
-- still in-flight: its bytes stay accounted until it terminates
108180
schedule_func_exec(self, self.retry_delay,
109181
batch)
110182
else
111183
self.processed_entries = self.processed_entries + #batch.entries
184+
release_bytes(self, batch.bytes)
112185
core.log.error("Batch Processor[", self.name,"] exceeded ",
113186
"the max_retry_count[", batch.retry_count,
114187
"] dropping the entries")
115188
end
116189
return
117190
end
118191
self.processed_entries = self.processed_entries + #batch.entries
192+
release_bytes(self, batch.bytes)
119193
core.log.debug("Batch Processor[", self.name,
120194
"] successfully processed the entries")
121195
end
@@ -175,23 +249,46 @@ function batch_processor:new(func, config)
175249
batch_max_size = config.batch_max_size,
176250
retry_delay = config.retry_delay,
177251
name = config.name,
252+
max_buffer_bytes = config.max_buffer_bytes,
178253
batch_to_process = {},
179-
entry_buffer = {entries = {}, retry_count = 0},
254+
entry_buffer = {entries = {}, retry_count = 0, bytes = 0},
180255
is_timer_running = false,
181256
first_entry_t = 0,
182257
last_entry_t = 0,
183258
route_id = config.route_id,
184259
server_addr = config.server_addr,
185-
processed_entries = 0
260+
processed_entries = 0,
261+
-- bytes currently held by this processor: buffered entries plus those
262+
-- still in-flight to the sink. Used to enforce max_buffer_bytes.
263+
buffer_bytes = 0,
264+
dropped_entries = 0,
186265
}
187266

188267
return setmetatable(processor, batch_processor_mt)
189268
end
190269

191270
function batch_processor:push(entry)
271+
-- enforce the byte budget before buffering: when the data already held
272+
-- (buffered + in-flight) plus this entry would exceed max_buffer_bytes,
273+
-- drop the entry instead of letting the backlog grow without bound.
274+
local entry_bytes
275+
if self.max_buffer_bytes and self.max_buffer_bytes > 0 then
276+
entry_bytes = estimate_entry_bytes(entry)
277+
if self.buffer_bytes + entry_bytes > self.max_buffer_bytes then
278+
self.dropped_entries = self.dropped_entries + 1
279+
incr_dropped_metric(self)
280+
core.log.error("Batch Processor[", self.name, "] max_buffer_bytes[",
281+
self.max_buffer_bytes, "] exceeded (held ", self.buffer_bytes,
282+
" + entry ", entry_bytes, "), dropping entry; total dropped: ",
283+
self.dropped_entries)
284+
return
285+
end
286+
end
287+
192288
-- if the batch size is one then immediately send for processing
193289
if self.batch_max_size == 1 then
194-
local batch = {entries = {entry}, retry_count = 0}
290+
self.buffer_bytes = self.buffer_bytes + (entry_bytes or 0)
291+
local batch = {entries = {entry}, retry_count = 0, bytes = entry_bytes or 0}
195292
schedule_func_exec(self, 0, batch)
196293
return
197294
end
@@ -205,6 +302,8 @@ function batch_processor:push(entry)
205302

206303
local entries = self.entry_buffer.entries
207304
table.insert(entries, entry)
305+
self.buffer_bytes = self.buffer_bytes + (entry_bytes or 0)
306+
self.entry_buffer.bytes = self.entry_buffer.bytes + (entry_bytes or 0)
208307
set_metrics(self, #entries)
209308

210309
if #entries == 1 then
@@ -230,7 +329,7 @@ function batch_processor:process_buffer()
230329
core.log.debug("transferring buffer entries to processing pipe line, ",
231330
"buffercount[", #self.entry_buffer.entries ,"]")
232331
self.batch_to_process[#self.batch_to_process + 1] = self.entry_buffer
233-
self.entry_buffer = {entries = {}, retry_count = 0}
332+
self.entry_buffer = {entries = {}, retry_count = 0, bytes = 0}
234333
set_metrics(self, 0)
235334
end
236335

t/utils/batch-processor.t

Lines changed: 74 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -531,3 +531,77 @@ GET /t
531531
--- response_body
532532
done
533533
--- wait: 2
534+
535+
536+
537+
=== TEST 14: max_buffer_bytes caps buffered data and drops excess entries
538+
# Regression for apache/apisix#11244: with large entries the buffer must be
539+
# bounded by bytes, not only by entry count. A large batch_max_size keeps the
540+
# entries in the buffer (no flush), so the byte budget alone decides admission.
541+
--- config
542+
location /t {
543+
content_by_lua_block {
544+
local Batch = require("apisix.utils.batch-processor")
545+
local func_to_send = function() return true end
546+
local config = {
547+
max_retry_count = 0,
548+
batch_max_size = 1000, -- large, so entries stay buffered
549+
buffer_duration = 60,
550+
inactive_timeout = 60,
551+
retry_delay = 0,
552+
max_buffer_bytes = 1000, -- ~1 entry of 604 bytes fits
553+
}
554+
local log_buffer, err = Batch:new(func_to_send, config)
555+
if not log_buffer then ngx.say(err); return end
556+
557+
-- each entry ~= #"data"(4) + 600 = 604 bytes
558+
for i = 1, 5 do
559+
log_buffer:push({ data = string.rep("x", 600) })
560+
end
561+
562+
ngx.say("buffered=", #log_buffer.entry_buffer.entries)
563+
ngx.say("dropped=", log_buffer.dropped_entries)
564+
ngx.say("within_budget=", tostring(log_buffer.buffer_bytes <= 1000))
565+
}
566+
}
567+
--- request
568+
GET /t
569+
--- response_body
570+
buffered=1
571+
dropped=4
572+
within_budget=true
573+
--- wait: 0.5
574+
575+
576+
577+
=== TEST 15: max_buffer_bytes unset (default 0) preserves prior unbounded behavior
578+
--- config
579+
location /t {
580+
content_by_lua_block {
581+
local Batch = require("apisix.utils.batch-processor")
582+
local func_to_send = function() return true end
583+
local config = {
584+
max_retry_count = 0,
585+
batch_max_size = 1000,
586+
buffer_duration = 60,
587+
inactive_timeout = 60,
588+
retry_delay = 0,
589+
-- max_buffer_bytes omitted -> default 0 -> disabled
590+
}
591+
local log_buffer, err = Batch:new(func_to_send, config)
592+
if not log_buffer then ngx.say(err); return end
593+
594+
for i = 1, 5 do
595+
log_buffer:push({ data = string.rep("x", 600) })
596+
end
597+
598+
ngx.say("buffered=", #log_buffer.entry_buffer.entries)
599+
ngx.say("dropped=", log_buffer.dropped_entries)
600+
}
601+
}
602+
--- request
603+
GET /t
604+
--- response_body
605+
buffered=5
606+
dropped=0
607+
--- wait: 0.5

0 commit comments

Comments
 (0)