Bad overall performance, high CPU, blocking connections

[Melvin Rook]

Hi all,

For some time I am trying to use Redis in a high volume system, but till
now I am not happy about the performance of Redis. I wonder what the
issue is, am I just pushing Redis to it's limits or am I doing something
wrong?

I am using Redis to store a great amount of counters (of which some have
an expiry timestamp). However, after some time Redis starts to block new
connections for short periods of time and the CPU usage becomes 100%.
The overall performance is degraded at those times.

The following things were already improved/tried:

- Improved the client code
- Enabled PIPELINE
- Spreading the keys among 4 instances instead of just one instance
- Disabled snapshotting to the RDB file
- Updated Redis from 2.4 to 2.6 RC.
- Enabled the Redis Watchdog (see logs below)

* Some key numbers:

Redis instances: 4
Memory usage per instance: ~ 3GB
Amount of keys per instance: db0:keys=18644443,expires=9137407
Amount of set operations: 1200 - 1500 per second

* Server specifications:

CPU: 2x Intel Xeon E5620 @ 2.40GHz
Memory: 64 GB
Network: 2x GBit

* Server memory (free -m):

total used free shared buffers cached
Mem: 64551 45413 19137 0 158 12661
-/+ buffers/cache: 32593 31957
Swap: 3999 0 3999

* Versions:

CentOS 6.2
Linux 2.6.32-71.29.1.el6.x86_64 #1 SMP Mon Jun 27 19:49:27 BST 2011
x86_64 x86_64 x86_64 GNU/Linux
Redis server v=2.5.9 sha=00000000:0 malloc=jemalloc-2.2.5 bits=64

redis 127.0.0.1:6381> INFO
# Server
redis_version:2.5.9
redis_git_sha1:00000000
redis_git_dirty:0
os:Linux 2.6.32-71.29.1.el6.x86_64 x86_64
arch_bits:64
multiplexing_api:epoll
gcc_version:4.4.6
process_id:9614
run_id:fc990e2026b0030228741f9028c87aeae3d4eb11
tcp_port:6381
uptime_in_seconds:967
uptime_in_days:0
lru_clock:1640425

# Clients
connected_clients:1
client_longest_output_list:0
client_biggest_input_buf:0
blocked_clients:0

# Memory
used_memory:2336621672
used_memory_human:2.18G
used_memory_rss:2385965056
used_memory_peak:2464117640
used_memory_peak_human:2.29G
used_memory_lua:30720
mem_fragmentation_ratio:1.02
mem_allocator:jemalloc-2.2.5

# Persistence
loading:0
aof_enabled:0
changes_since_last_save:43686
bgsave_in_progress:0
last_save_time:1337609977
last_bgsave_status:ok
bgrewriteaof_in_progress:0
bgrewriteaof_scheduled:0

# Stats
total_connections_received:119569
total_commands_processed:1047293
instantaneous_ops_per_sec:1185
rejected_connections:0
expired_keys:0
evicted_keys:0
keyspace_hits:0
keyspace_misses:0
pubsub_channels:0
pubsub_patterns:0
latest_fork_usec:1694807

# Replication
role:master
connected_slaves:0

# CPU
used_cpu_sys:95.18
used_cpu_user:31.31
used_cpu_sys_children:5.68
used_cpu_user_children:16.56

# Keyspace
db0:keys=18706495,expires=9179366

* Current configuration:

daemonize yes
pidfile /var/run/redis_6381.pid
port 6381
timeout 0
loglevel notice
logfile /var/log/redis_6381.log
databases 1
save 900 1
stop-writes-on-bgsave-error yes
rdbcompression yes
dbfilename dump.rdb
dir /var/lib/redis/6381
slave-serve-stale-data yes
appendonly no
appendfsync everysec
no-appendfsync-on-rewrite no
auto-aof-rewrite-percentage 100
auto-aof-rewrite-min-size 64mb
lua-time-limit 5000
slowlog-log-slower-than 10000
slowlog-max-len 1024
hash-max-ziplist-entries 512
hash-max-ziplist-value 64
list-max-ziplist-entries 512
list-max-ziplist-value 64
set-max-intset-entries 512
zset-max-ziplist-entries 128
zset-max-ziplist-value 64
activerehashing yes
client-output-buffer-limit normal 0 0 0
client-output-buffer-limit slave 256mb 64mb 60
client-output-buffer-limit pubsub 32mb 8mb 60

