Why do write calls sometimes block for a long time in Linux?
Update: Explanation at the bottom.
Anyone know why fwrite() calls sometimes block?
Here is a test I did. I sequentially append 4096 byte chunks to 10 files in a round robin fashion. Throughput is artificially limited to a fixed rate set at about 1/4 the maximum throughput of the drives, which I accomplish by sleeping at subsecond intervals in between my writes. I time each call to write. My expectation is that writes go immediately to pagecache and are asynchronously written out to disk (unless I were to call fsync, which I don’t).
In fact this is usually what happens, the average time is just a few microseconds, but sometimes the write calls block for somewhere between 400 ms and a few seconds. I am using Linux 3.6.32 (RHEL 6) with ext4. I am using default configurations otherwise (no change to any of the /proc/sys/vm stuff and fiddling with those parameters don’t seem to help).
Here is a trace of average and max latencies taken over 1 second intervals. Note the regular spikes. What is the cause of this? Locking between the flush threads and the write thread? Is there anything you can do to mitigate it? This effects anything that does logging—i.e. almost everything.
I understand why this would happen if I exceeded the throughput that Linux’s background flush threads can handle, but that is clearly not the case here as the drive can sustain 400MB writes over a long period.
I tried this on a few different machines, some with RAID, some with a single disk and all showed the same behavior to varying degrees.
|Throughput (mb/sec)||Avg. Latency (ms)||Max Latency (ms)|
A number of people gave interesting and helpful suggestions, such as “this is your punishment for not using Solaris.” The best suggestion was from Mark Wolfe which was to install latencytop and measure it. To do this on Red Hat you need to install their debug kernel and reboot with that, then latencytop will capture the highest latency kernel operations for each process. This gives a great deal of insight into what is going on.
For those who are curious here are a few of the traces that pop up as causing hundreds of ms of latency:
vfs_write() do_sync_write() ext4_file_write() generic_file_aio_write() ext4_da_write_begin() [in this case da means delayed allocation] block_write_begin() __block_prepare_write() ext4_da_get_block_prep() ext4_get_block_prep() ext4_get_blocks() call_rw_sem_down_read_failed()
This trace seems to be due to delayed allocation. Turing off delayed allocation makes it go away, though probably at the cost of some throughput.Here is another one, this one seems to be related to journalling.
sys_write() vfs_write() do_sync_write() ext4_file_write() generic_file_aio_write() __generic_file_aio_write() file_update_time() __mark_inode_dirty() ext4_dirty_inode() ext4_journal_start_sb() jbd2_journal_start() start_this_handle()You can check out the details of the code in one of these nice Linux kernel code browsers. My take away from all this was that maybe it is time to look at XFS since that allegedly also has better file locking for fsync which is my other problem.