diff --git a/changelog/unreleased/kong/feat-request-debguger-finer-resolution-and-total-latency.yml b/changelog/unreleased/kong/feat-request-debguger-finer-resolution-and-total-latency.yml new file mode 100644 index 000000000000..ae866b6c68d2 --- /dev/null +++ b/changelog/unreleased/kong/feat-request-debguger-finer-resolution-and-total-latency.yml @@ -0,0 +1,7 @@ +message: | + Improved the output of the request debugger: + - Now the resolution of field `total_time` is microseconds. + - A new field `total_time_without_upstream` on the top level shows the latency only introduced by Kong. +type: feature +scope: Core + diff --git a/kong/timing/context.lua b/kong/timing/context.lua index 2df5f5ec52bf..659f3fcb4713 100644 --- a/kong/timing/context.lua +++ b/kong/timing/context.lua @@ -8,7 +8,7 @@ local setmetatable = setmetatable local table_insert = table.insert local table_remove = table.remove -local get_cur_msec = require("kong.tools.time").get_updated_monotonic_ms +local time_ns = require("kong.tools.time").time_ns local assert = assert @@ -29,14 +29,13 @@ function _M:enter_subcontext(name) end self.current_subcontext = self.current_subcontext.child[name] - self.current_subcontext.____start____ = get_cur_msec() + self.current_subcontext.____start____ = time_ns() end function _M:leave_subcontext(attributes) assert(#self.sub_context_stack > 0, "subcontext stack underflow") - - local elapsed = get_cur_msec() - self.current_subcontext.____start____ + local elapsed = (time_ns() - self.current_subcontext.____start____) / 1e6 local old_total_time = self.current_subcontext.total_time or 0 self.current_subcontext.total_time = old_total_time + elapsed self.current_subcontext.____start____ = nil @@ -75,11 +74,38 @@ function _M:set_root_context_prop(k, v) end +function _M:finalize(subcontext) + -- finalize total_time optionally rounding to the nearest integer + -- if greater than 1ms. + if subcontext.total_time then + -- round to 2 decimal places + subcontext.total_time = math_floor(subcontext.total_time * 100) / 100 + end + + if subcontext.child then + for _, child in pairs(subcontext.child) do + self:finalize(child) + end + end +end + + +function _M:get_total_time_without_upstream() + local total_time = 0 + for k, child in pairs(self.root_context.child) do + if k ~= "upstream" and child.total_time then + total_time = total_time + child.total_time + end + end + return total_time +end + + function _M:to_json() local dangling = nil -- `> 1` means we have at least one subcontext (the root context) - -- We always call this function at then end of the header_filter and + -- We always call this function at then end of the header_filter and -- log phases, so we should always have at least one subcontext. while #self.sub_context_stack > 1 do self:set_context_prop("dangling", true) @@ -92,6 +118,8 @@ function _M:to_json() end self:set_root_context_prop("dangling", dangling) + self:finalize(self.root_context) + self.root_context.total_time_without_upstream = self:get_total_time_without_upstream() return assert(cjson.encode(self.root_context)) end