* Client code:

// Store counters in Redis
try
{
$redis = new Redis();
$redis->connect($server, $port, 0.5);
$redis->select(0);
}
catch(Exception $e)
{
trigger_error("Unable to connect to Redis: ".$e->getMessage(),
E_USER_WARNING);

return;
}

$pipe = $redis->multi(Redis::PIPELINE);

// Increment counters
$pipe->set($key_prefix."l", $time);
$pipe->incr($key_prefix."t");
$pipe->incr($key_prefix."d");
$pipe->incr($key_prefix."w");
$pipe->incr($key_prefix."m");

// Expiry
$pipe->expireAt($key_prefix."d", mktime(23, 59, 59, $date_m, $date_d,
$date_Y));
$pipe->expireAt($key_prefix."w", mktime(23, 59, 59, $date_m,
$date_d-$date_w+7, $date_Y));
$pipe->expireAt($key_prefix."m", mktime(23, 59, 59, $date_m, $date_t,
$date_Y));

// Execute
$replies = $pipe->exec();
$redis->close();

$pipe = null;
$redis = null;

* Watchdog logs:

[9614 | signal handler] (1337609806)
--- WATCHDOG TIMER EXPIRED ---
/usr/local/bin/redis-server(logStackTrace+0x75)[0x436cd5]
/lib64/libc.so.6(+0x13ff0b)[0x7f2def40df0b]
/lib64/libpthread.so.0(+0xf4a0)[0x7f2def67e4a0]
/lib64/libc.so.6(+0x13ff0b)[0x7f2def40df0b]
/usr/local/bin/redis-server[0x461a69]
/usr/local/bin/redis-server(je_realloc+0x86)[0x45aa06]
/usr/local/bin/redis-server(zrealloc+0x35)[0x4174d5]
/usr/local/bin/redis-server(sdsMakeRoomFor+0x56)[0x416126]
/usr/local/bin/redis-server(readQueryFromClient+0x4e)[0x41dbce]
/usr/local/bin/redis-server(aeProcessEvents+0x124)[0x40f7e4]
/usr/local/bin/redis-server(aeMain+0x2b)[0x40fa5b]
/usr/local/bin/redis-server(main+0x2a2)[0x415d22]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x7f2def2eccdd]
/usr/local/bin/redis-server[0x40ee39]
[9614 | signal handler] (1337609806) --------

[9614 | signal handler] (1337609806)
--- WATCHDOG TIMER EXPIRED ---
/usr/local/bin/redis-server(logStackTrace+0x75)[0x436cd5]
/lib64/libc.so.6(+0x13ff0b)[0x7f2def40df0b]
/lib64/libpthread.so.0(+0xf4a0)[0x7f2def67e4a0]
/lib64/libc.so.6(+0x13ff0b)[0x7f2def40df0b]
/usr/local/bin/redis-server[0x461a69]
/usr/local/bin/redis-server(je_realloc+0x86)[0x45aa06]
/usr/local/bin/redis-server(zrealloc+0x35)[0x4174d5]
/usr/local/bin/redis-server(sdsMakeRoomFor+0x56)[0x416126]
/usr/local/bin/redis-server(readQueryFromClient+0x4e)[0x41dbce]
/usr/local/bin/redis-server(aeProcessEvents+0x124)[0x40f7e4]
/usr/local/bin/redis-server(aeMain+0x2b)[0x40fa5b]
/usr/local/bin/redis-server(main+0x2a2)[0x415d22]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x7f2def2eccdd]
/usr/local/bin/redis-server[0x40ee39]
[9614 | signal handler] (1337609806) --------

