memcache socket errors

sparshgupta · 2012-05-31T19:34:15+00:00

Looking into the codes, I find ngx.shared_dict is quite similar to memcache, but simpler.Ngx+memcache uses unix sockets to do IPC while ngx.shared_dict uses...

memcache socket errors

sparshgupta

Hello

As stated in my previous email, I went ahead to do some load testing
comparing ngx.shared.DICT with lua-resty-memcache. When I am loading
ngx.shared.DICT everything is perfectly fine and the response times
and query/second are very impressive. When I do the same on memcache,
I see a lot of errors in my error.log like:

[error] 9324#0: *9086 lua socket read timed out
[error] 9324#0: *9086 [lua] common.lua:128: getURLsFromMemcache():
failed to retrieve key URLs-8081 from memcache: failed to receive 1st
line: timeout
[error] 9324#0: *9086 attempt to send data on a closed socket:
u:0000000041BF86A8, c:0000000000000000, ft:2 eof:0
[error] 9324#0: *9086 [lua] common.lua:146: setURLsToMemcache():
Unable to set variable URLs-8081,closed
[error] 9324#0: *9086 attempt to send data on a closed socket:
u:0000000041BF86A8, c:0000000000000000, ft:2 eof:0
[error] 9324#0: *9086 [lua] common.lua:240: getSettingsFromMemcache():
failed to retrieve key SETTINGS-8081_103 from memcache: failed to send
command: closed
[error] 9324#0: *9086 attempt to send data on a closed socket:
u:0000000041BF86A8, c:0000000000000000, ft:2 eof:0
[error] 9324#0: *9086 [lua] common.lua:259: setSettingsToMemcache():
Unable to set variable SETTINGS-8081_103,closed
[error] 9324#0: *9086 [lua] common.lua:454: closeMemcache(): failed to
set keepalive of Memcache: closed


I am enclosing some code pieces from my lua code (relevant parts I think):


-- MAIN.LUA
local common = require "common"
local rows = common.getURLs(a) -- Can be nil or valid list
...
-- A lot of logic around here (calles common.getSettingsFromMemcache()
which is very similar to getURLsFromMemcache())
...
common.closeMemcache()



--COMMON.LUA
local memcached = require "resty.memcached"
local memc -- To hold instance of Memcache

function getMemcache()
    if memc == nil then
        -- Connect Memcache Server
        memc = memcached:new()
        memc:set_timeout(500)
        local ok, err = memc:connect("unix:/tmp/memcached.sock")
        if not ok then
            ngx.log(ngx.ERR, "failed to connect memcache: ", err)
            return nil
        end
    end

    return memc
end



