librelist archives

« back to archive

Hundreds of Resque::DirtyExit and several Errno::EAGAIN exceptions per day

Hundreds of Resque::DirtyExit and several Errno::EAGAIN exceptions per day

From:
Stone
Date:
2010-11-08 @ 05:24
Hi all,

We have 20+ workers running, they are pretty stable until I tried adding 4M
of items in one queue 4 days ago.
It failed after adding 2M+ items, and the exception is the following:

Count : 2803672
*Errno::EAGAIN: Resource temporarily unavailable - Timeout reading
from the socket*
        from 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:102:in
`read'

        from 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:35:in
`call'
        from 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:65:in
`process'

        from 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:247:in
`ensure_connected'
        from 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:273:in
`ensure_connected'

        from 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/1.8/monitor.rb:242:in
`synchronize'
        from 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:269:in
`synchronize'

        from 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:273:in
`ensure_connected'
        from 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:63:in
`process'

        from 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:201:in
`logging'
        from 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:62:in
`process'

        from 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:34:in
`call'
        from 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis.rb:235:in
`sadd'

        from 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-namespace-0.8.0/lib/redis/namespace.rb:188:in
`send'
        from 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-namespace-0.8.0/lib/redis/namespace.rb:188:in
`method_missing'

        from 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/resque-1.10.0/lib/resque.rb:184:in
`watch_queue'
        from 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/resque-1.10.0/lib/resque.rb:129:in
`push'

        from 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/resque-1.10.0/lib/resque/job.rb:51:in
`create'



After the first *Errno::EAGAIN* exception, we got hundreds of *
Resque::DirtyExit* and several Errno::EAGAIN exceptions per day.

The worker error message for *Errno::EAGAIN Resource temporarily unavailable
- Timeout reading from the socket* is the following :
Resource temporarily unavailable - Timeout reading from the socket


/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:102:in
`read'

/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:35:in
`call'


/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:65:in
`process'

/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:247:in
`ensure_connected'


/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:273:in
`ensure_connected'
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/1.8/monitor.rb:242:in
`synchronize'


/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:269:in
`synchronize'

/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:273:in
`ensure_connected'


/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:63:in
`process'

/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:201:in
`logging'


/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:62:in
`process'

/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:34:in
`call'


/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis.rb:123:in
`hget'

/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-namespace-0.8.0/lib/redis/namespace.rb:188:in
`send'


/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-namespace-0.8.0/lib/redis/namespace.rb:188:in
`method_missing'
/production/releases/20101105155351/app/workers/worker_common.rb:158:in
`perform'


/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/resque-1.10.0/lib/resque/job.rb:133:in
`perform'

/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/resque-1.10.0/lib/resque/worker.rb:157:in
`perform'


/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/resque-1.10.0/lib/resque/worker.rb:124:in
`work'

/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/resque-1.10.0/lib/resque/worker.rb:110:in
`loop'


/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/resque-1.10.0/lib/resque/worker.rb:110:in
`work'

/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/resque-1.10.0/lib/resque/tasks.rb:24


/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:636:in
`call'

/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:636:in
`execute'

/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:631:in
`each'


/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:631:in
`execute'

/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:597:in
`invoke_with_call_chain'

/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/1.8/monitor.rb:242:in
`synchronize'

/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:590:in
`invoke_with_call_chain'

/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:583:in
`invoke'


/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2051:in
`invoke_task'

/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2029:in
`top_level'


/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2029:in
`each'

/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2029:in
`top_level'


/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2068:in
`standard_exception_handling'

/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2023:in
`top_level'


/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2001:in
`run'

/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2068:in
`standard_exception_handling'


/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:1998:in
`run'

