Redis performance - Processing time increasing over time.

[Raamnath Mani]

Hello,

Have been running some performance tests against latest stable Redis which we used to store sessiondata using hash, key constructed with UUID

Problem:
Response time increases over a period of time, in 11 hours it had increased from a few microseconds to 5 milliseconds. Load pattern was stable throughout the test period. Our expectation was, response time plateau period, but this unbounded increase has led me to write to this group. No memory swapping, checked /proc/**/smaps.

Our doubts, are:

• Could be related to memory fragmentation? [since it involves a lot of deletes/create]
• The background task of actively expiring the keys, currently it is running 10 times a second and sampling 10 keys every time]
• Or anything that we havent covered?
  

Our Load scenario: [Single Redis instance configured with disk persistence]

• we constructed a java class using jedis library to do communciate with redis,
• Loadrunner was used to simulate multi threads, we simulated around 1000 TPS using 50 concurrent threads.
• Each iteration, create a new session key and there will be Read+Update+Read+Update+Update+Read+Update.
• This is repeated every 100-200 milliseconds by each of the 50 threads.
• The payload of each key is as follows,
• database,type,key,size_in_bytes,encoding,num_elements,len_largest_element
  0,hash,"Samp.sess::3X4g1c6wqth7rHxepeq9c23G6.jvm",8459,hashtable,9,3164
• Read - using HGETALL and update using a transaction - MULTI [HMSET+EXPIREAT]. TTL -30 mins

Hardware:
Hardware is a high spec server with 96GB memory and dual Quad Xeon CPU. NUMA aware hardware.

Version:
redis_version:2.6.14
os:Linux 2.6.32-279.22.1.el6.x86_64 x86_64
arch_bits:64
multiplexing_api:epoll
gcc_version:4.4.6
process_id:21023
run_id:f7d158548af84bd825ce724627581ba1fae057f1
tcp_port:6379
uptime_in_seconds:2580
uptime_in_days:0
hz:10
lru_clock:919368

Info stats: [File attached]
total_commands_processed:12881175
instantaneous_ops_per_sec:4352
rejected_connections:0
expired_keys:272071
evicted_keys:0
keyspace_hits:4293010
keyspace_misses:858602
pubsub_channels:0
pubsub_patterns:0
latest_fork_usec:4880

# Keyspace
db0:keys=586531,expires=586531

Others:

• ·         Response times for the Read and Write transactions were in <1 milliseconds, however, after a certain point in the test the response time starts on an increasing trend and had reached 4 millisecond over a period of 11 hours.
• ·         Based on the OS statistics, there were no paging happening on the redis process [based on proc smaps] , it had more than sufficient memory. Max memory was set to 20GB, but max used during the test was around 14GB.
• ·         Disk persistence was enabled with frequency “save 300 10” running every 5 minutes, this forked a child process which then writes the rdb file on the box, hence every 5 minutes we see response times spike upto 12 milliseconds. Since redis is singlethreaded, the client connections experience delay during the time taken for the fork operation, max time for a fork was around 10milliseconds during the test.
• ·         To isolate disk persistence causing the increasing trend, we did a test with disk persistence disabled. This had the increasing trend too.

Has anyone experienced this behaviour? Or is this a mis-configuration? Any directions will be very helpful.

Thanks
Raam

[Josiah Carlson]

The info that you sent says that Redis was restarted less than 1 hour prior. Do you have an info output that includes information after Redis has been running for 12+ hours? Also, the memory fragmentation in the output says 1.03 (effectively not fragmented), and that it's only using about 6 gigs. Can we get output when it's near the peak?

 - Josiah

--
You received this message because you are subscribed to the Google Groups "Redis DB" group.
To unsubscribe from this group and stop receiving emails from it, send an email to redis-db+u...@googlegroups.com.
To post to this group, send email to redi...@googlegroups.com.
Visit this group at http://groups.google.com/group/redis-db.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

[Yiftach Shoolman]

Looks like you send a lot of expiry commands, true ? 

My 2 cents (based on our own experience), try to run without expiry, if it solves the issue try to minimize the amount of expiry commands you send per hash

--

Yiftach Shoolman
+972-54-7634621

[Yiftach Shoolman]

I'm forwarding Raam's response to the forum

On Fri, Jul 12, 2013 at 3:05 PM, Raamnath Mani <raamna...@gmail.com> wrote:

Thanks Josiah /Yiftach,

The root cause of the issue was with the load generation tool itself, we had been using Loadrunner Java vuser by building a wrapper to the jedis library. Due to the high throughput we had been testing, the tool's measurement had screwed up resulting in an unbounded increase. This was proved by setting the slowlog threshold to 1000 microsec and then we had a script to monitor the "LEN" of the slowlog requests, the LEN didnt increase throughout the test period but the tool was reporting response times of >2ms and it was still increasing.

For the benefit of others, we avoided this issue in Loadrunner by setting "run as process" instead of the default "run as thread". Response times in this test was invariant throughout.

Looks like you send a lot of expiry commands, true ?

---Yes, session data expiring after 30 mins

Once again, thanks for the responses :-)

Regards
Raam

--

Yiftach Shoolman
+972-54-7634621