lua entry thread aborted: runtime error: /usr/local/share/lua/5.1/vips/voperation.lua:126: too many callbacks

[wuyachao]

I use ab -n 1000 -c 100 "xxx.com/asdsad".
I get the original picture

Requests per second:    1457.55 [#/sec] (mean)
Time per request:       68.608 [ms] (mean)
Time per request:       0.686 [ms] (mean, across all concurrent requests)
Transfer rate:          101334.15 [Kbytes/sec] received

but，I use thumbnail_buffer, the rps decrease a lot.

Requests per second:    85.25 [#/sec] (mean)
Time per request:       1328.824 [ms] (mean)
Time per request:       13.288 [ms] (mean, across all concurrent requests)
Transfer rate:          1845.87 [Kbytes/sec] received

[wuyachao]

local image = vips.Image.new_from_buffer(img)

local args = ngx_req_get_uri_args()

local img2

if tonumber(args.p) == 0 or tonumber(args.w) > image:width() or tonumber(args.h) > image:height() then
  ngx.header.content_type = "image/jpeg"
  ngx.say(img)
  ngx.exit(200)
end

if tonumber(args.p) == 2 then
  img2 = image:smartcrop(tonumber(args.w), tonumber(args.h), { interesting = "centre" })
else
  img2 = vips.Image.thumbnail_buffer(img, tonumber(args.w), { height = tonumber(args.h), size = "down"})
end

local a = img2:jpegsave_buffer()
ngx.header.content_type = "image/jpeg"
ngx.say(a)

vips.Image.thumbnail_buffer may cause qps decrease.
I can get some error form nginx_error_log:

115567 lua entry thread aborted: runtime error: /usr/local/share/lua/5.1/vips/voperation.lua:126: too many callbacks
or 

[wuyachao]

sometimes，there is no error.but the qps is also 80~110. I'm sorry for my poor English.

[jcupitt]

Hello, I tried to make a test program:

#!/usr/bin/env luajit

vips = require 'vips'

-- benchmark thumbnail via a memory buffer
function via_memory(filename, thumbnail_width)
    print("memory processing ", filename)

    local fp = assert(io.open(filename, "rb"))
    local data = fp:read("*all")

    local thumb = vips.Image.thumbnail_buffer(data, thumbnail_width,
        {crop = "centre"})

    return thumb:write_to_buffer(".jpg")
end

-- benchmark thumbnail via files
function via_files(filename, thumbnail_width)
    print("file processing ", filename)

    local thumb = vips.Image.thumbnail(filename, thumbnail_width,
        {crop = "centre"})

    return thumb:write_to_buffer(".jpg")
end

for i = 1, #arg do
    -- thumb = via_memory(arg[i], 500)
    thumb = via_files(arg[i], 500)
end

I made some sample data like this:

  677  mkdir samples
  678  cd samples/
  679  for i in {1..10}; do cp ~/pics/k2.jpg $i.jpg; done

Wher k2.jpg is 1500 x 2000 pixel JPG.

When I run the program I see:

john@kiwi:~/try$ time ./soak.lua samples/*
file processing 	samples/10.jpg
file processing 	samples/1.jpg
file processing 	samples/2.jpg
file processing 	samples/3.jpg
file processing 	samples/4.jpg
file processing 	samples/5.jpg
file processing 	samples/6.jpg
file processing 	samples/7.jpg
file processing 	samples/8.jpg
file processing 	samples/9.jpg

real	0m0.538s
user	0m0.880s
sys	0m0.028s

And:

john@kiwi:~/try$ time ./soak.lua samples/*
memory processing 	samples/10.jpg
memory processing 	samples/1.jpg
memory processing 	samples/2.jpg
memory processing 	samples/3.jpg
memory processing 	samples/4.jpg
memory processing 	samples/5.jpg
memory processing 	samples/6.jpg
memory processing 	samples/7.jpg
memory processing 	samples/8.jpg
memory processing 	samples/9.jpg

real	0m0.521s
user	0m0.832s
sys	0m0.060s

So very similar speed, about 50ms per image on my slow laptop.

[jcupitt]

I tried with 1,000 images, and I see your "too many callbacks" error:

...
memory processing 	samples/934.jpg
memory processing 	samples/935.jpg
luajit: /home/john/.luarocks/share/lua/5.1/vips/voperation.lua:126: too many callbacks
stack traceback:
	[C]: in function 'cast'
	/home/john/.luarocks/share/lua/5.1/vips/voperation.lua:126: in function 'getargs'
	/home/john/.luarocks/share/lua/5.1/vips/voperation.lua:158: in function 'via_memory'
	./soak.lua:30: in main chunk
	[C]: at 0x004044a0

real	0m44.504s
user	1m16.292s
sys	0m2.236s

I tried adding collectgarbage() before each loop, but it made no difference.

I agree, it seems a callback is being leaked on each iteration. I'll investigate.

Thank you for reporting this.

[jcupitt]

The file processing version works, so it seems to be the GC callback on the buffer that leaks.

[jcupitt]

I've pushed a fix, it seems to work for me now. Would you be able to test?

If it fixes the problem for you too, I'll update the rock.

[wuyachao]

@jcupitt yes, it can fix this. It can work well when I request with `ab -n 2000 -c 200 'xxx.com/asda'

[jcupitt]

OK, I'll update the rock. Thanks again!

[jcupitt]

I meant to ask, did you find out why you were sometimes seeing low speed?

For JPEG, I would expect roughly 10 - 50ms per image, whether from file or memory. If you are seeing over 1000ms, something is probably broken.

[wuyachao]

@jcupitt lua-vips is always work fastly. It will 30-80ms for a request. I write the lua-vips to nginx_lua(OpenResty).
But the qps is very low. GraphicsMagick and ImageMagick is also like this.
I think the libvips，GraphicsMagick or ImageMagick dependent CPU very much. I can see the CPU is used up(over 90%) when I test it.

It's very fast per request. GraphicsMagick or ImageMagick will need 110-190ms. but libvips need 40~80ms.

real	0m0.045s
user	0m0.004s
sys	0m0.005s

[jcupitt]

QPS is queries per second, I guess?

On my desktop, I see:

john@mm-jcupitt5 /data/john/pics $ mkdir sample
john@mm-jcupitt5 /data/john/pics $ cd sample/
john@mm-jcupitt5 /data/john/pics/sample $ for i in {1..1000}; do cp ../k2.jpg $i.jpg; done
john@mm-jcupitt5 /data/john/pics/sample $ time parallel vipsthumbnail {} ::: *.jpg
real	0m5.372s
user	0m37.072s
sys	0m9.628s

So about ~150 thumbnails per second on this machine.

You could try benchmarking PNG, libvips should be much faster than graphicsmagick there. I see:

john@mm-jcupitt5 /data/john/pics $ time convert k2.png -resize 128x128 tn_k2.jpg

real	0m0.436s
user	0m0.380s
sys	0m0.020s
john@mm-jcupitt5 /data/john/pics $ time vipsthumbnail k2.png -s 128x128 -o tn_k2.jpg

real	0m0.182s
user	0m0.176s
sys	0m0.004s

With lower memory use. You'll find you can thumbnail very, very large images.

[wuyachao]

@jcupitt Thank you for your reply.
The qps is 43 when I use pngsave_buffer benchmarking. But jpegsave_buffer have 78 qps. the jpegsave_buffer is faster than pngsave_buffer.

[jcupitt]

Yes, libpng is slower than libjpg, but when you use PNG, libvips should be faster than graphicsmagick.