[9614] 21 May 16:19:12.052 * 1 changes in 900 seconds. Saving...
[9614 | signal handler] (1337609953)
--- WATCHDOG TIMER EXPIRED ---
/usr/local/bin/redis-server(logStackTrace+0x75)[0x436cd5]
/lib64/libpthread.so.0(__pthread_mutex_unlock+0x15)[0x7f2def6795e5]
/lib64/libpthread.so.0(+0xf4a0)[0x7f2def67e4a0]
/lib64/libpthread.so.0(__pthread_mutex_unlock+0x15)[0x7f2def6795e5]
/usr/local/bin/redis-server[0x45982d]
/lib64/libc.so.6(__libc_fork+0x216)[0x7f2def378de6]
/usr/local/bin/redis-server(rdbSaveBackground+0x5b)[0x423e4b]
/usr/local/bin/redis-server(serverCron+0x460)[0x415510]
/usr/local/bin/redis-server(aeProcessEvents+0x1ca)[0x40f88a]
/usr/local/bin/redis-server(aeMain+0x2b)[0x40fa5b]
/usr/local/bin/redis-server(main+0x2a2)[0x415d22]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x7f2def2eccdd]
/usr/local/bin/redis-server[0x40ee39]
[9614 | signal handler] (1337609953) --------

[9614] 21 May 16:19:13.747 * Background saving started by pid 21986
[9614 | signal handler] (1337609957)
--- WATCHDOG TIMER EXPIRED ---
/usr/local/bin/redis-server(logStackTrace+0x75)[0x436cd5]
/usr/local/bin/redis-server(dictReplace+0xa0)[0x411770]
/lib64/libpthread.so.0(+0xf4a0)[0x7f2def67e4a0]
/usr/local/bin/redis-server(dictReplace+0xa0)[0x411770]
/usr/local/bin/redis-server(setKey+0x34)[0x421634]
/usr/local/bin/redis-server(setGenericCommand+0x9d)[0x42639d]
/usr/local/bin/redis-server(call+0x5d)[0x4132cd]
/usr/local/bin/redis-server(processCommand+0x375)[0x4137f5]
/usr/local/bin/redis-server(processInputBuffer+0x4f)[0x41db0f]
/usr/local/bin/redis-server(readQueryFromClient+0xa0)[0x41dc20]
/usr/local/bin/redis-server(aeProcessEvents+0x124)[0x40f7e4]
/usr/local/bin/redis-server(aeMain+0x2b)[0x40fa5b]
/usr/local/bin/redis-server(main+0x2a2)[0x415d22]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x7f2def2eccdd]
/usr/local/bin/redis-server[0x40ee39]
[9614 | signal handler] (1337609957) --------

[9614 | signal handler] (1337609962)
--- WATCHDOG TIMER EXPIRED ---
/usr/local/bin/redis-server(logStackTrace+0x75)[0x436cd5]
/usr/local/bin/redis-server(dictAddRaw+0xe9)[0x411549]
/lib64/libpthread.so.0(+0xf4a0)[0x7f2def67e4a0]
/usr/local/bin/redis-server(dictAddRaw+0xe9)[0x411549]
/usr/local/bin/redis-server(dictAdd+0x1e)[0x41167e]
/usr/local/bin/redis-server(dbAdd+0x34)[0x4212c4]
/usr/local/bin/redis-server(setKey+0x76)[0x421676]
/usr/local/bin/redis-server(setGenericCommand+0x9d)[0x42639d]
/usr/local/bin/redis-server(call+0x5d)[0x4132cd]
/usr/local/bin/redis-server(processCommand+0x375)[0x4137f5]
/usr/local/bin/redis-server(processInputBuffer+0x4f)[0x41db0f]
/usr/local/bin/redis-server(readQueryFromClient+0xa0)[0x41dc20]
/usr/local/bin/redis-server(aeProcessEvents+0x124)[0x40f7e4]
/usr/local/bin/redis-server(aeMain+0x2b)[0x40fa5b]
/usr/local/bin/redis-server(main+0x2a2)[0x415d22]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x7f2def2eccdd]
/usr/local/bin/redis-server[0x40ee39]
[9614 | signal handler] (1337609962) --------