function getURLs(a)
    local res = getURLsFromMemcache(a) -- Res can be NIL or List

    -- If res is NIL, i.e. no result is found in the memcache
    if not res then
        res = getURLsFromMySQL(a) -- Get the list of URLs from MySQL
        -- Set it into Memcache for next time :)
        if res ~= nil then
            setURLsToMemcache(a, res)
        else
            ngx.log(ngx.ERR, "Result from MySQL (URLs) was found nil
and hence couldnt be saved in memcache")
        end
    end

    return res -- NIL or valid List with URLs
end


-- Function to get list of URLs from Memcache for a given account ID
-- Input: account ID
-- Output: NIL or Lua list with URLs
function getURLsFromMemcache(a)
    local memc = getMemcache()
    if memc then
        local res, flags, err = memc:get("URLs-" .. a)
        if not res then
            ngx.log(ngx.ERR, "failed to retrieve key URLs-"..a.." from
memcache: ", err)
            return nil
        end

        return cjson.decode(res)
    end

    return nil
end

-- Function to set URLs to Memcache for an account
-- Input: account ID, list of URLs
-- Output: nothing
function setURLsToMemcache(a, res)
    local memc = getMemcache()
    if memc then
        local ok, err = memc:set("URLs-" .. a, cjson.encode(res))
        if not ok then
            ngx.log(ngx.ERR, "Unable to set variable URLs-"..a..",", err)
        end
        return ok
    end

    return nil
end


--Set Memcache keepalives
function closeMemcache()
    --local memc = getMemcache() No point creating a new memcache if
its not there already
    if memc ~= nil then
        local ok, err = memc:set_keepalive(0, 1000)
        if not ok then
            ngx.log(ngx.ERR, "failed to set keepalive of Memcache: ", err)
        end
    end
end



Questions:
1. Am I doing anything wrong here. I am maintaining an instance of
memcache in common.lua and accessing it via getMemcache() function. My
understanding is that the socket ends memc doesnt become nil (ofcourse
as it doesnt know). Should I not check for if memc == nil in my
getMemcache() function and always go ahead and initiate a connect
function (which will do the rest, considering if keepalive is active).
Should I do memcached:new() everytime getMemcache() is called or how
should I go about it?

2. Is it normal to use such code in Lua as I come from PHP background
and still learning Lua

Thanks
Sparsh Gupta

agentzh

Hello!

On Thu, May 31, 2012 at 7:33 PM, Sparsh Gupta <spars...@gmail.com> wrote:
>
> --COMMON.LUA
> local memcached = require "resty.memcached"
> local memc -- To hold instance of Memcache
>

The Lua module level variables are shared by all the concurrent
requests handled by the same nginx worker process (see
http://wiki.nginx.org/HttpLuaModule#Data_Sharing_within_an_Nginx_Worker
). So you will have access conflicts when concurrent requests are
trying to use the same resty.memcached instance. You should avoid
sharing one single resty-memcached instance in your "common" module's
module level variables with all the requests.

You should always initiate resty.memcached objects in function local
variables or in the ngx.ctx table. These data all own its own copy for
each request.

Regards,
-agentzh

sparshgupta

Thanks again, I will use ngx.ctx for storing instance of my memc and mysql

Sparsh Gupta


On 31 May 2012 18:11, agentzh <age...@gmail.com> wrote:
> Hello!
>
> On Thu, May 31, 2012 at 7:33 PM, Sparsh Gupta <spars...@gmail.com> wrote:
>>
>> --COMMON.LUA
>> local memcached = require "resty.memcached"
>> local memc -- To hold instance of Memcache
>>
>
> The Lua module level variables are shared by all the concurrent
> requests handled by the same nginx worker process (see
> http://wiki.nginx.org/HttpLuaModule#Data_Sharing_within_an_Nginx_Worker
> ). So you will have access conflicts when concurrent requests are
> trying to use the same resty.memcached instance. You should avoid
> sharing one single resty-memcached instance in your "common" module's
> module level variables with all the requests.
>
> You should always initiate resty.memcached objects in function local
> variables or in the ngx.ctx table. These data all own its own copy for
> each request.
>
> Regards,
> -agentzh
>
>

sparshgupta

So I modified my getMemcache() function as:

function getMemcache()
    if ngx.ctx.memc == nil then
        local memcached = require "resty.memcached"
        -- Connect Memcache Server
        local memc = memcached:new()
        -- Memcache will reside on same server, not sure whats the
best value, 100ms for now
        memc:set_timeout(1000)
        -- Will probably use unix socket for this, think they are
faster due to lack of TCP/IP overhead
        --local ok, err = memc:connect("127.0.0.1", 11211)
        local ok, err = memc:connect("unix:/tmp/memcached.sock")
        if not ok then
            ngx.log(ngx.ERR, "failed to connect memcache: ", err)
            return nil
        end

        ngx.ctx.memc = memc
    end

    return ngx.ctx.memc
end

Every function in common.lua (common module) that needs to interact
with memcache will call this function for its local memc =
getMemcache()

I know there is still a flaw here that ngx.ctx.memc can point to a
closed socket and the requests might fail. How can I have a check in
getMemcache() that the socket is still open so that I can modify the
line

if ngx.ctx.memc == nil then to something which checks the availability
of socket.

I also set the set_timeout to 1000 which I thought is a good enough
value for every request, but when I benchmark, I still see tons of
errors on Closed Socket in my logs. Any pointers?

Thanks
Sparsh Gupta


On 31 May 2012 18:26, Sparsh Gupta <spars...@gmail.com> wrote:
> Thanks again, I will use ngx.ctx for storing instance of my memc and mysql
>
> Sparsh Gupta
>
>
> On 31 May 2012 18:11, agentzh <age...@gmail.com> wrote:
>> Hello!
>>
>> On Thu, May 31, 2012 at 7:33 PM, Sparsh Gupta <spars...@gmail.com> wrote:
>>>
>>> --COMMON.LUA
>>> local memcached = require "resty.memcached"
>>> local memc -- To hold instance of Memcache
>>>
>>
>> The Lua module level variables are shared by all the concurrent
>> requests handled by the same nginx worker process (see
>> http://wiki.nginx.org/HttpLuaModule#Data_Sharing_within_an_Nginx_Worker
>> ). So you will have access conflicts when concurrent requests are
>> trying to use the same resty.memcached instance. You should avoid
>> sharing one single resty-memcached instance in your "common" module's
>> module level variables with all the requests.
>>
>> You should always initiate resty.memcached objects in function local
>> variables or in the ngx.ctx table. These data all own its own copy for
>> each request.
>>
>> Regards,
>> -agentzh
>>
>>

agentzh

Hello!

On Thu, May 31, 2012 at 9:40 PM, Sparsh Gupta <spars...@gmail.com> wrote:
>
> I also set the set_timeout to 1000 which I thought is a good enough
> value for every request, but when I benchmark, I still see tons of
> errors on Closed Socket in my logs. Any pointers?
>

Have you reloaded your nginx server to make your changes take effect?
What exactly are the first few error messages this time?

Regards,
-agentzh

agentzh

On Thu, May 31, 2012 at 9:40 PM, Sparsh Gupta <spars...@gmail.com> wrote:
> So I modified my getMemcache() function as:
>
> function getMemcache()
>    if ngx.ctx.memc == nil then
>        local memcached = require "resty.memcached"

BTW, the line

    local memcached = require "resty.memcached"

can be put on the module level to save some CPU time, it's the module,
not the object instance.

Regards,
-agentzh

sparshgupta

>>
>> I also set the set_timeout to 1000 which I thought is a good enough
>> value for every request, but when I benchmark, I still see tons of
>> errors on Closed Socket in my logs. Any pointers?
>>
>
> Have you reloaded your nginx server to make your changes take effect?
> What exactly are the first few error messages this time?


lua socket read timed out,
[lua] common.lua:138: getURLsFromMemcache(): failed to retrieve key
URLs-8081 from memcache: failed to receive 1st line: timeout,
attempt to send data on a closed socket: u:00000000406AA728,
c:0000000000000000, ft:2 eof:0,
[lua] common.lua:156: setURLsToMemcache(): Unable to set variable
URLs-8081,closed,
attempt to send data on a closed socket: u:00000000406AA728,
c:0000000000000000, ft:2 eof:0,
[lua] common.lua:257: getSettingsFromMemcache(): failed to retrieve
key SETTINGS-8081_103 from memcache: failed to send command: closed,
attempt to send data on a closed socket: u:00000000406AA728,
c:0000000000000000, ft:2 eof:0,
[lua] common.lua:276: setSettingsToMemcache(): Unable to set variable
SETTINGS-8081_103,closed,
[lua] common.lua:470: closeMemcache(): failed to set keepalive of
Memcache: closed,


> Regards,
> -agentzh
>
>

agentzh

Hello!

On Thu, May 31, 2012 at 9:49 PM, Sparsh Gupta <spars...@gmail.com> wrote:
> lua socket read timed out,
> [lua] common.lua:138: getURLsFromMemcache(): failed to retrieve key
> URLs-8081 from memcache: failed to receive 1st line: timeout,
> attempt to send data on a closed socket: u:00000000406AA728,
> c:0000000000000000, ft:2 eof:0,

When getURLsFromMemcache() fails, you should try reconnecting the
resty.memcached object because the connection will become closed and
subsequent operations (like your setURLsToMemcache and
setSettingsToMemcache) on this object will return the "closed" errors.

It seems that your memcached is still taking more than 1 sec to
respond. What tool and what command are you using to press nginx? What
concurrency level are you using? Is it blowing your memcached server
too hard and your memcached server is too busy? Maybe you should
enlarge the timeout setting on your resty.memcached object? Or maybe
you should tune your memcached server?

Regards,
-agentzh

sparshgupta

Hello

On 31 May 2012 19:24, agentzh <age...@gmail.com> wrote:
> Hello!
>
> On Thu, May 31, 2012 at 9:49 PM, Sparsh Gupta <spars...@gmail.com> wrote:
>> lua socket read timed out,
>> [lua] common.lua:138: getURLsFromMemcache(): failed to retrieve key
>> URLs-8081 from memcache: failed to receive 1st line: timeout,
>> attempt to send data on a closed socket: u:00000000406AA728,
>> c:0000000000000000, ft:2 eof:0,
>
> When getURLsFromMemcache() fails, you should try reconnecting the
> resty.memcached object because the connection will become closed and
> subsequent operations (like your setURLsToMemcache and
> setSettingsToMemcache) on this object will return the "closed" errors.

Sure, I will do that to avoid, but ideally this shouldn't happen at
first place is my concern
>
> It seems that your memcached is still taking more than 1 sec to
> respond.

During the rush, I used memcache CLI to get some keys and it was super
fast (definately less than 1second, around 10-20ms maybe)

>What tool and what command are you using to press nginx?
tried ab (from different machine in same private network), and also
using external service (BLITZ); happening in both situations

>What concurrency level are you using?
This happened when I did concurrency of 500 :(

>Is it blowing your memcached server
> too hard and your memcached server is too busy?
Its not busy. Its a memcache which resides locally and connects over
unix socket. There is nothing else on the server and I am flushing and
restarting memcache everytime before hitting it. In the end I looked
at memcache stats and the read value if almost equal to the request I
sent using ab

>Maybe you should
> enlarge the timeout setting on your resty.memcached object?
I started with 200ms, made it 1000ms now, can always increase it but
then this is no good if its taking more than 1s

>Or maybe
> you should tune your memcached server?
I have memcached 1.4.5 on ubuntu 10.04 server started using following parameters
memcached -d -m 128 -s /tmp/memcached.sock -u www-data -c 16384

I can try increasing -c but 16384 is anyways way too high than 500
(which is hitting nginx)

Lemme know if I can debug this further to find more on this issue.
Happy to share my complete code and nginx config files if you wanna
look into it.

Thanks
Sparsh Gupta
>
> Regards,
> -agentzh
>
>

agentzh

Hello!

On Thu, May 31, 2012 at 10:10 PM, Sparsh Gupta <spars...@gmail.com> wrote:
>
>>What concurrency level are you using?
> This happened when I did concurrency of 500 :(
>

That's rather weird.

I just tried "ab -k c500 -n20000 127.0.0.1:1984/t" on both my
Slackware Linux x86_64 (on my laptop, Core2Duo T9600) and Amazon Basic
Linux AMI x86_64 (on an Amazon EC2 High-CPU instance, 2x2.5 EC2
Computing Unit) with a very simple example below, and could not
reproduce any errors in nginx's error.log.

    location /t {
        content_by_lua '
            local memcached = require "resty.memcached"
            local memc = memcached:new()

            memc:set_timeout(300) -- 300 ms

            local ok, err = memc:connect("unix:/tmp/memc2.sock")
            if not ok then
                ngx.say("failed to connect: ", err)
                return
            end

            local ok, err = memc:set("dog", 32)
            if not ok then
                ngx.log(ngx.ERR, "failed to set dog: ", err)
                return
            end

            for i = 1, 2 do
                local res, flags, err = memc:get("dog")
                if err then
                    ngx.log(ngx.ERR, "failed to get dog: ", err)
                    return
                end

                if not res then
                    ngx.say("dog not found")
                else
                    ngx.say("dog: ", res, " (flags: ", flags, ")")
                end
            end

            local ok, err = memc:set_keepalive(0, 800)
            if not ok then
                ngx.log(ngx.ERR, "failed to set keepalive: ", err)
            end

            ngx.say("done")
        ';
    }

The memcached server was started like this, nothing fancy:

    memcached -c 1024 -s /tmp/memc2.sock -d

I was using memcached 1.4.13 and ngx_openresty 1.0.15.7. As you can
see, I'm using only 300ms as the timeout setting and with even "-c
700" there was no errors either.

Could you try my simple example above?

Best regards,
-agentzh