Hi , I met a strange question: even set a 500M string, redis doesn't make a slowlog(slowlog threshold 10ms, i even adjust slowlog thresholdto 5ms). But when i use hset, redis record a slowlog.
Thanks very much.
How to reproduce:
Create a 500mb file
dd if=/dev/zero of=bigfile bs=1M count=500
Check slowlog configuration
Redis version: 4.0.12 (I also tried redis 6.0.6)
127.0.0.1:6379> config get slowlog* 1) "slowlog-log-slower-than" 2) "10000" 3) "slowlog-max-len" 4) "10240" 127.0.0.1:6379> slowlog get 1 (empty array) 127.0.0.1:6379>
Set two keys separatly using bigfile, and only hset trigger a slowlog
[centos ]$ redis-cli -x set bigstring
Comment From: sundb
Run your test, set bigstring <bigfile cost 8ms, and does not exceed the slowlog-log-slower-than(10ms) threshold.
btw, dict insert is slower than list, so the dictionary will trigger the threshold.
Comment From: madolson
Setting a string in Redis is also a well-optimized used case, and is typically done without an extra string copy. HSET however does need to copy the resulting data into a new structure, which is where most of the time is going to be.
Comment From: gaodg
Run your test,
set bigstring <bigfilecost 8ms, and does not exceed the slowlog-log-slower-than(10ms) threshold. btw, dict insert is slower than list, so the dictionary will trigger the threshold.
Many thanks. Can you adjust slowlog setting to 2ms, and test again?
Here are my findings: 1) On a 6.0.9 version redis, even i adjusted slowlog setting to 0.5ms, i still can't get slowlog. 2) On a 4.0.12 versio redis, It seems no matter how small the slow log setting is, how big the string is, redis don't record slowlog the first time.Stable recurrence.
Below are demo process for 4.0.12 version:
sudo systemctl restart redis-server@6379
[admin@VMS8888 tmp]$ sudo systemctl restart redis-server@6379 [admin@VMS8888 tmp]$ redis-cli config set "slowlog-log-slower-than" 500 OK [admin@VMS8888 tmp]$ time redis-cli -x set bigkey <bigfile OK
real 0m2.430s
user 0m0.348s
sys 0m1.513s
[admin@VMS8888 tmp]$ redis-cli slowlog get 10 (empty array) [admin@VMS8888 tmp]$ time redis-cli -x set bigkey <bigfile OK
real 0m2.603s
user 0m0.399s
sys 0m1.552s
[admin@VMS8888 tmp]$ redis-cli slowlog get 10 1) 1) (integer) 0 2) (integer) 1611048131 3) (integer) 32088 4) 1) "set" 2) "bigkey" 3) "\x00... (524287872 more bytes)" 5) "127.0.0.1:50574" 6) ""
Many thanks, Please forgive me my poor english.
Comment From: sundb
sorry, I just cut to tag 6.0.9, and found that the performance is much slower than the product environment because it was tested in the development environment.
- I checkout to 6.0.9, and the cost time is 50 microseconds, you can set slowlog-log-slower-than to 50 to test.
- The reason why it doesn't show up the first time is that you don't need to delete the old data the first time, but when you set the same key the second time, you need to free the old val data, you can set lazyfree-lazy-server-del yes in redis.conf, so that val can free in thread.
btw, my English is also poor.
Comment From: gaodg
sorry, I just cut to tag 6.0.9, and found that the performance is much slower than the product environment because it was tested in the development environment.
- I checkout to 6.0.9, and the cost time is 50 microseconds, you can set slowlog-log-slower-than to 50 to test.
- The reason why it doesn't show up the first time is that you don't need to delete the old data the first time, but when you set the same key the second time, you need to free the old val data, you can set lazyfree-lazy-server-del yes in redis.conf, so that val can free in thread.
btw, my English is also poor.
I tested again, the result is same as yours. Did not expect redis to set the string so fast! redis 6 is so awsome!
Thanks very much.
Below are my test result, i adjust slowlog-log-slower-than to 5 to get the slowlog : 2) 1) (integer) 10066 2) (integer) 1611105771 3) (integer) 8 4) 1) "set" 2) "bigkey" 3) "\x00\x00... (524287872 more bytes)" 5) "10.62.197.12:54750" 6) "" -- even the second set is only taken 13 23) 1) (integer) 10093 2) (integer) 1611105865 3) (integer) 13 4) 1) "set" 2) "bigkey" 3) "\x00\x00... (524287872 more bytes)" 5) "10.62.197.12:54756" 6) ""
Comment From: gaodg
Setting a string in Redis is also a well-optimized used case, and is typically done without an extra string copy. HSET however does need to copy the resulting data into a new structure, which is where most of the time is going to be.
Thanks you!
Comment From: sundb
You use time xxx to calculate the time is not accurate, because it includes the time of network data transmission, redis only calculates the time of command execution, not include the time of protocol decode.
Comment From: gaodg
OK, thank you.
Comment From: sundb
@madolson I found that lazyfree has no effect on the free of large string object, lazyfreeGetFreeEffort always returns 1, is this a problem?