/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/bin/rake:31
/usr/local/bin/rake:19:in `load'

/usr/local/bin/rake:19

And there's no stack trace for *Resque::DirtyExit, *I inspected the
resque-worker.log, there are many messages like :

(See full trace by running task with --trace)
rake aborted!
*time's up!*

Any suggestions ? Appreciate for your help.

Best Regards,
Stone

Re: [resque] Hundreds of Resque::DirtyExit and several Errno::EAGAIN exceptions per day

From:
nicholas a. evans
Date:
2010-11-08 @ 16:34
I've seen this happen when redis starts getting swapped to disk by the
operating system and also when using "keys" on a very large DB.  I
solved it by rewriting the one task to use store relevant keys in sets
(removing the need for "keys"), increasing the timeouts on my redis
connections, switching redis to use its own virtual memory (thus
avoiding slower OS VM), and simply decreasing the amount of data
stored in redis (e.g. expiring certain data more quickly than usual).
For the long term, I'll solve it by adding some more redis servers
with more memory.

-- 
Nick

On Mon, Nov 8, 2010 at 12:24 AM, Stone <stones.gao@gmail.com> wrote:
> Hi all,
>
> We have 20+ workers running, they are pretty stable until I tried adding 4M
> of items in one queue 4 days ago.
> It failed after adding 2M+ items, and the exception is the following:
>
> Count : 2803672
> Errno::EAGAIN: Resource temporarily unavailable - Timeout reading from the
> socket
>         from
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:102:in
> `read'
>
>         from
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:35:in
> `call'
>         from
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:65:in
> `process'
>
>         from
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:247:in
> `ensure_connected'
>         from
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:273:in
> `ensure_connected'
>
>         from
> /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/1.8/monitor.rb:242:in
> `synchronize'
>         from
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:269:in
> `synchronize'
>
>         from
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:273:in
> `ensure_connected'
>         from
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:63:in
> `process'
>
>         from
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:201:in
> `logging'
>         from
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:62:in
> `process'
>
>         from
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:34:in
> `call'
>         from
> /usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis.rb:235:in
> `sadd'
>
>         from
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-namespace-0.8.0/lib/redis/namespace.rb:188:in
> `send'
>         from
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-namespace-0.8.0/lib/redis/namespace.rb:188:in
> `method_missing'
>
>         from
> /usr/local/rvm/gems/ree-1.8.7-2010.02/gems/resque-1.10.0/lib/resque.rb:184:in
> `watch_queue'
>         from
> /usr/local/rvm/gems/ree-1.8.7-2010.02/gems/resque-1.10.0/lib/resque.rb:129:in
> `push'
>
>         from
> /usr/local/rvm/gems/ree-1.8.7-2010.02/gems/resque-1.10.0/lib/resque/job.rb:51:in
> `create'
>
>
> After the first Errno::EAGAIN exception, we got hundreds of
> Resque::DirtyExit and several Errno::EAGAIN exceptions per day.
>
> The worker error message for Errno::EAGAIN Resource temporarily unavailable
> - Timeout reading from the socket is the following :
> Resource temporarily unavailable - Timeout reading from the socket
>
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:102:in
> `read'
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:35:in
> `call'
>
>
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:65:in
> `process'
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:247:in
> `ensure_connected'
>
>
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:273:in
> `ensure_connected'
> /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/1.8/monitor.rb:242:in
> `synchronize'
>
>
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:269:in
> `synchronize'
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:273:in
> `ensure_connected'
>
>
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:63:in
> `process'
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:201:in
> `logging'
>
>
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:62:in
> `process'
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:34:in
> `call'
>
>
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis.rb:123:in
> `hget'
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-namespace-0.8.0/lib/redis/namespace.rb:188:in
> `send'
>
>
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-namespace-0.8.0/lib/redis/namespace.rb:188:in
> `method_missing'
> /production/releases/20101105155351/app/workers/worker_common.rb:158:in
> `perform'
>
>
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/resque-1.10.0/lib/resque/job.rb:133:in
> `perform'
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/resque-1.10.0/lib/resque/worker.rb:157:in
> `perform'
>
>
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/resque-1.10.0/lib/resque/worker.rb:124:in
> `work'
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/resque-1.10.0/lib/resque/worker.rb:110:in
> `loop'
>
>
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/resque-1.10.0/lib/resque/worker.rb:110:in
> `work'
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/resque-1.10.0/lib/resque/tasks.rb:24
>
>
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:636:in
> `call'
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:636:in
> `execute'
>
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:631:in
> `each'
>
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:631:in
> `execute'
>
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:597:in
> `invoke_with_call_chain'
>
> /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/1.8/monitor.rb:242:in
> `synchronize'
>
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:590:in
> `invoke_with_call_chain'
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:583:in
> `invoke'
>
>
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2051:in
> `invoke_task'
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2029:in
> `top_level'
>
>
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2029:in
> `each'
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2029:in
> `top_level'
>
>
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2068:in
> `standard_exception_handling'
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2023:in
> `top_level'
>
>
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2001:in
> `run'
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2068:in
> `standard_exception_handling'
>
>
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:1998:in
> `run'
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/bin/rake:31
> /usr/local/bin/rake:19:in `load'
>
>
> /usr/local/bin/rake:19
>
> And there's no stack trace for Resque::DirtyExit, I inspected the
> resque-worker.log, there are many messages like :
>
> (See full trace by running task with --trace)
> rake aborted!
> time's up!
>
> Any suggestions ? Appreciate for your help.
>
> Best Regards,
> Stone
>
>

