New: Huge latency in concurrent I/O when using data=ordered
(switching to email - please respond via emailed reply-to-all, not via the bugzilla web interface)
Quoted 113 lines · On Tue, 11 Dec 2007 11:36:39 -0800 (PST) [email protected] wrote:
http://bugzilla.kernel.org/show_bug.cgi?id=9546
Summary: Huge latency in concurrent I/O when using data=ordered
Product: File System
Version: 2.5
KernelVersion: 2.6.24-rc4
Platform: All
OS/Version: Linux
Tree: Mainline
Status: NEW
Severity: normal
Priority: P1
Component: ext3
AssignedTo: [email protected]
ReportedBy: [email protected]Most recent kernel where this bug did not occur:
Unknown, certainly not a regression, but something specific to ext3 algorithmDistribution:
Bluewhite64 12 (Slackware 12 64 bits port) and Slackware 12Hardware Environment:
Athlon 64 3000+laptop IDE 5400 80GB+1.2GB RAM
Athlon 64X2 4200+SATA 7200 200GB drive+1GB
Athlon 2800+IDE 7200 40GB drive+512MBSoftware Environment:
dd, cp, konqueror/KDE, mount/tune2fsProblem Description:
When the system does heavy input/output operations on big files, small files access from other applications are always not served for very long time. This can cause huge latencies. The system is really not usable at all, even with all the recent improvements done to increase interactivity on desktop.This behaviour is very visible with the simple following test case:
1. Build a DVD structure from big MPEG+PS files with dvdauthor (it copies the files in the DVD stucture, then pass on them to fix VOBUs, but this part is not very long so this is not the main problem).
2. While the computer is doing this, try to open a web browser such as konqueror. Then open a page from bookmark. Then open a new tab, then open another page from bookmark. Switch bak to first page.What I get is:
35 seconds to open Konqueror.
8 seconds to open the "bookmark menu". Incredible.
30 seconds to open the web page (DSL/10GBits).
5 seconds to open the second tab.
6 seconds to reopen the menu.
36 seconds to open the second page.
14 seconds to come back to first tab.
This is unbelievable! The system is completely trashed, with more than 1GB RAM, whatever the hardware configuration is used.Of course, I investigated the problem... First, DMA is OK. Second, I thought cache would make memory swapped. So I used echo 0 > swapiness. Then (of course, the system was not swapping at all), I thought TEXT sections from software discarded (that would be simply stupid, but who knows?). I then tried to make the writing process throttled with
dirty_background_ratio(say 10%) while reserving a greater RAM portion for the rest of the system withdirty_ratio(say 70%). No way. Then I launched top, and looked at the WCHAN to see what was the problem for the frozen process (ie: konqueror). The I saw the faulty guy:log_wait_commit!So I concluded there is unfair access to the filesystem journal. So I tried other journaling options than the default "ordered" data mode. The results were really different: "5s, 2s, 4s, etc.", both with journal and write back mode!
I therefore think there is a great lock and even maybe a priority inversion in
log_wait_commitof the ext3 filesystem. I think that, even if it is throttled, the writing process always get access to the journal in ordered mode, simply because it writes many pages at a time and because the ordered mode indeed implies... ordering of requests (as I understand it).It's sad this is the default option that gives the worst interactivity problems. Indeed, this messes all previous work done to enhance desktop experience I think, too bad!
Btw, I've also seen on Internet that some people reported that journal data mode gives "better" performance. I think the problem was indeed related to latency rather than performance (timing the writing process effectively shows a output rate halved with journal data mode, and twice the time to process).
Steps to reproduce:
I did a simple script:
#!/bin/bashSRC1=src1.bin
SRC2=src2.bin
DEST_DIR=tmpdir
DST1=dst.bin# First, create the source files:
if [ ! -e $SRC1 ] ; thendd if=/dev/zero of=$SRC1 bs=10k count=150000 fi if [ ! -e $SRC2 ] ; then dd if=/dev/zero of=$SRC2 bs=10k count=150000fi
mkdir $DEST_DIR >/dev/null2>&1
sync# Do the test:
echo "Trashing the system..."
rm $DEST_DIR/$DST1 >/dev/null2>&1
cp $SRC1 $DEST_DIR/$DST1
cat $SRC2 >> $DEST_DIR/$DST1
echo "Done!"#rm -rf $DEST_DIR $SRC1 $SRC2
Quoted 8 lines
While running it, try to use "normally" the interactive programs, such as konqueror (the program should have to access files, such as cookies, cache and so for konqueror). Then remount/tune the filesystem to use another data mode for ext3.
I didn't try with other journaling filesystems. I guess ext2 also doesn't exhibit the problem.
Interesting that data=writeback helped this. You don't give a lot of details, but I assume that data=writeback made a large difference here?
OK for reply to all. I'm using the first mail received.
Quoted 2 lines
Interesting that data=writeback helped this. You don't give a lot of details, but I assume that data=writeback made a large difference here?
Well, my measures were taken by counting seconds from the desktop clock, so the precision is roughly 1s. Here are the effective results from the 3 journaling modes I have done yesterday :
Times in seconds:
ordered mode : 17 5 38 19 33
journal mode : 6 1 5 6 5
writeback mode : 4 1 7 6 8
I do not remember exactly the operation sequence, but the beginning was opening Konqueror, opening the bookmarks menu, loading a page, and opening another tab.
As you can see anyway, ordered is completely broken, opening the menu is near 1s in journal and writeback mode, which is perfectly acceptable for a user (after all, the computer is loaded, and interactivity is not simply running interactive tasks at real time priority, so the the user can understand it reacts slower). Launching Konqueror in 4 to 6 seconds is a good time, given that the cache is poisoned by the writing process. Opening another tab or a web page is tolerable within 5-6s, even if this is still a little too long, specially for opening another tab of an already running process (2-3s would be a perfect value I think, but this is another story to get this). Certainly 5-6s of latency is due to the block size used by the writing process, and tuning the kernel to get lower results would be dangerous for general performances. I could do tests by asking dd to write more but smaller blocks to check this idea.
As far as writeback is concerned, the latency reduction was not clear as you can see, at least with my mesurement procedure. For performance of the **writing process**, it was nearly the same as ordered. I havn't written the timings results for the writing process, since I was still investigating at that time. But I used :
time dowrite.sh
to time it, and I got real time, as well as dd output (records written, MB/s, and journal was half as ordered). So writeback and ordered seemed the same at this level, and journal mode was effectively twice slower. It was clear there was twice as most write operations, that was the expected behaviour.
I could redo the tests, with a more formal approach (that is: fixing the operations order done in Konqueror, and noting the times for the writing process), it's easy. In fact, I'm considering doing another script simulating Konqueror / user activities and timing them automatically, just to get a reproduceable benchmark suite.
Please note that not all programs are affected (for instance kmail was quite quick), so the kernel does a good job to run programs that do not many I/Os when the fs is stressed by another process. The difference with konqueror is it is opening several files (block dump says), so my guess is that processes doing small I/O operations are not given "journal access" fairly enough in ordered mode.
Indeed, I imagine (without knowing any internals of course) that the data writing is indeed scheduled correctly by the disk scheduler, and that the writing process is throttled, but the priority informations are lost when metadata are written in ordered mode, because all I/Os are mixed for metadata. Therefore, the writing process manages to fill the journal quite easily. With journal and writeback mode, all data may be written sequentially, in the context of the issuing process, so priorities may be tracked on the whole writing process. Then the writing process is prempted correctly to the benefits of Konqueror. This is of course just "black box" hypothesis...
CC
Quoted 125 lines
(switching to email - please respond via emailed reply-to-all, not via the bugzilla web interface)
Quoted 118 lines · On Tue, 11 Dec 2007 11:36:39 -0800 (PST) [email protected] wrote:
http://bugzilla.kernel.org/show_bug.cgi?id=9546
Summary: Huge latency in concurrent I/O when using data=ordered
Product: File System
Version: 2.5
KernelVersion: 2.6.24-rc4
Platform: All
OS/Version: Linux
Tree: Mainline
Status: NEW
Severity: normal
Priority: P1
Component: ext3
AssignedTo: [email protected]
ReportedBy: [email protected]Most recent kernel where this bug did not occur:
Unknown, certainly not a regression, but something specific to ext3 algorithmDistribution:
Bluewhite64 12 (Slackware 12 64 bits port) and Slackware 12Hardware Environment:
Athlon 64 3000+laptop IDE 5400 80GB+1.2GB RAM
Athlon 64X2 4200+SATA 7200 200GB drive+1GB
Athlon 2800+IDE 7200 40GB drive+512MBSoftware Environment:
dd, cp, konqueror/KDE, mount/tune2fsProblem Description:
When the system does heavy input/output operations on big files, small files access from other applications are always not served for very long time. This can cause huge latencies. The system is really not usable at all, even with all the recent improvements done to increase interactivity on desktop.This behaviour is very visible with the simple following test case:
1. Build a DVD structure from big MPEG+PS files with dvdauthor (it copies the files in the DVD stucture, then pass on them to fix VOBUs, but this part is not very long so this is not the main problem).
2. While the computer is doing this, try to open a web browser such as konqueror. Then open a page from bookmark. Then open a new tab, then open another page from bookmark. Switch bak to first page.What I get is:
35 seconds to open Konqueror.
8 seconds to open the "bookmark menu". Incredible.
30 seconds to open the web page (DSL/10GBits).
5 seconds to open the second tab.
6 seconds to reopen the menu.
36 seconds to open the second page.
14 seconds to come back to first tab.
This is unbelievable! The system is completely trashed, with more than 1GB RAM, whatever the hardware configuration is used.Of course, I investigated the problem... First, DMA is OK. Second, I thought cache would make memory swapped. So I used echo 0 > swapiness. Then (of course, the system was not swapping at all), I thought TEXT sections from software discarded (that would be simply stupid, but who knows?). I then tried to make the writing process throttled with
dirty_background_ratio(say 10%) while reserving a greater RAM portion for the rest of the system withdirty_ratio(say 70%). No way. Then I launched top, and looked at the WCHAN to see what was the problem for the frozen process (ie: konqueror). The I saw the faulty guy:log_wait_commit!So I concluded there is unfair access to the filesystem journal. So I tried other journaling options than the default "ordered" data mode. The results were really different: "5s, 2s, 4s, etc.", both with journal and write back mode!
I therefore think there is a great lock and even maybe a priority inversion in
log_wait_commitof the ext3 filesystem. I think that, even if it is throttled, the writing process always get access to the journal in ordered mode, simply because it writes many pages at a time and because the ordered mode indeed implies... ordering of requests (as I understand it).It's sad this is the default option that gives the worst interactivity problems. Indeed, this messes all previous work done to enhance desktop experience I think, too bad!
Btw, I've also seen on Internet that some people reported that journal data mode gives "better" performance. I think the problem was indeed related to latency rather than performance (timing the writing process effectively shows a output rate halved with journal data mode, and twice the time to process).
Steps to reproduce:
I did a simple script:
#!/bin/bashSRC1=src1.bin
SRC2=src2.bin
DEST_DIR=tmpdir
DST1=dst.bin# First, create the source files:
if [ ! -e $SRC1 ] ; thendd if=/dev/zero of=$SRC1 bs=10k count=150000 fi if [ ! -e $SRC2 ] ; then dd if=/dev/zero of=$SRC2 bs=10k count=150000fi
mkdir $DEST_DIR >/dev/null2>&1
sync# Do the test:
echo "Trashing the system..."
rm $DEST_DIR/$DST1 >/dev/null2>&1
cp $SRC1 $DEST_DIR/$DST1
cat $SRC2 >> $DEST_DIR/$DST1
echo "Done!"#rm -rf $DEST_DIR $SRC1 $SRC2
While running it, try to use "normally" the interactive programs, such as konqueror (the program should have to access files, such as cookies, cache and so for konqueror). Then remount/tune the filesystem to use another data mode for ext3.
Quoted 6 lines
Quoted 3 lines
I didn't try with other journaling filesystems. I guess ext2 also doesn't exhibit the problem.
Interesting that data=writeback helped this. You don't give a lot of details, but I assume that data=writeback made a large difference here?
What I think could be happening:
One process does data-intensive load. Thus in the ordered mode the transaction is tiny but has tons of data buffers attached. If commit happens, it takes a long time to sync all the data before the commit can proceed... In the writeback mode, we don't wait for data buffers, in the journal mode amount of data to be written is really limited by the maximum size of a transaction and so we write by much smaller chunks and better latency is thus ensured.
I'll try some tests to verify whether my theory is correct :).
Honza
Signature · 2 lines
Jan Kara <[email protected]> SuSE CR Labs
Quoted 131 lines
Quoted 125 lines
(switching to email - please respond via emailed reply-to-all, not via the bugzilla web interface)
Quoted 118 lines · On Tue, 11 Dec 2007 11:36:39 -0800 (PST) [email protected] wrote:
http://bugzilla.kernel.org/show_bug.cgi?id=9546
Summary: Huge latency in concurrent I/O when using data=ordered
Product: File System
Version: 2.5
KernelVersion: 2.6.24-rc4
Platform: All
OS/Version: Linux
Tree: Mainline
Status: NEW
Severity: normal
Priority: P1
Component: ext3
AssignedTo: [email protected]
ReportedBy: [email protected]Most recent kernel where this bug did not occur:
Unknown, certainly not a regression, but something specific to ext3 algorithmDistribution:
Bluewhite64 12 (Slackware 12 64 bits port) and Slackware 12Hardware Environment:
Athlon 64 3000+laptop IDE 5400 80GB+1.2GB RAM
Athlon 64X2 4200+SATA 7200 200GB drive+1GB
Athlon 2800+IDE 7200 40GB drive+512MBSoftware Environment:
dd, cp, konqueror/KDE, mount/tune2fsProblem Description:
When the system does heavy input/output operations on big files, small files access from other applications are always not served for very long time. This can cause huge latencies. The system is really not usable at all, even with all the recent improvements done to increase interactivity on desktop.This behaviour is very visible with the simple following test case:
1. Build a DVD structure from big MPEG+PS files with dvdauthor (it copies the files in the DVD stucture, then pass on them to fix VOBUs, but this part is not very long so this is not the main problem).
2. While the computer is doing this, try to open a web browser such as konqueror. Then open a page from bookmark. Then open a new tab, then open another page from bookmark. Switch bak to first page.What I get is:
35 seconds to open Konqueror.
8 seconds to open the "bookmark menu". Incredible.
30 seconds to open the web page (DSL/10GBits).
5 seconds to open the second tab.
6 seconds to reopen the menu.
36 seconds to open the second page.
14 seconds to come back to first tab.
This is unbelievable! The system is completely trashed, with more than 1GB RAM, whatever the hardware configuration is used.Of course, I investigated the problem... First, DMA is OK. Second, I thought cache would make memory swapped. So I used echo 0 > swapiness. Then (of course, the system was not swapping at all), I thought TEXT sections from software discarded (that would be simply stupid, but who knows?). I then tried to make the writing process throttled with
dirty_background_ratio(say 10%) while reserving a greater RAM portion for the rest of the system withdirty_ratio(say 70%). No way. Then I launched top, and looked at the WCHAN to see what was the problem for the frozen process (ie: konqueror). The I saw the faulty guy:log_wait_commit!So I concluded there is unfair access to the filesystem journal. So I tried other journaling options than the default "ordered" data mode. The results were really different: "5s, 2s, 4s, etc.", both with journal and write back mode!
I therefore think there is a great lock and even maybe a priority inversion in
log_wait_commitof the ext3 filesystem. I think that, even if it is throttled, the writing process always get access to the journal in ordered mode, simply because it writes many pages at a time and because the ordered mode indeed implies... ordering of requests (as I understand it).It's sad this is the default option that gives the worst interactivity problems. Indeed, this messes all previous work done to enhance desktop experience I think, too bad!
Btw, I've also seen on Internet that some people reported that journal data mode gives "better" performance. I think the problem was indeed related to latency rather than performance (timing the writing process effectively shows a output rate halved with journal data mode, and twice the time to process).
Steps to reproduce:
I did a simple script:
#!/bin/bashSRC1=src1.bin
SRC2=src2.bin
DEST_DIR=tmpdir
DST1=dst.bin# First, create the source files:
if [ ! -e $SRC1 ] ; thendd if=/dev/zero of=$SRC1 bs=10k count=150000 fi if [ ! -e $SRC2 ] ; then dd if=/dev/zero of=$SRC2 bs=10k count=150000fi
mkdir $DEST_DIR >/dev/null2>&1
sync# Do the test:
echo "Trashing the system..."
rm $DEST_DIR/$DST1 >/dev/null2>&1
cp $SRC1 $DEST_DIR/$DST1
cat $SRC2 >> $DEST_DIR/$DST1
echo "Done!"#rm -rf $DEST_DIR $SRC1 $SRC2
While running it, try to use "normally" the interactive programs, such as konqueror (the program should have to access files, such as cookies, cache and so for konqueror). Then remount/tune the filesystem to use another data mode for ext3.
Quoted 6 lines
Quoted 3 lines
I didn't try with other journaling filesystems. I guess ext2 also doesn't exhibit the problem.
Interesting that data=writeback helped this. You don't give a lot of details, but I assume that data=writeback made a large difference here?
Quoted 9 lines
What I think could be happening:
One process does data-intensive load. Thus in the ordered mode the transaction is tiny but has tons of data buffers attached. If commit happens, it takes a long time to sync all the data before the commit can proceed... In the writeback mode, we don't wait for data buffers, in the journal mode amount of data to be written is really limited by the maximum size of a transaction and so we write by much smaller chunks and better latency is thus ensured.
I'll try some tests to verify whether my theory is correct :).
Hmm, I couldn't reproduce the bad behavior... But anyway, if my theory
is correct, attached patch should help - can you try it please? It's a debugging quality only but shouldn't do anything bad to your data :)
Honza
Signature · 2 lines
Jan Kara <[email protected]> SuSE CR Labs
Don't allow too much data buffers in a transaction.
fs/jbd/transaction.c +3 -1
@@ -163,7 +163,7 @@ repeat_locked:spin_lock (&transaction->t_handle_lock); needed = transaction->t_outstanding_credits + nblocks; -if (needed > journal->j_max_transaction_buffers) { +if (needed > journal->j_max_transaction_buffers ||atomic_read (&transaction->t_data_buf_count) >32768 ) {/* * If the current transaction is already too large, then start * to commit it: we can then go back and attach this handle to
@@ -1528,6 +1528,7 @@ static void __journal_temp_unlink_buffer(struct journal_head *jh)return ;case BJ_SyncData: list = &transaction->t_sync_datalist; +atomic_dec (&transaction->t_data_buf_count);break ;case BJ_Metadata: transaction->t_nr_buffers--;
@@ -1989,6 +1990,7 @@ void __journal_file_buffer(struct journal_head *jh,return ;case BJ_SyncData: list = &transaction->t_sync_datalist; +atomic_inc (&transaction->t_data_buf_count);break ;case BJ_Metadata: transaction->t_nr_buffers++;
include/linux/jbd.h +6 -0
@@ -541,6 +541,12 @@ struct transaction_sint t_outstanding_credits;/* +* Number of data buffers on t_sync_datalist attached to +* the transaction. +*/ +atomic_t t_data_buf_count; + +/* * Forward and backward links for the circular list of all transactions * awaiting checkpoint. [j_list_lock] */