Monitoring fiber of latency of single ev_once

bad_tarantool.sh

> tarantool -l fiber -l clock -e 'fiber.create(function() while true do while clock.time() < fiber.time()+0.1 do end fiber.sleep(0.01) end end)' test.lua
entering the event loop
e:100.011µs p:0.017µs t:99.998µs
e:100.042µs p:0.010µs t:100.035µs
e:100.013µs p:0.015µs t:100.004µs
e:100.005µs p:0.006µs t:99.994µs
e:100.007µs p:0.004µs t:99.996µs
e:100.010µs p:0.009µs t:99.993µs
e:100.012µs p:0.016µs t:100.000µs
e:100.009µs p:0.050µs t:99.999µs
e:100.011µs p:0.016µs t:100.002µs
e:100.009µs p:0.009µs t:99.999µs
e:100.009µs p:0.014µs t:99.992µs
e:100.009µs p:0.010µs t:99.962µs
# if fiber is sleeping more than 0 seconds (uses fiber.sleep(0.01) instead of fiber.yield())
# then we see that it utilizes previous loop

> tarantool -l fiber -l clock -e 'fiber.create(function() while true do while clock.time() < fiber.time()+0.1 do end fiber.sleep(0) end end)' test.lua   
entering the event loop
e:100.032µs p:100.016µs t:0.004µs
e:100.020µs p:100.028µs t:0.006µs
e:100.015µs p:100.044µs t:0.005µs
e:100.007µs p:100.011µs t:0.003µs
e:100.021µs p:100.024µs t:0.008µs
e:100.027µs p:100.013µs t:0.013µs
e:100.056µs p:100.011µs t:0.009µs
# if fiber uses fiber.yield()/fiber.sleep(0) we see that it takes precedence over our monitoring fiber

evloop.lua

local clock = require 'clock'
local fiber = require 'fiber'

local ev_now_64 = function() return 1e3*fiber.time64() end

-- Returns microseconds
local function ev_run_time()
	fiber.sleep(0) -- setups watcher to the start of next ev_once

	local e0, w0 = ev_now_64(), clock.time64()
	fiber.sleep(0) -- rotates single loop
	local e1, w1 = ev_now_64(), clock.time64()

	-- e0 <= w0 <= e1 <= w1 (if ntp is ok)
	local ev_prolog = w1-e1 -- lag from the start of the loop till current fiber (must be as little as possible)
	local ev_tail = e1-w0 -- the epilog of previous ev_once

	local ev_loop_time = e1-e0
	return tonumber(ev_loop_time/1e3), tonumber(ev_prolog/1e3), tonumber(ev_tail/1e3)
end

return ev_run_time

test.lua

local ev_run_time = require 'evloop'
local fiber = require 'fiber'
local log = require 'log'


local function run_loop(mesure_interval, on_tick_cb)
	mesure_interval = tonumber(mesure_interval) or 0.01 -- every 10ms

	if not on_tick_cb then
		on_tick_cb = function() end
	end

	local gen
	if package.reload then gen = package.reload.count end

	local is_run = function()
		if gen and gen ~= package.reload.count then
			return false
		end
		fiber.testcancel()
		return true
	end

	while is_run() do
		local ev_once_time, ev_prolog_time, ev_epilog_time = ev_run_time() -- microseconds
		-- export anywhere you'd like to
		local ok, err = pcall(on_tick_cb, ev_once_time, ev_prolog_time, ev_epilog_time)
		if not ok then
			log.error("[ev_loop_time] on_tick_cb failed: %s", err)
		end
		fiber.sleep(mesure_interval)
	end
end

f = fiber.create(run_loop, nil, function(e, p, t)
	log.info("e:%.3fµs p:%.3fµs t:%.3fµs", e/1000, p/1000, t/1000)
end)