write() hangs during flush

write() hangs during flush

[Brian Malehorn]

Hi,

I'm debugging an issue where write() can sometimes take several
seconds to complete. I'm looking for general guidance on why this
might happen, and what I can do about it.

While I originally encountered the problem on an embedded device
writing to an MMC, I can also reproduce it on my laptop (Ubuntu
16.04):

    pv -L 100m /dev/zero |
      strace -s 8 -T -e trace=write dd bs=32k of=./zero 2>&1 |
      awk 'substr($NF, 2, length($NF)-2) + 0 > 0.1'

    write(1, "\0\0\0\0\0\0\0\0"..., 32768) = 32768 <0.145895>
    write(1, "\0\0\0\0\0\0\0\0"..., 32768) = 32768 <0.673575>
    write(1, "\0\0\0\0\0\0\0\0"..., 32768) = 32768 <0.126722>
    write(1, "\0\0\0\0\0\0\0\0"..., 32768) = 32768 <1.284791>

In the above example, I write 100 MiB / second, and print out any
write() that took over 100 ms. In the output, the slowest write was
1.28 seconds. I can provide more details about the setup if needed.

I believe this is happening:

  1. accumulate lots of data in cache
  2. filesystem decides to flush
  3. nobody can write during flush
  4. flush flushes "a lot" of data - maybe everything

Do my guesses align with reality, or is there another explanation?

Does anybody have ideas on how to make this more "smooth"? Ideally,
I'd like each write() to be slowed down a little bit, rather than
99.99% of writes completing instantly and 0.01% taking over a second.

Thanks,
Brian

Re: write() hangs during flush

[Darrick J. Wong]

On Wed, Jul 19, 2017 at 11:07:08PM -0700, Brian Malehorn wrote:
> Hi,
> 
> I'm debugging an issue where write() can sometimes take several
> seconds to complete. I'm looking for general guidance on why this
> might happen, and what I can do about it.
> 
> While I originally encountered the problem on an embedded device
> writing to an MMC, I can also reproduce it on my laptop (Ubuntu
> 16.04):
> 
>     pv -L 100m /dev/zero |
>       strace -s 8 -T -e trace=write dd bs=32k of=./zero 2>&1 |
>       awk 'substr($NF, 2, length($NF)-2) + 0 > 0.1'
> 
>     write(1, "\0\0\0\0\0\0\0\0"..., 32768) = 32768 <0.145895>
>     write(1, "\0\0\0\0\0\0\0\0"..., 32768) = 32768 <0.673575>
>     write(1, "\0\0\0\0\0\0\0\0"..., 32768) = 32768 <0.126722>
>     write(1, "\0\0\0\0\0\0\0\0"..., 32768) = 32768 <1.284791>
> 
> In the above example, I write 100 MiB / second, and print out any
> write() that took over 100 ms. In the output, the slowest write was
> 1.28 seconds. I can provide more details about the setup if needed.
> 
> I believe this is happening:
> 
>   1. accumulate lots of data in cache
>   2. filesystem decides to flush
>   3. nobody can write during flush
>   4. flush flushes "a lot" of data - maybe everything
> 
> Do my guesses align with reality, or is there another explanation?
> 
> Does anybody have ideas on how to make this more "smooth"? Ideally,
> I'd like each write() to be slowed down a little bit, rather than
> 99.99% of writes completing instantly and 0.01% taking over a second.

/proc/sys/vm/dirty* knobs?

--D

> 
> Thanks,
> Brian