[9614 | signal handler] (1337609967)
--- WATCHDOG TIMER EXPIRED ---
/usr/local/bin/redis-server(logStackTrace+0x75)[0x436cd5]
/usr/local/bin/redis-server(dictReplace+0xa0)[0x411770]
/lib64/libpthread.so.0(+0xf4a0)[0x7f2def67e4a0]
/usr/local/bin/redis-server(dictReplace+0xa0)[0x411770]
/usr/local/bin/redis-server(setKey+0x34)[0x421634]
/usr/local/bin/redis-server(setGenericCommand+0x9d)[0x42639d]
/usr/local/bin/redis-server(call+0x5d)[0x4132cd]
/usr/local/bin/redis-server(processCommand+0x375)[0x4137f5]
/usr/local/bin/redis-server(processInputBuffer+0x4f)[0x41db0f]
/usr/local/bin/redis-server(readQueryFromClient+0xa0)[0x41dc20]
/usr/local/bin/redis-server(aeProcessEvents+0x124)[0x40f7e4]
/usr/local/bin/redis-server(aeMain+0x2b)[0x40fa5b]
/usr/local/bin/redis-server(main+0x2a2)[0x415d22]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x7f2def2eccdd]
/usr/local/bin/redis-server[0x40ee39]
[9614 | signal handler] (1337609967) --------

[9614 | signal handler] (1337609970)
--- WATCHDOG TIMER EXPIRED ---
/usr/local/bin/redis-server(logStackTrace+0x75)[0x436cd5]
/usr/local/bin/redis-server[0x45e187]
/lib64/libpthread.so.0(+0xf4a0)[0x7f2def67e4a0]
/usr/local/bin/redis-server[0x45e187]
/usr/local/bin/redis-server[0x45f9c4]
/usr/local/bin/redis-server[0x46141e]
/usr/local/bin/redis-server[0x461a48]
/usr/local/bin/redis-server(je_realloc+0x86)[0x45aa06]
/usr/local/bin/redis-server(zrealloc+0x35)[0x4174d5]
/usr/local/bin/redis-server(sdsMakeRoomFor+0x56)[0x416126]
/usr/local/bin/redis-server(readQueryFromClient+0x4e)[0x41dbce]
/usr/local/bin/redis-server(aeProcessEvents+0x124)[0x40f7e4]
/usr/local/bin/redis-server(aeMain+0x2b)[0x40fa5b]
/usr/local/bin/redis-server(main+0x2a2)[0x415d22]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x7f2def2eccdd]
/usr/local/bin/redis-server[0x40ee39]
[9614 | signal handler] (1337609970) --------

[9614 | signal handler] (1337609972)
--- WATCHDOG TIMER EXPIRED ---
/usr/local/bin/redis-server(logStackTrace+0x75)[0x436cd5]
/usr/local/bin/redis-server(dictReplace+0xa0)[0x411770]
/lib64/libpthread.so.0(+0xf4a0)[0x7f2def67e4a0]
/usr/local/bin/redis-server(dictReplace+0xa0)[0x411770]
/usr/local/bin/redis-server(setKey+0x34)[0x421634]
/usr/local/bin/redis-server(setGenericCommand+0x9d)[0x42639d]
/usr/local/bin/redis-server(call+0x5d)[0x4132cd]
/usr/local/bin/redis-server(processCommand+0x375)[0x4137f5]
/usr/local/bin/redis-server(processInputBuffer+0x4f)[0x41db0f]
/usr/local/bin/redis-server(readQueryFromClient+0xa0)[0x41dc20]
/usr/local/bin/redis-server(aeProcessEvents+0x124)[0x40f7e4]
/usr/local/bin/redis-server(aeMain+0x2b)[0x40fa5b]
/usr/local/bin/redis-server(main+0x2a2)[0x415d22]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x7f2def2eccdd]
/usr/local/bin/redis-server[0x40ee39]
[9614 | signal handler] (1337609972) --------

