feat(request-debugging): Finer time resolution and latency in total

Using `time_ns` to measure the context duration and introduced a field
`total_time_without_upstream` to represent total latency without upstream.

KAG-4733

changelog/unreleased/kong/feat-request-debguger-finer-resolution-and-total-latency.yml

@@ -0,0 +1,6 @@
+message: |
+  Improve the latency resolution of the request debugger from milliseconds to microseconds when latency is lower than 1ms.
+  Add a new field `total_time_without_upstream` to request debugger output to show the total latency of the request without upstream latency.
+type: feature
+scope: Core
+

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,44 @@ 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
+    if subcontext.total_time >= 1 then
+      -- round to the nearest integer
+      subcontext.total_time = math_floor(subcontext.total_time + 0.5)
+
+    else
+      -- round to 2 decimal places
+      subcontext.total_time = math_floor(subcontext.total_time * 100) / 100
+    end
+  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 +124,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