fix(logging) include 'balancer_by_lua' latency (#2494)

Kong · Jun 23, 2017 · e27a7d6 · e27a7d6
1 parent 91a9d6f
commit e27a7d6
Show file tree

Hide file tree

Showing 3 changed files with 33 additions and 9 deletions.
diff --git a/kong/core/handler.lua b/kong/core/handler.lua
@@ -113,7 +113,6 @@ return {
         send_timeout         = api.upstream_send_timeout or 60000,
         read_timeout         = api.upstream_read_timeout or 60000,
         -- ip                = nil,            -- final target IP address
-        -- failures          = nil,            -- for each failure an entry { name = "...", code = xx }
         -- balancer          = nil,            -- the balancer object, in case of a balancer
         -- hostname          = nil,            -- the hostname belonging to the final target IP
       }
@@ -183,6 +182,26 @@ return {
       ctx.KONG_PROXIED = true
     end
   },
+  balancer = {
+    before = function()
+      local addr = ngx.ctx.balancer_address
+      local current_try = addr.tries[addr.try_count]
+      current_try.balancer_start = get_now()
+    end,
+    after = function ()
+      local ctx = ngx.ctx
+      local addr = ctx.balancer_address
+      local current_try = addr.tries[addr.try_count]
+
+      -- record try-latency
+      local try_latency = get_now() - current_try.balancer_start
+      current_try.balancer_latency = try_latency
+      current_try.balancer_start = nil
+
+      -- record overall latency
+      ctx.KONG_BALANCER_TIME = (ctx.KONG_BALANCER_TIME or 0) + try_latency
+    end
+  },
   header_filter = {
     before = function()
       local ctx = ngx.ctx

diff --git a/kong/kong.lua b/kong/kong.lua
@@ -227,16 +227,20 @@ end
 function Kong.balancer()
   local addr = ngx.ctx.balancer_address
   local tries = addr.tries
-
+  local current_try = {}
   addr.try_count = addr.try_count + 1
+  tries[addr.try_count] = current_try
+
+  core.balancer.before()
+
   if addr.try_count > 1 then
     -- only call balancer on retry, first one is done in `core.access.after` which runs
     -- in the ACCESS context and hence has less limitations than this BALANCER context
     -- where the retries are executed
 
     -- record failure data
-    local try = tries[addr.try_count - 1]
-    try.state, try.code = get_last_failure()
+    local previous_try = tries[addr.try_count - 1]
+    previous_try.state, previous_try.code = get_last_failure()
 
     local ok, err = balancer_execute(addr)
     if not ok then
@@ -254,10 +258,8 @@ function Kong.balancer()
     end
   end
 
-  tries[addr.try_count] = {
-    ip    = addr.ip,
-    port  = addr.port,
-  }
+  current_try.ip   = addr.ip
+  current_try.port = addr.port
 
   -- set the targets as resolved
   local ok, err = set_current_peer(addr.ip, addr.port)
@@ -275,6 +277,8 @@ function Kong.balancer()
   if not ok then
     ngx.log(ngx.ERR, "could not set upstream timeouts: ", err)
   end
+
+  core.balancer.after()
 end
 
 function Kong.rewrite()

diff --git a/kong/plugins/log-serializers/basic.lua b/kong/plugins/log-serializers/basic.lua
@@ -31,7 +31,8 @@ function _M.serialize(ngx)
     latencies = {
       kong = (ngx.ctx.KONG_ACCESS_TIME or 0) +
              (ngx.ctx.KONG_RECEIVE_TIME or 0) +
-             (ngx.ctx.KONG_REWRITE_TIME or 0),
+             (ngx.ctx.KONG_REWRITE_TIME or 0) + 
+             (ngx.ctx.KONG_BALANCER_TIME or 0),
       proxy = ngx.ctx.KONG_WAITING_TIME or -1,
       request = ngx.var.request_time * 1000
     },