[9614 | signal handler] (1337609974)
--- WATCHDOG TIMER EXPIRED ---
/usr/local/bin/redis-server(logStackTrace+0x75)[0x436cd5]
/usr/local/bin/redis-server(dictReplace+0xa0)[0x411770]
/lib64/libpthread.so.0(+0xf4a0)[0x7f2def67e4a0]
/usr/local/bin/redis-server(dictReplace+0xa0)[0x411770]
/usr/local/bin/redis-server(setKey+0x34)[0x421634]
/usr/local/bin/redis-server(setGenericCommand+0x9d)[0x42639d]
/usr/local/bin/redis-server(call+0x5d)[0x4132cd]
/usr/local/bin/redis-server(processCommand+0x375)[0x4137f5]
/usr/local/bin/redis-server(processInputBuffer+0x4f)[0x41db0f]
/usr/local/bin/redis-server(readQueryFromClient+0xa0)[0x41dc20]
/usr/local/bin/redis-server(aeProcessEvents+0x124)[0x40f7e4]
/usr/local/bin/redis-server(aeMain+0x2b)[0x40fa5b]
/usr/local/bin/redis-server(main+0x2a2)[0x415d22]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x7f2def2eccdd]
/usr/local/bin/redis-server[0x40ee39]
[9614 | signal handler] (1337609974) --------

[9614 | signal handler] (1337609976)
--- WATCHDOG TIMER EXPIRED ---
/usr/local/bin/redis-server(logStackTrace+0x75)[0x436cd5]
/usr/local/bin/redis-server(dictAddRaw+0xe9)[0x411549]
/lib64/libpthread.so.0(+0xf4a0)[0x7f2def67e4a0]
/usr/local/bin/redis-server(dictAddRaw+0xe9)[0x411549]
/usr/local/bin/redis-server(dictAdd+0x1e)[0x41167e]
/usr/local/bin/redis-server(dbAdd+0x34)[0x4212c4]
/usr/local/bin/redis-server(setKey+0x76)[0x421676]
/usr/local/bin/redis-server(setGenericCommand+0x9d)[0x42639d]
/usr/local/bin/redis-server(call+0x5d)[0x4132cd]
/usr/local/bin/redis-server(processCommand+0x375)[0x4137f5]
/usr/local/bin/redis-server(processInputBuffer+0x4f)[0x41db0f]
/usr/local/bin/redis-server(readQueryFromClient+0xa0)[0x41dc20]
/usr/local/bin/redis-server(aeProcessEvents+0x124)[0x40f7e4]
/usr/local/bin/redis-server(aeMain+0x2b)[0x40fa5b]
/usr/local/bin/redis-server(main+0x2a2)[0x415d22]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x7f2def2eccdd]
/usr/local/bin/redis-server[0x40ee39]
[9614 | signal handler] (1337609976) --------

[21986] 21 May 16:19:36.654 * DB saved on disk
[9614] 21 May 16:19:37.896 * Background saving terminated with success

* Watchdog logs (same configuration, but without save):

[9614 | signal handler] (1337610193)
--- WATCHDOG TIMER EXPIRED ---
/usr/local/bin/redis-server(logStackTrace+0x75)[0x436cd5]
/lib64/libc.so.6(+0x13ff0b)[0x7f2def40df0b]
/lib64/libpthread.so.0(+0xf4a0)[0x7f2def67e4a0]
/lib64/libc.so.6(+0x13ff0b)[0x7f2def40df0b]
/usr/local/bin/redis-server[0x461a69]
/usr/local/bin/redis-server(je_realloc+0x86)[0x45aa06]
/usr/local/bin/redis-server(zrealloc+0x35)[0x4174d5]
/usr/local/bin/redis-server(sdsMakeRoomFor+0x56)[0x416126]
/usr/local/bin/redis-server(readQueryFromClient+0x4e)[0x41dbce]
/usr/local/bin/redis-server(aeProcessEvents+0x124)[0x40f7e4]
/usr/local/bin/redis-server(aeMain+0x2b)[0x40fa5b]
/usr/local/bin/redis-server(main+0x2a2)[0x415d22]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x7f2def2eccdd]
/usr/local/bin/redis-server[0x40ee39]
[9614 | signal handler] (1337610193) --------