Re: [resque] Hundreds of Resque::DirtyExit and several Errno::EAGAIN exceptions per day

From:
Stone
Date:
2010-11-09 @ 14:13
Thanks for your reply.

I tried add the following to redis.conf, but not help, still got many *
Resque::DirtyExit* exceptions.

vm-enabled yes
vm-max-memory 1500000000
vm-page-size 32
vm-pages 16777216
vm-max-threads 4

The following is the ouput of *info* command :

redis> info
redis_version:2.0.2
redis_git_sha1:00000000
redis_git_dirty:0
arch_bits:64
multiplexing_api:epoll
process_id:11102
uptime_in_seconds:21997
uptime_in_days:0
connected_clients:29
connected_slaves:0
blocked_clients:0
used_memory:998493776
used_memory_human:952.24M
changes_since_last_save:5899
bgsave_in_progress:0
last_save_time:1289311573
bgrewriteaof_in_progress:0
total_connections_received:175
total_commands_processed:3886361
expired_keys:0
hash_max_zipmap_entries:64
hash_max_zipmap_value:512
pubsub_channels:0
pubsub_patterns:0
vm_enabled:1
role:master
vm_conf_max_memory:1500000000
vm_conf_page_size:32
vm_conf_pages:16777216
vm_stats_used_pages:0
vm_stats_swapped_objects:0
vm_stats_swappin_count:0
vm_stats_swappout_count:0
vm_stats_io_newjobs_len:0
vm_stats_io_processing_len:0
vm_stats_io_processed_len:0
vm_stats_io_active_threads:0
vm_stats_blocked_clients:0
db0:keys=4933,expires=0
db1:keys=32,expires=0

And redis-stat command output:

 ------- data ------ ------------ load ----------------------------- -
childs -
 keys      used-mem  clients blpops  requests            connections
 4959      952.27M   29      0       3900632 (+3900632)  176
 4958      952.27M   29      0       3900833 (+201)      176
 4961      952.27M   29      0       3900966 (+133)      176
 4962      952.27M   29      0       3901143 (+177)      176
 4963      952.27M   29      0       3901374 (+231)      176
 4962      952.27M   29      0       3901595 (+221)      176
 4961      952.27M   29      0       3901776 (+181)      176
 4962      952.27M   29      0       3901992 (+216)      176
 4961      952.28M   29      0       3902179 (+187)      176
 4961      952.27M   29      0       3902428 (+249)      176
 4961      952.28M   29      0       3902656 (+228)      176
 4960      952.27M   29      0       3902860 (+204)      176
 4956      952.27M   29      0       3903102 (+242)      176
 4961      952.28M   29      0       3903250 (+148)      176
 4962      952.28M   29      0       3903400 (+150)      176
 4960      952.28M   29      0       3903622 (+222)      176
 4959      952.28M   29      0       3903766 (+144)      176
 4960      952.28M   29      0       3903976 (+210)      176
 4958      952.28M   29      0       3904204 (+228)      176
 4958      952.28M   29      0       3904405 (+201)      176

And *redis-load* command output:

PRNG seed is: 821588382 - use the 'seed' option to reproduce the same
sequence
====== Report ======
  10007 requests completed in 0.18 seconds
  50 parallel clients
  1 min bytes payload
  64 max bytes payload
  keep alive: 1

18.13% <= 0 milliseconds
93.54% <= 1 milliseconds
99.94% <= 2 milliseconds
99.96% <= 3 milliseconds
99.97% <= 4 milliseconds
99.99% <= 5 milliseconds
100.00% <= 6 milliseconds
54983.52 requests per second



