Skip to content

Commit

Permalink
feat(request-debugging): Finer time resolution and latency in total
Browse files Browse the repository at this point in the history
Using `time_ns` to measure the context duration and introduced a field
`total_time_without_upstream` to represent total latency without upstream.

KAG-4733
  • Loading branch information
Oyami-Srk committed Sep 19, 2024
1 parent dd72007 commit 6cb9dd8
Show file tree
Hide file tree
Showing 2 changed files with 39 additions and 5 deletions.
Original file line number Diff line number Diff line change
@@ -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

37 changes: 32 additions & 5 deletions kong/timing/context.lua
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand All @@ -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
Expand Down Expand Up @@ -75,11 +74,37 @@ function _M:set_root_context_prop(k, v)
end


function _M:finalize(subcontext)
-- finalize total_time optionally rounding to the nearest integer
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)
Expand All @@ -92,6 +117,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

Expand Down

0 comments on commit 6cb9dd8

Please sign in to comment.