redis-cli bgrewriteaof blocks ?

[Tim Haines]

Hi guys,

I've just upgraded to Redis 2.0.0 RC2.  I have it configured with saves turned off, and AOF updates set to everysec.

While monitoring with: redis-stat latency delay 100

I ran: redis-cli bgrewriteaof

And my jaw dropped:

233: 0.05 ms

234: 0.07 ms

235: 0.07 ms

236: 9204.92 ms

237: 37925.19 ms

238: 0.07 ms

239: 0.06 ms

Blocked for 9 seconds and then 38 seconds! (i.e. until the rewrite had finished)

This is on a box with mysql running, and under pretty heavy IO.  Is this behavior expected, or is this a bug?  Would moving the redis aof file to some dedicate drives on the same machine help?

Here's a dump of redis-cli info:

db1 ~: redis-cli info        

redis_version:1.3.15

redis_git_sha1:00000000

redis_git_dirty:0

arch_bits:64

multiplexing_api:epoll

process_id:5831

uptime_in_seconds:1449

uptime_in_days:0

connected_clients:30

connected_slaves:0

blocked_clients:0

used_memory:2174805344

used_memory_human:2.03G

changes_since_last_save:7873577

bgsave_in_progress:0

last_save_time:1278116766

bgrewriteaof_in_progress:0

total_connections_received:2655

total_commands_processed:391957

expired_keys:584

hash_max_zipmap_entries:64

hash_max_zipmap_value:512

pubsub_channels:0

pubsub_patterns:0

vm_enabled:0

role:master

db0:keys=991988,expires=4

Eek!  

Previously I was on Redis 1.2.6 and saw the same problem, except with smaller blocking periods, but perhaps more of them.

Tim.

[Salvatore Sanfilippo]

On Sat, Jul 3, 2010 at 2:57 AM, Tim Haines <tmha...@gmail.com> wrote:
> Hi guys,

Hello Tim, first: thanks for the report.

Let's try to understand what's happening here...

> I've just upgraded to Redis 2.0.0 RC2.  I have it configured with saves
> turned off, and AOF updates set to everysec.
> While monitoring with: redis-stat latency delay 100
> I ran: redis-cli bgrewriteaof
> And my jaw dropped:
> 233: 0.05 ms
> 234: 0.07 ms
> 235: 0.07 ms
> 236: 9204.92 ms
> 237: 37925.19 ms

My first guess is that this is related to the fsync() call.
Please can you relax the fsync policy and retry? Good news, you can
now do this in a pretty simple way:

% redis-cli config get appendfsync
1. appendfsync
2. everysec
% redis-cli config set appendfsync no
OK
% redis-cli config get appendfsync
1. appendfsync
2. no

Fsync sucks on Linux in general, but when there is tons of I/O at
least it has a reason to be slow ;)

> some dedicate drives on the same machine help?

I think so but before we need to make sure the problem is fsync() or
whatever it is...
I think that in a few emails and retries we can trap this, hopefully.

Thanks for the INFO output, also please if you can provide the output of:

redis-cli config get '*'

Cheers,
Salvatore

--
Salvatore 'antirez' Sanfilippo
http://invece.org

"Once you have something that grows faster than education grows,
you’re always going to get a pop culture.", Alan Kay

[Tim Haines]

Hi Salvatore,

Thanks for the mega-fast response.

So, I did as you suggested, and switched appendfsync to no.  When I ran bgrewriteaof there was a blip of about 20ms, normal operation for a few seconds, then a couple of blips of around 700ms, then normal operation.  No blocks larger than 1s.  I repeated this a couple of times.  I also switched back to  appendfsync everysec and saw similar behavior to what I reported earlier, with one block of over 30s.

Here is the config output:

db1 ~: redis-cli config get '*'

1. "dbfilename"

2. "redis-dump-file-for-worker.rdb"

3. "requirepass"

4. (nil)

5. "masterauth"

6. (nil)

7. "maxmemory"

8. "0"

9. "timeout"

10. "300"

11. "appendonly"

12. "yes"

13. "appendfsync"

14. "everysec"

15. "save"

16. ""

Cheers,

Tim.

--
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 Sanfilippo]

On Sat, Jul 3, 2010 at 4:20 AM, Tim Haines <tmha...@gmail.com> wrote:

> So, I did as you suggested, and switched appendfsync to no.  When I
> ran bgrewriteaof there was a blip of about 20ms, normal operation for a few
> seconds, then a couple of blips of around 700ms, then normal operation.  No
> blocks larger than 1s.  I repeated this a couple of times.  I also switched

Cool! So we know what happens:

While Redis is rewriting the log, the child performs a lot of disk
I/O, so fsync() starts to be super slow.
Now there are two options:

1) If you don't have problems to loose up to 30 seconds of data on
crash, you can leave the fsync policy to "no".
2) If you want to be both safer and still don't have this problem with
the I/O is caused by Redis itself it's possible to do this:

redis-cli config no-appendfsync_on_rewrite yes

This will disable fsync *only* when there is a bgsave or bgrewriteaof
in progress. The problem is, this is 2.2 only, but there is no reason
why this is not backported to Redis 2.0, so expect an RC3 soon
(probably the start of the next week) where this feature is
backported.

3) ... if you know some tweak to make fsync() on Linux faster this can
help as well ;)

Thank you for your help. There is no better thing about this we can
actually do for now. The only other strategy is writing the buffer and
then flushing it via an additional thread, but since you saw that the
latency is so high when there is I/O contention, what meaning will
have "everysec" in this context? It will not be honored anyway, so why
don't just use "no" that will flush at max every 30 seconds anyway?

Note that fsync()ing in another thread will block write(2) as well.
Also any "in other thread" strategy is not applicable with "fsync
always" policy that is guaranteed to return OK to the caller only
*after* the data is written in the AOF.

The new 2.2 option saves a lot of problems, unless the everysec
requirements can't be relaxed for a few seconds while rewriting the
log, or when the heavy I/O is performed by a non-redis process running
in the same box.

[Tim Haines]

Hey,

The new option you have in 2.2 sounds like an improvement. I expect
I'll still have heavy io occasionally due to mysql persisting to the
same drive, so I should expect to continue to see long multi-second
blocks in this scenario? Would using a dedicated drive resolve the
issue, or is the bottleneck likely to be some place before the drive?

Cheers,

Tim.

[Tim Haines]

Hi Salvatore,

Just looking into this a little more.  I just monitored the latency while I was deleting an old backup file that was around 70GB in size.  During the delete operation, Redis didn't respond for 80 seconds.  Going by your previous email this is because it was waiting to do an fsync (set to everysec), and couldn't do anything else.  From what you've said, and reviewing the docs, setting fsync to 'no' will mean that the writes to the AOF file on disk will be delayed until the OS feels like writing.  I'm going to do that for now, as I can tolerate losing a minute or two of writes if need be.

Not knowing too much about how this works at an OS level, I'm wondering if it makes sense to  have an fsync setting similar to everysec that attempts an fsync, and if it takes longer than 20ms for example, it gives up, logs that it gave up, and processes some other requests, and then retries fsync the next second?  

Tim.