Skip to content

Commit

Permalink
Better way of calculating latencies
Browse files Browse the repository at this point in the history
  • Loading branch information
@subnetmarco
subnetmarco committed Jun 24, 2015
1 parent da54013 commit b82c568
Show file tree
Hide file tree
Showing 3 changed files with 28 additions and 18 deletions.
21 changes: 11 additions & 10 deletions kong/kong.lua
View file
Original file line number Diff line number Diff line change
Expand Up @@ -177,8 +177,8 @@ end

-- Calls `access()` on every loaded plugin
function _M.exec_plugins_access()
-- Setting a property that will be available for every plugin
ngx.ctx.started_at = get_now()
local start = get_now()

ngx.ctx.plugin_conf = {}

-- Iterate over all the plugins
Expand All @@ -205,13 +205,12 @@ function _M.exec_plugins_access()
final_url = final_url.."?"..ngx.encode_args(ngx.req.get_uri_args())
end
ngx.var.backend_url = final_url
ngx.ctx.proxy_started_at = get_now()
ngx.ctx.kong_processing_access = get_now() - start
end

-- Calls `header_filter()` on every loaded plugin
function _M.exec_plugins_header_filter()
ngx.ctx.proxy_ended_at = get_now()

local start = get_now()
if not ngx.ctx.stop_phases then
ngx.header["Via"] = constants.NAME.."/"..constants.VERSION

Expand All @@ -222,10 +221,12 @@ function _M.exec_plugins_header_filter()
end
end
end
ngx.ctx.kong_processing_header_filter = get_now() - start
end

-- Calls `body_filter()` on every loaded plugin
function _M.exec_plugins_body_filter()
local start = get_now()
if not ngx.ctx.stop_phases then
for _, plugin in ipairs(plugins) do
local conf = ngx.ctx.plugin_conf[plugin.name]
Expand All @@ -234,7 +235,7 @@ function _M.exec_plugins_body_filter()
end
end
end
ngx.ctx.ended_at = get_now()
ngx.ctx.kong_processing_body_filter = get_now() - start

This comment has been minimized.

Sign in to view

Copy link
@thibaultcha

thibaultcha Jun 25, 2015

Member

You know this won't give you the time at which the response has finished being received right? Only the first chunk of the response from upstream.

This comment has been minimized.

Sign in to view

Copy link
@subnetmarco

subnetmarco Jun 25, 2015

Author Member

I am not using that to calculate the time at which the response has finished.

This comment has been minimized.

Sign in to view

Copy link
@thibaultcha

thibaultcha Jun 25, 2015

Member

I know. But plugins will be run multiple times if the response is sent with multiple chunks. So the value would be wrong, shadowed by a new value when the body_filter was actually ran twice.

This comment has been minimized.

Sign in to view

Copy link
@subnetmarco

subnetmarco Jun 25, 2015

Author Member

You mean it should be:

ngx.ctx.kong_processing_body_filter = (ngx.ctx.kong_processing_body_filter and ngx.ctx.kong_processing_body_filter or 0) + (get_now() - start)

?

This comment has been minimized.

Sign in to view

Copy link
@thibaultcha

thibaultcha Jun 25, 2015

Member

Semantically yes, but since it's explicitly said that calls to ctx are expensive, probably

ngx.ctx.kong_processing_body_filter = (ngx.ctx.kong_processing_body_filter or 0) + (get_now() - start)

This comment has been minimized.

Sign in to view

Copy link
@subnetmarco

subnetmarco Jun 25, 2015

Author Member

c573db8
end

-- Calls `log()` on every loaded plugin
Expand All @@ -256,14 +257,14 @@ function _M.exec_plugins_log()
size = ngx.var.bytes_sent
},
latencies = {
kong = (ngx.ctx.ended_at - ngx.ctx.started_at) - (ngx.ctx.proxy_ended_at - ngx.ctx.proxy_started_at),
proxy = ngx.ctx.proxy_ended_at - ngx.ctx.proxy_started_at,
total = ngx.ctx.ended_at - ngx.ctx.started_at
kong = (ngx.ctx.kong_processing_access + ngx.ctx.kong_processing_header_filter + ngx.ctx.kong_processing_body_filter),
proxy = ngx.var.upstream_response_time * 1000,
request = ngx.var.request_time * 1000

This comment has been minimized.

Sign in to view

Copy link
@thibaultcha

thibaultcha Jun 25, 2015

Member

ngx.var.request_time is the time elapsed since the request was received:

local request_time = ngx.now() - ngx.req.start_time()

Which is not accurate when describing:

request is the time elapsed between the first bytes were read from the client and after the last bytes were sent to the client. Useful for detecting slow clients.

Because the time the last byte was sent to the client is in body_filter, not later during the execution of log_by_lua that can happen later on. One can detect the streaming to the client has ended like follows:

-- in body_filter
local eof =  ngx.arg[2]
if eof then -- latest chunk
  ngx.ctx.total_time = ngx.now() - ngx.req.start_time()
  -- or ngx.var.request_time
end

This comment has been minimized.

Sign in to view

Copy link
@subnetmarco

subnetmarco Jun 25, 2015

Author Member

@thibaultcha, from the nginx doc:

$request_time
request processing time in seconds with a milliseconds resolution; time elapsed between the first bytes were read from the client and the log write after the last bytes were sent to the client

http://nginx.org/en/docs/http/ngx_http_log_module.html
},
authenticated_entity = ngx.ctx.authenticated_entity,
api = ngx.ctx.api,
client_ip = ngx.var.remote_addr,
started_at = ngx.ctx.started_at
started_at = ngx.req.start_time() * 1000
}

