full scan in utubettl take()

utubettl.luaから始め、take()メソッドとissueに示されているstatusインデックスの定義を調べます。提供されている100万タスクの再現を実行して完全なスキャンを観察し、その後、take()が取得済みのutubesを効率的にスキップしながら、利用可能なタスクを正しく選択することを確認します。

The take() method in utubettl does a linear search for a task from an available utube.
In case there are many tasks in the same utube, calling take() will result in a full scan.

This can be improved by adding the 'utube' field to the status index, like this:

- parts = {i_status, str_type(), i_pri, num_type(), i_id, num_type()}
+ parts = {i_status, str_type(), i_pri, num_type(), i_utube, num_type(), i_id, num_type()}

And then using it in the take() method, quickly skipping taken utubes.

Code to demonstrate the full scan:

local queue = require('queue')
box.once('access:v1', function()
	box.schema.user.grant('guest', 'read,write,execute', 'universe')
	queue.create_tube('q1', 'utubettl', {})
	for i=1,10^6 do
		queue.tube.q1:put('task', {utube='u1'})
	end
end)

local log = require 'log'

log.info('insert done, beginning test')

local fiber = require 'fiber'
local clock = require 'clock'
local start_time = clock.time()
local nworkers = 3
local chan = fiber.channel(nworkers)

for i = 1, nworkers do
	fiber.create(function()
		local myid = i
		while true do
			chan:put(1)
			log.info('worker %d calls take...', myid)
			local task = queue.tube.q1:take()
			log.info('worker %d got task', myid)
			queue.tube.q1:ack(task[1])
			log.info('worker %d ack task', myid)
			fiber.yield() -- give other workers a chance to work
		end
	end)
end

for i = 1, 2*nworkers do
	chan:get()
end

log.info('test took %d seconds', clock.time() - start_time)
os.exit(0)

output (utubettl.lua was modified to log the number of iterations in take()):

2019-09-17 20:42:48.838 [12519] main/101/init.lua I> insert done, beginning test
2019-09-17 20:42:48.838 [12519] main/114/lua I> worker 1 calls take...
2019-09-17 20:42:48.838 [12519] main/115/lua I> worker 2 calls take...
2019-09-17 20:42:54.127 [12519] main/115/lua I> (999999 iterations in utubettl take())
2019-09-17 20:42:54.128 [12519] main/116/lua I> worker 3 calls take...
2019-09-17 20:42:59.855 [12519] main/116/lua I> (999999 iterations in utubettl take())
2019-09-17 20:42:59.855 [12519] main/114/lua txn.c:314 W> too long WAL write: 1 rows at LSN 1000022: 11.017 sec
2019-09-17 20:42:59.855 [12519] main/114/lua I> worker 1 got task
2019-09-17 20:42:59.855 [12519] main/114/lua I> worker 1 ack task
2019-09-17 20:42:59.855 [12519] main/114/lua I> worker 1 calls take...
2019-09-17 20:43:05.866 [12519] main/114/lua I> (999998 iterations in utubettl take())
2019-09-17 20:43:05.867 [12519] main/115/lua txn.c:314 W> too long WAL write: 1 rows at LSN 1000024: 6.012 sec
2019-09-17 20:43:05.867 [12519] main/115/lua I> worker 2 got task
2019-09-17 20:43:05.867 [12519] main/115/lua I> worker 2 ack task
2019-09-17 20:43:05.867 [12519] main/115/lua I> worker 2 calls take...
2019-09-17 20:43:11.836 [12519] main/115/lua I> (999997 iterations in utubettl take())
2019-09-17 20:43:11.836 [12519] main/114/lua txn.c:314 W> too long WAL write: 1 rows at LSN 1000026: 5.969 sec
2019-09-17 20:43:11.836 [12519] main/114/lua I> worker 1 got task
2019-09-17 20:43:11.836 [12519] main/114/lua I> worker 1 ack task
2019-09-17 20:43:11.837 [12519] main/114/lua I> worker 1 calls take...
2019-09-17 20:43:17.140 [12519] main/114/lua I> (999996 iterations in utubettl take())
2019-09-17 20:43:17.140 [12519] main/115/lua txn.c:314 W> too long WAL write: 1 rows at LSN 1000028: 5.304 sec
2019-09-17 20:43:17.140 [12519] main/115/lua I> worker 2 got task
2019-09-17 20:43:17.141 [12519] main/115/lua I> worker 2 ack task
2019-09-17 20:43:17.141 [12519] main/115/lua I> worker 2 calls take...
2019-09-17 20:43:22.495 [12519] main/115/lua I> (999995 iterations in utubettl take())
2019-09-17 20:43:22.495 [12519] main/114/lua txn.c:314 W> too long WAL write: 1 rows at LSN 1000030: 5.354 sec
2019-09-17 20:43:22.495 [12519] main/114/lua I> worker 1 got task
2019-09-17 20:43:22.495 [12519] main/114/lua I> worker 1 ack task
2019-09-17 20:43:22.495 [12519] main/114/lua I> worker 1 calls take...
2019-09-17 20:43:28.938 [12519] main/114/lua I> (999994 iterations in utubettl take())
2019-09-17 20:43:28.938 [12519] main/115/lua txn.c:314 W> too long WAL write: 1 rows at LSN 1000032: 6.443 sec
2019-09-17 20:43:28.938 [12519] main/115/lua I> worker 2 got task
2019-09-17 20:43:28.938 [12519] main/115/lua I> worker 2 ack task
2019-09-17 20:43:28.938 [12519] main/115/lua I> worker 2 calls take...
2019-09-17 20:43:34.251 [12519] main/115/lua I> (999993 iterations in utubettl take())
2019-09-17 20:43:34.251 [12519] main/101/init.lua I> test took 45 seconds

cpu usage is 100% during the whole test and it is hard for producers to put new tasks in the queue, because the lua thread is so busy.