[9614 | signal handler] (1337610195)
--- WATCHDOG TIMER EXPIRED ---
/usr/local/bin/redis-server(logStackTrace+0x75)[0x436cd5]
/usr/local/bin/redis-server[0x45e187]
/lib64/libpthread.so.0(+0xf4a0)[0x7f2def67e4a0]
/usr/local/bin/redis-server[0x45e187]
/usr/local/bin/redis-server[0x45f9c4]
/usr/local/bin/redis-server[0x45ff46]
/usr/local/bin/redis-server[0x46172c]
/usr/local/bin/redis-server(je_malloc+0x62)[0x45a3e2]
/usr/local/bin/redis-server(zmalloc+0x16)[0x4173e6]
/usr/local/bin/redis-server(createClient+0x12)[0x41c922]
/usr/local/bin/redis-server[0x41caf5]
/usr/local/bin/redis-server(acceptTcpHandler+0x4f)[0x41cc2f]
/usr/local/bin/redis-server(aeProcessEvents+0x124)[0x40f7e4]
/usr/local/bin/redis-server(aeMain+0x2b)[0x40fa5b]
/usr/local/bin/redis-server(main+0x2a2)[0x415d22]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x7f2def2eccdd]
/usr/local/bin/redis-server[0x40ee39]
[9614 | signal handler] (1337610195) --------

Would be great if somebody could help me out.

Kind regards,

Melvin

[Hampus Wessman]

Try not to create a new TCP connection each time. My guess is that your
problem is related to that. Unfortunately, I don't know how to use a
connection pool (aka persistent connections) for Redis in PHP (if at all
possible). To check if this is the problem, perhaps you could try to
connect using a local unix socket instead of TCP and see if the problem
goes away?

BR,
Hampus

[Marc Byrd]

You mentioned going from 1 instance to 4 - but these are all on the same hardware?

What does # ulimit -n return?  If it's the default 1024, that might be your problem.

m

--
You received this message because you are subscribed to the Google Groups "Redis DB" group.
To post to this group, send email to redi...@googlegroups.com.
To unsubscribe from this group, send email to redis-db+u...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/redis-db?hl=en.

[Josiah Carlson]

Your reporting information mentions sets. How many sets are you
passing to your operations, what operations are you performing, and
how large are your sets?

Regards,
- Josiah

[Dvir Volk]

I don't know the client library, is it phpredis? looks like not only you are not using persistent connections, you are closing the socket on each request, that's really bad.

this gives a hint:

total_connections_received:119569
total_commands_processed:1047293

around 1:9 connection/commands ratio. I counted and your code has 9 commands. :)

so what you have here is tons of TCP sockets probably in time wait state, blocking redis or the kernel or whatever.

anyway, phpredis has the method pconnect() instead of connect, that tries to pool connections.

use it and not connect() and don't close your connection in the end.

[Melvin Rook]

The 4 instances are on the same hardware, but on different (physical) CPU cores. The system has 8 physical cores in total.

The value for ulimit is unlimited for the redis-server process.

Kind regards,

Melvin

Op 21-5-2012 20:55, Marc Byrd schreef:

[Melvin Rook]

The client library is phpredis. Persistent connections gave troubles as well, but I will look into using those again.

I monitored the netstat output as well and the number of sockets in time wait state is quite low.

Kind regards,

Melvin

Op 21-5-2012 21:51, Dvir Volk schreef:

[Melvin Rook]

Actually, at the moment only the 'writing' part is enabled. The data
isn't being read actively yet.

I do not use sets. The following operations are performed within one
multi pipeline:

- 1x SET
- 4x INCR
- 3x EXPIREAT (for 3 of the incremented keys)

Note that the EXPIREAT operation happens after each increment and not
only for the first increment. Performing the EXPIREAT only the first
time opens a way for race conditions as the key might be incremented at
the same time by another client.

I wonder where in my reporting information sets are mentioned, because
as far as I know I am not using sets in my client code. Might be that
sets are used 'under water' by PHPRedis or Redis itself?

Kind regards,

Melvin

Op 21-5-2012 21:20, Josiah Carlson schreef:

[Dvir Volk]

could this be related to this issue perhaps?

https://groups.google.com/group/redis-db/browse_thread/thread/0f1ca3a9bb71191e?hl=en