ngx.ctx.log_message = message
Expand Down
18 changes: 11 additions & 7 deletions spec/plugins/logging_spec.lua
View file
Original file line number Diff line number Diff line change
Expand Up @@ -31,7 +31,7 @@ describe("Logging Plugins", function()
spec_helper.insert_fixtures {
api = {
{ name = "tests tcp logging", public_dns = "tcp_logging.com", target_url = "http://mockbin.com" },
{ name = "tests tcp logging2", public_dns = "tcp_logging2.com", target_url = "https://httpbin.org/" },
{ name = "tests tcp logging2", public_dns = "tcp_logging2.com", target_url = "http://localhost:"..HTTP_PORT },
{ name = "tests udp logging", public_dns = "udp_logging.com", target_url = "http://mockbin.com" },
{ name = "tests http logging", public_dns = "http_logging.com", target_url = "http://mockbin.com" },
{ name = "tests https logging", public_dns = "https_logging.com", target_url = "http://mockbin.com" },
Expand Down Expand Up @@ -70,24 +70,28 @@ describe("Logging Plugins", function()
local log_message = cjson.decode(res)
assert.are.same("127.0.0.1", log_message.client_ip)
end)

it("should log proper latencies", function()
local thread = spec_helper.start_tcp_server(TCP_PORT) -- Starting the mock TCP server
local http_thread = spec_helper.start_http_server(HTTP_PORT) -- Starting the mock TCP server
local tcp_thread = spec_helper.start_tcp_server(TCP_PORT) -- Starting the mock TCP server

-- Making the request
local _, status = http_client.get(spec_helper.PROXY_URL.."/delay/2", nil, { host = "tcp_logging2.com" })
local _, status = http_client.get(spec_helper.PROXY_URL.."/delay", nil, { host = "tcp_logging2.com" })
assert.are.equal(200, status)

-- Getting back the TCP server input
local ok, res = thread:join()
local ok, res = tcp_thread:join()
assert.truthy(ok)
assert.truthy(res)

-- Making sure it's alright
local log_message = cjson.decode(res)

assert.truthy(log_message.latencies.proxy < 3000)
assert.truthy(log_message.latencies.kong < 20)
assert.are.same(log_message.latencies.total, log_message.latencies.kong + log_message.latencies.proxy)
assert.truthy(log_message.latencies.request >= log_message.latencies.kong + log_message.latencies.proxy)

http_thread:join()
end)

it("should log to UDP", function()
Expand Down Expand Up @@ -165,5 +169,5 @@ describe("Logging Plugins", function()
assert.are.same("127.0.0.1", log_message.client_ip)
assert.are.same(uuid, log_message.request.headers.file_log_uuid)
end)

end)
7 changes: 6 additions & 1 deletion spec/spec_helpers.lua
View file
Original file line number Diff line number Diff line change
Expand Up @@ -120,10 +120,15 @@ function _M.start_http_server(port, ...)
end
end

if #lines > 0 and lines[1] == "GET /delay HTTP/1.0" then
os.execute("sleep 2")
end

if err then
error(err)
end
client:send("ok\n")

client:send("HTTP/1.1 200 OK\r\nConnection: close\r\n\r\n")
client:close()
return lines
end;
Expand Down

6 comments on commit b82c568

@thibaultcha
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The API analytics plugin needs the values you removed (started_at, proxy_ended_at, proxy_started_at). Those were also values we agreed on leaving for plugins to publicly use them.

Also, it also already updated a lot of things in the timestamp computations and will have tons of conflicts...

@subnetmarco
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Some of those values were not currently used and ngx.var.upstream_response_time is more accurate. Once we merge the analytics plugin into master we need to remember to update anything that we need to update.

@thibaultcha
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We agreed on those values being usable by any plugin. Removing them potentially breaks plugins.

@subnetmarco
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it's okay to release them in 0.4.0 as a breaking change, the previous values were technically incorrect so better to fix any incoherence before having a higher adoption.

I was going ahead to update the analytics plugin, but I don't see it anywhere (not even in a separate branch).

@subnetmarco
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@thibaultcha can you push the analytics plugin in a separate branch?

@subnetmarco
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh sorry, didn't see the pull request #272

Please sign in to comment.