full scan in utubettl take()

Inizia da utubettl.lua, esamina il metodo take() e la definizione dell’indice status mostrata nell’issue. Esegui la riproduzione fornita con un milione di task per osservare la scansione completa, quindi verifica che take() salti in modo efficiente le utubes già prese continuando a selezionare correttamente i task disponibili.

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.