"So the issue is, when this happens Redis currently will block 
everything and expire keys in a busy loop til the number of already 
expired keys (in the total of keys with an expire) became 25% or less. 
25% is considered an acceptable memory waste to continue serving 
queries again, expiring the remaining keys 100 per second, 
incrementally. "

if you're creating tons of expires all the time, maybe the expire loop gets too heavy?

have you tried this without expires?

On Tue, May 22, 2012 at 3:21 PM, Melvin Rook <mel...@melvinrook.nl> wrote:

Actually, at the moment only the 'writing' part is enabled. The data isn't being read actively yet.

I do not use sets. The following operations are performed within one multi pipeline:

- 1x SET
- 4x INCR
- 3x EXPIREAT (for 3 of the incremented keys)

Note that the EXPIREAT operation happens after each increment and not only for the first increment. Performing the EXPIREAT only the first time opens a way for race conditions as the key might be incremented at the same time by another client.

I wonder where in my reporting information sets are mentioned, because as far as I know I am not using sets in my client code. Might be that sets are used 'under water' by PHPRedis or Redis itself?

Kind regards,

Melvin

Op 21-5-2012 21:20, Josiah Carlson schreef:

Your reporting information mentions sets. How many sets are you
passing to your operations, what operations are you performing, and
how large are your sets?

Regards,
 - Josiah

On Mon, May 21, 2012 at 11:55 AM, Marc Byrd<dr.mar...@gmail.com>  wrote:

You mentioned going from 1 instance to 4 - but these are all on the same
hardware?

What does # ulimit -n return?  If it's the default 1024, that might be your
problem.

m

On Mon, May 21, 2012 at 11:52 AM, Hampus Wessman<hampus@hampuswessman.se>
wrote:

redis-db+unsubscribe@googlegroups.com.

For more options, visit this group at
http://groups.google.com/group/redis-db?hl=en.

--
You received this message because you are subscribed to the Google Groups
"Redis DB" group.
To post to this group, send email to redi...@googlegroups.com.
To unsubscribe from this group, send email to

redis-db+unsubscribe@googlegroups.com.

For more options, visit this group at
http://groups.google.com/group/redis-db?hl=en.

--
You received this message because you are subscribed to the Google Groups "Redis DB" group.
To post to this group, send email to redi...@googlegroups.com.

To unsubscribe from this group, send email to redis-db+unsubscribe@googlegroups.com.

[Josiah Carlson]

On Tue, May 22, 2012 at 5:21 AM, Melvin Rook <mel...@melvinrook.nl> wrote:
> Actually, at the moment only the 'writing' part is enabled. The data isn't
> being read actively yet.
>
> I do not use sets. The following operations are performed within one multi
> pipeline:
>
> - 1x SET
> - 4x INCR
> - 3x EXPIREAT (for 3 of the incremented keys)
>
> Note that the EXPIREAT operation happens after each increment and not only
> for the first increment. Performing the EXPIREAT only the first time opens a
> way for race conditions as the key might be incremented at the same time by
> another client.
>
> I wonder where in my reporting information sets are mentioned, because as
> far as I know I am not using sets in my client code. Might be that sets are
> used 'under water' by PHPRedis or Redis itself?

"Amount of set operations: 1200 - 1500 per second"

It seemed ambiguous, which is why I asked. My guess is that Dvir is
right about the expirations with the lockups, and that you could
likely halve your command latency by taking Hampus' suggestion to use
connection pooling (which should have a viable implementation in php
at this point).

Regards,
- Josiah

[Salvatore Sanfilippo]

Hello,

the watchdog output seems odd, like if the Redis process is blocked in
the middle of normal operations by swapping or some other OS activity
that does not allow it to run comfortably.

Cheers,
Salvatore

> --
> You received this message because you are subscribed to the Google Groups
> "Redis DB" group.
> To post to this group, send email to redi...@googlegroups.com.
> To unsubscribe from this group, send email to

> redis-db+u...@googlegroups.com.

> For more options, visit this group at
> http://groups.google.com/group/redis-db?hl=en.
>



--