Best Regards,
Stone



On Tue, Nov 9, 2010 at 12:34 AM, nicholas a. evans <nick@ekenosen.net>wrote:

> I've seen this happen when redis starts getting swapped to disk by the
> operating system and also when using "keys" on a very large DB.  I
> solved it by rewriting the one task to use store relevant keys in sets
> (removing the need for "keys"), increasing the timeouts on my redis
> connections, switching redis to use its own virtual memory (thus
> avoiding slower OS VM), and simply decreasing the amount of data
> stored in redis (e.g. expiring certain data more quickly than usual).
> For the long term, I'll solve it by adding some more redis servers
> with more memory.
>
> --
> Nick
>
> On Mon, Nov 8, 2010 at 12:24 AM, Stone <stones.gao@gmail.com> wrote:
> > Hi all,
> >
> > We have 20+ workers running, they are pretty stable until I tried adding
> 4M
> > of items in one queue 4 days ago.
> > It failed after adding 2M+ items, and the exception is the following:
> >
> > Count : 2803672
> > Errno::EAGAIN: Resource temporarily unavailable - Timeout reading from
> the
> > socket
> >         from
> >
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:102:in
> > `read'
> >
> >         from
> >
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:35:in
> > `call'
> >         from
> >
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:65:in
> > `process'
> >
> >         from
> >
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:247:in
> > `ensure_connected'
> >         from
> >
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:273:in
> > `ensure_connected'
> >
> >         from
> > /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/1.8/monitor.rb:242:in
> > `synchronize'
> >         from
> >
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:269:in
> > `synchronize'
> >
> >         from
> >
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:273:in
> > `ensure_connected'
> >         from
> >
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:63:in
> > `process'
> >
> >         from
> >
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:201:in
> > `logging'
> >         from
> >
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:62:in
> > `process'
> >
> >         from
> >
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis/client.rb:34:in
> > `call'
> >         from
> >
> /usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-2.0.13/lib/redis.rb:235:in
> > `sadd'
> >
> >         from
> >
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-namespace-0.8.0/lib/redis/namespace.rb:188:in
> > `send'
> >         from
> >
> 
/usr/local/rvm/gems/ree-1.8.7-2010.02/gems/redis-namespace-0.8.0/lib/redis/namespace.rb:188:in
> > `method_missing'
> >
> >         from
> >
> /usr/local/rvm/gems/ree-1.8.7-2010.02/gems/resque-1.10.0/lib/resque.rb:184:in
> > `watch_queue'
> >         from
> >
> /usr/local/rvm/gems/ree-1.8.7-2010.02/gems/resque-1.10.0/lib/resque.rb:129:in
> > `push'
> >
> >         from
> >
> /usr/local/rvm/gems/ree-1.8.7-2010.02/gems/resque-1.10.0/lib/resque/job.rb:51:in
> > `create'
> >
> >
> > After the first Errno::EAGAIN exception, we got hundreds of
> > Resque::DirtyExit and several Errno::EAGAIN exceptions per day.
> >
> > The worker error message for Errno::EAGAIN Resource temporarily
> unavailable
> > - Timeout reading from the socket is the following :
> > Resource temporarily unavailable - Timeout reading from the socket
> >
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:102:in
> > `read'
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:35:in
> > `call'
> >
> >
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:65:in
> > `process'
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:247:in
> > `ensure_connected'
> >
> >
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:273:in
> > `ensure_connected'
> > /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/1.8/monitor.rb:242:in
> > `synchronize'
> >
> >
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:269:in
> > `synchronize'
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:273:in
> > `ensure_connected'
> >
> >
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:63:in
> > `process'
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:201:in
> > `logging'
> >
> >
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:62:in
> > `process'
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis/client.rb:34:in
> > `call'
> >
> >
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-2.0.13/lib/redis.rb:123:in
> > `hget'
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-namespace-0.8.0/lib/redis/namespace.rb:188:in
> > `send'
> >
> >
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/redis-namespace-0.8.0/lib/redis/namespace.rb:188:in
> > `method_missing'
> > /production/releases/20101105155351/app/workers/worker_common.rb:158:in
> > `perform'
> >
> >
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/resque-1.10.0/lib/resque/job.rb:133:in
> > `perform'
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/resque-1.10.0/lib/resque/worker.rb:157:in
> > `perform'
> >
> >
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/resque-1.10.0/lib/resque/worker.rb:124:in
> > `work'
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/resque-1.10.0/lib/resque/worker.rb:110:in
> > `loop'
> >
> >
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/resque-1.10.0/lib/resque/worker.rb:110:in
> > `work'
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/resque-1.10.0/lib/resque/tasks.rb:24
> >
> >
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:636:in
> > `call'
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:636:in
> > `execute'
> >
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:631:in
> > `each'
> >
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:631:in
> > `execute'
> >
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:597:in
> > `invoke_with_call_chain'
> >
> > /usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/1.8/monitor.rb:242:in
> > `synchronize'
> >
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:590:in
> > `invoke_with_call_chain'
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:583:in
> > `invoke'
> >
> >
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2051:in
> > `invoke_task'
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2029:in
> > `top_level'
> >
> >
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2029:in
> > `each'
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2029:in
> > `top_level'
> >
> >
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2068:in
> > `standard_exception_handling'
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2023:in
> > `top_level'
> >
> >
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2001:in
> > `run'
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:2068:in
> > `standard_exception_handling'
> >
> >
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/lib/rake.rb:1998:in
> > `run'
> >
> 
/usr/local/rvm/rubies/ree-1.8.7-2010.02/lib/ruby/gems/1.8/gems/rake-0.8.7/bin/rake:31
> > /usr/local/bin/rake:19:in `load'
> >
> >
> > /usr/local/bin/rake:19
> >
> > And there's no stack trace for Resque::DirtyExit, I inspected the
> > resque-worker.log, there are many messages like :
> >
> > (See full trace by running task with --trace)
> > rake aborted!
> > time's up!
> >
> > Any suggestions ? Appreciate for your help.
> >
> > Best Regards,
> > Stone
> >
> >
>

Re: [resque] Hundreds of Resque::DirtyExit and several Errno::EAGAIN exceptions per day

From:
nicholas a. evans
Date:
2010-11-09 @ 20:31
On Tue, Nov 9, 2010 at 9:13 AM, Stone <stones.gao@gmail.com> wrote:
> I tried add the following to redis.conf, but not help, still got many
> Resque::DirtyExit exceptions.
...
> The following is the ouput of info command :
...
> used_memory:998493776
> used_memory_human:952.24M
...
> vm_conf_max_memory:1500000000
...
> vm_stats_used_pages:0
> vm_stats_swapped_objects:0
...
> db0:keys=4933,expires=0
> db1:keys=32,expires=0

This particular redis-server has VM enabled, but it doesn't have
enough data in it yet to start using it.  Try checking your OS's swap
usage (free -m) as well as redis-stat, redis-info before (with an
empty redis DB) and after loading up the redis DB with the 4 million
items like you did the last time.  I'm guessing you're still hitting
OS swap, even with redis VM enabled.  Perhaps you need to lower the
vm_max_memory.

You might also get better help if you ask the redis mailing list
(google group) or IRC channel.
http://code.google.com/p/redis/#Learn_more!  They should be able to
answer questions about redis memory usage and timeouts when you have a
single list with 4 million items in it.

One technique you might consider using to reduce memory load is to
make a meta-job that will add a limited number of your normal jobs,
and add it to the end of the queue.  E.g. something like the
following:

module FooJob
  extend self
  def queue; "foo" end
  def perform(id) Foo.find(id).bar! end
end

module AddMoreFooJobs
  extend self
  LIMIT = 2000
  def queue; "foo" end
  def perform
     Foo.needs_job.limit(LIMIT).each {|f| Resque.enqueue(FooJob, f.id) }
     Resque.enqueue(self) if Foo.needs_job.offset(LIMIT).count > 0
  end
end

And then you can run "Resque.enqueue(AddMoreFooJobs)" from a cron job,
or from wherever it is you're currently enqueuing your FooJobs.

Hope that helps.

-- 
Nick

CPU Usage and Logging

From:
Tute
Date:
2010-11-10 @ 14:32
Each Resque Job even when isn't running consumes 30% of CPU almost all 
the time. Is this the normal cpu usage or maybe I have an error ?

Another problem is I don't have clear how to redirect resque Logging to 
my own log files.