Salvatore 'antirez' Sanfilippo
open source developer - VMware
http://invece.org

Beauty is more important in computing than anywhere else in technology
because software is so complicated. Beauty is the ultimate defence
against complexity.
       — David Gelernter

[Melvin Rook]

I looked into that issue as well, but the expiry loop isn't that heavy as you might think. Actually, to be sure I checked the redis-server source code and the expiry algorithm is pretty solid.

Kind regards,

Melvin

Op 22-5-2012 15:29, Dvir Volk schreef:

On Mon, May 21, 2012 at 11:52 AM, Hampus Wessman<ham...@hampuswessman.se>
wrote:

redis-db+u...@googlegroups.com.

For more options, visit this group at
http://groups.google.com/group/redis-db?hl=en.

--
You received this message because you are subscribed to the Google Groups
"Redis DB" group.
To post to this group, send email to redi...@googlegroups.com.
To unsubscribe from this group, send email to

redis-db+u...@googlegroups.com.

For more options, visit this group at
http://groups.google.com/group/redis-db?hl=en.

--
You received this message because you are subscribed to the Google Groups "Redis DB" group.
To post to this group, send email to redi...@googlegroups.com.

To unsubscribe from this group, send email to redis-db+u...@googlegroups.com.

For more options, visit this group at http://groups.google.com/group/redis-db?hl=en.

--
You received this message because you are subscribed to the Google Groups "Redis DB" group.
To post to this group, send email to redi...@googlegroups.com.

To unsubscribe from this group, send email to redis-db+u...@googlegroups.com.

[Dvir Volk]

Just out of curiosity, I want to run your code and see if I can recreate the problem.

what's your server setup and how to grind it? will "ab -n 100" do?

[Melvin Rook]

You are right about the watchdog output, I suspect the blocking is
caused by the BGSAVE fork. I tracked down that a great number of blocked
connections were happening during the fork.

With all the adjustments I ended up with quite a mess. Just to be sure I
reconfigured everything from scratch again and performed all my
configuration cases again. Seems I overlooked a few cases in combination
with the 2.6 RC version (which I did performed with 2.4).

I found out that pconnect didn't work well on 2.4 with BGSAVE on.
However, with 2.6 the number of blocked connections are less, but not
yet gone. All the blocked connections disappeared after I disabled
BGSAVE completely.

I will probably initiate BGSAVE manually during off-peak times to at
least have a daily dump of the data.

To recap:
- BGSAVE could be a cause of blocked connections (-> disable BGSAVE)
- connect could be a cause of blocked connections (-> use pconnect)
- a combination of the above two reasons, used in a high volume system,
could be the reason for a bad overall performance.

Other improvements I made:
- According to my tests 2.6 seems to perform better in comparison with 2.4
- Configured the number of databases to 1. If I understand the code
correctly, it will save a few loop iterations in the expiry algorithm.
- Spreading the keys among multiple Redis instances (using modulo). A
rule of thumb I used:
- With BGSAVE on: # instances = physical CPU cores / 2
- Without BGSAVE: # instances = physical CPU cores / 1

Thanks for all the responses. :-)

Kind regards,

Melvin

Op 22-5-2012 18:09, Salvatore Sanfilippo schreef:

[Melvin Rook]

Please note my other reply as well, as for now the overall performance issue seems to be resolved. As for your curiosity:

Let's say you want to reproduce it on just one instance (I am using multiple instances), then "ab -n 200" will come pretty close I think. Make sure that you reach about 18 million keys and a DB size of about 3 GB.

You will notice that the expiry algorithm isn't that heavy. If you play around with BGSAVE and (p)connect you will see that those affect performance really a lot.

With BGSAVE enabled you will see that Redis will start to block connections during the fork. Another solution would be to catch that event in the client code, then wait a bit and try to reconnect.

Kind regards,

Melvin

Op 23-5-2012 16:34, Dvir Volk schreef:

[Dvir Volk]

cool, although now that you've figured it out, the curiosity is quite over :)

re your previous email -

if you can spare the resources, to keep a slave that does all the BGSAVE and let the master be persistence free. this will solve the forking issues.