LinuxLists.cc - ext4 out of order when use cfq scheduler

2015-12-22 06:32:46

Subject: ext4 out of order when use cfq scheduler

Hi EXT4 developers,

I am doing the power failure on a storage device. We are arm embedded system.

Test environment:
Kernel: 3.10.63
Test type: power failure
File create type: O_SYNC flag enabled
Mount option: data=ordered, journal_checksum,barrier=1
IO scheduler: CFQ

Debug method: kernel print every block number of write request. print whether it is journal block. print whether it is (REQ_FUA | REQ_META | write)
After system startup, backup journal blocks before mount the test partition.

Below is analysis which I think there is a out of order:
hp0000017aMhWY3i0vMv is the file which checksum is error. Only half of the file contents is correct.

[root@SiRFatlas6 ~]# debugfs /dev/nandblk0p3
debugfs 1.42.9 (28-Dec-2013)
debugfs: imap test/hp0000017aMhWY3i0vMv
Inode 390 is part of block group 0
located at block 141, offset 0x0280

00000280 80 81 00 00 10 00 04 00 c8 09 00 00 66 0a 00 00 |............f...|
00000290 66 0a 00 00 00 00 00 00 00 00 01 00 04 02 00 00 |f...............|
000002a0 00 00 08 00 01 00 00 00 0a f3 02 00 04 00 00 00 |................|
000002b0 00 00 00 00 00 00 00 00 80 00 00 00 00 2c 01 00 |.............,..| ==> the file contents is at 0x00012c00
000002c0 80 00 00 00 01 00 00 00 8e 26 01 00 00 00 00 00 |.........&......|

Search the block number from the journal blocks:

[root@SiRFatlas6 ~]# hexdump j.bin -C | grep "00 2c 01 00"
00039ab0 00 00 00 00 00 00 00 00 80 00 00 00 00 2c 01 00 |.............,..|

Search file name which the file checksum is error in journal blocks:

[root@SiRFatlas6 ~]# hexdump j.bin -C | grep "3i0vMv" -B1
00030c60 86 01 00 00 1c 00 14 01 68 70 30 30 30 30 30 31 |........hp000001|
00030c70 37 61 4d 68 57 59 33 69 30 76 4d 76 88 01 00 00 |7aMhWY3i0vMv....|

List all journal block record to check which journal block records it:

[root@SiRFatlas6 ~]# hexdump j.bin -C | grep "c0 3b 39 98"
00000000 c0 3b 39 98 00 00 00 04 00 00 00 00 00 00 08 00 |.;9.............|
00000800 c0 3b 39 98 00 00 00 05 00 00 00 6f 00 00 00 24 |.;9........o...$|
00001000 c0 3b 39 98 00 00 00 01 00 00 00 6f 00 00 00 75 |.;9........o...u|
0000c800 c0 3b 39 98 00 00 00 02 00 00 00 6f 00 00 00 00 |.;9........o....|
0000d000 c0 3b 39 98 00 00 00 01 00 00 00 70 00 00 00 65 |.;9........p...e|
00016000 c0 3b 39 98 00 00 00 02 00 00 00 70 00 00 00 00 |.;9........p....|
00016800 c0 3b 39 98 00 00 00 01 00 00 00 71 00 00 00 7c |.;9........q...||
00021000 c0 3b 39 98 00 00 00 02 00 00 00 71 00 00 00 00 |.;9........q....|
00021800 c0 3b 39 98 00 00 00 01 00 00 00 72 00 00 00 82 |.;9........r....|
0002d000 c0 3b 39 98 00 00 00 02 00 00 00 72 00 00 00 00 |.;9........r....|
0002d800 c0 3b 39 98 00 00 00 01 00 00 00 73 00 00 00 88 |.;9........s....| ==>00039ab0 is in last block, the file name and the start block number are all recorded in the journals.
0003a000 c0 3b 39 98 00 00 00 02 00 00 00 73 00 00 00 00 |.;9........s....|

Back to see the kernel log which it print all the block numbers:

...
...
[ 46.222671] 244109 75277
[ 46.222693]
[ 46.272438] 244352 75520
[ 46.272460]
[ 46.348417] 238443 69611
[ 46.348438]
[ 46.349811] 244480 75648
[ 46.352287]
[ 46.404904] 244609 75777
[ 46.404926]
[ 46.454698] 244738 75906
[ 46.454719]
[ 46.505439] 244992 76160
[ 46.505459]
[ 46.557783] 245120 76288
[ 46.557804]
[ 46.610075] 245249 76417
[ 46.610096]
[ 46.660196] 245378 76546
[ 46.660219]
[ 46.709906] 201691 32859 ==> journal start is 32768, so the offset is 91, block size=2048, so, the offset address in the j.bin is 0x2d800
[ 46.709928] J [ 46.711233]
[ 46.740635] drop to 9v
[ 46.749540] 201716 32884
[ 46.749560] J S
[ 46.751039]
[ 46.753151] 245632 76800 ==> 76800 in hex is 0x012c00, it is the same start block of the file which checksum is error.
[ 46.755284]
nanddisk idle -> 1.
[ 46.800227] 6v irq-2

The j.bin offset 0x2d800

0002d800 c0 3b 39 98 00 00 00 01 00 00 00 73 00 00 00 88 |.;9........s....| ==>00039ab0 is in last block
0003a000 c0 3b 39 98 00 00 00 02 00 00 00 73 00 00 00 00 |.;9........s....|

Normally, ext4 will first write the file contents, and then write the journal and journal commit. Then after some delay, it will write the meta data.
So The journal blocks contains the meta data of the file which the file contents already been written before.
But from above analysis, the journal sequence 0x73 already contain the file name(hp0000017aMhWY3i0vMv) and the start block number(76800). So from the kernel log, the block number(76800) should be available before the journal blocks but NOT after it.
It seems that there is out of order happen.

Could you please help to check this issue ? or give a explanation about it ?
Many thanks.

Best regards

Weller HUANG

2015-12-22 15:00:39

by Jan Kara

[permalink] [raw]

Subject: Re: ext4 out of order when use cfq scheduler

Hello,

On Tue 22-12-15 06:24:29, HUANG Weller (CM/EPF1-CN) wrote:
> I am doing the power failure on a storage device. We are arm embedded
> system.
>
> Test environment:
> Kernel: 3.10.63
> Test type: power failure
> File create type: O_SYNC flag enabled
> Mount option: data=ordered, journal_checksum,barrier=1
> IO scheduler: CFQ
>
> Debug method: kernel print every block number of write request. print
> whether it is journal block. print whether it is (REQ_FUA | REQ_META |
> write) After system startup, backup journal blocks before mount the test
> partition.

Do you know blktrace / blkparse tools? They would give you this information
without the need of patching the kernel...

> Below is analysis which I think there is a out of order:
> hp0000017aMhWY3i0vMv is the file which checksum is error. Only half of
> the file contents is correct.

Can you post the test program you are using? What is in the incorrect
block? Previous content of the file or some random garbage? If you are just
overwriting the file and see old contents, that could happen and is legal (we
just guarantee newly allocated blocks are first written out).

Is the problem reproducible?

Honza

> [root@SiRFatlas6 ~]# debugfs /dev/nandblk0p3
> debugfs 1.42.9 (28-Dec-2013)
> debugfs: imap test/hp0000017aMhWY3i0vMv
> Inode 390 is part of block group 0
> located at block 141, offset 0x0280
>
> 00000280 80 81 00 00 10 00 04 00 c8 09 00 00 66 0a 00 00 |............f...|
> 00000290 66 0a 00 00 00 00 00 00 00 00 01 00 04 02 00 00 |f...............|
> 000002a0 00 00 08 00 01 00 00 00 0a f3 02 00 04 00 00 00 |................|
> 000002b0 00 00 00 00 00 00 00 00 80 00 00 00 00 2c 01 00 |.............,..| ==> the file contents is at 0x00012c00
> 000002c0 80 00 00 00 01 00 00 00 8e 26 01 00 00 00 00 00 |.........&......|
>
>
> Search the block number from the journal blocks:
>
> [root@SiRFatlas6 ~]# hexdump j.bin -C | grep "00 2c 01 00"
> 00039ab0 00 00 00 00 00 00 00 00 80 00 00 00 00 2c 01 00 |.............,..|
>
> Search file name which the file checksum is error in journal blocks:
>
> [root@SiRFatlas6 ~]# hexdump j.bin -C | grep "3i0vMv" -B1
> 00030c60 86 01 00 00 1c 00 14 01 68 70 30 30 30 30 30 31 |........hp000001|
> 00030c70 37 61 4d 68 57 59 33 69 30 76 4d 76 88 01 00 00 |7aMhWY3i0vMv....|
>
>
> List all journal block record to check which journal block records it:
>
> [root@SiRFatlas6 ~]# hexdump j.bin -C | grep "c0 3b 39 98"
> 00000000 c0 3b 39 98 00 00 00 04 00 00 00 00 00 00 08 00 |.;9.............|
> 00000800 c0 3b 39 98 00 00 00 05 00 00 00 6f 00 00 00 24 |.;9........o...$|
> 00001000 c0 3b 39 98 00 00 00 01 00 00 00 6f 00 00 00 75 |.;9........o...u|
> 0000c800 c0 3b 39 98 00 00 00 02 00 00 00 6f 00 00 00 00 |.;9........o....|
> 0000d000 c0 3b 39 98 00 00 00 01 00 00 00 70 00 00 00 65 |.;9........p...e|
> 00016000 c0 3b 39 98 00 00 00 02 00 00 00 70 00 00 00 00 |.;9........p....|
> 00016800 c0 3b 39 98 00 00 00 01 00 00 00 71 00 00 00 7c |.;9........q...||
> 00021000 c0 3b 39 98 00 00 00 02 00 00 00 71 00 00 00 00 |.;9........q....|
> 00021800 c0 3b 39 98 00 00 00 01 00 00 00 72 00 00 00 82 |.;9........r....|
> 0002d000 c0 3b 39 98 00 00 00 02 00 00 00 72 00 00 00 00 |.;9........r....|
> 0002d800 c0 3b 39 98 00 00 00 01 00 00 00 73 00 00 00 88 |.;9........s....| ==>00039ab0 is in last block, the file name and the start block number are all recorded in the journals.
> 0003a000 c0 3b 39 98 00 00 00 02 00 00 00 73 00 00 00 00 |.;9........s....|
>
>
> Back to see the kernel log which it print all the block numbers:
>
> ...
> ...
> [ 46.222671] 244109 75277
> [ 46.222693]
> [ 46.272438] 244352 75520
> [ 46.272460]
> [ 46.348417] 238443 69611
> [ 46.348438]
> [ 46.349811] 244480 75648
> [ 46.352287]
> [ 46.404904] 244609 75777
> [ 46.404926]
> [ 46.454698] 244738 75906
> [ 46.454719]
> [ 46.505439] 244992 76160
> [ 46.505459]
> [ 46.557783] 245120 76288
> [ 46.557804]
> [ 46.610075] 245249 76417
> [ 46.610096]
> [ 46.660196] 245378 76546
> [ 46.660219]
> [ 46.709906] 201691 32859 ==> journal start is 32768, so the offset is 91, block size=2048, so, the offset address in the j.bin is 0x2d800
> [ 46.709928] J [ 46.711233]
> [ 46.740635] drop to 9v
> [ 46.749540] 201716 32884
> [ 46.749560] J S
> [ 46.751039]
> [ 46.753151] 245632 76800 ==> 76800 in hex is 0x012c00, it is the same start block of the file which checksum is error.
> [ 46.755284]
> nanddisk idle -> 1.
> [ 46.800227] 6v irq-2
>
>
> The j.bin offset 0x2d800
>
> 0002d800 c0 3b 39 98 00 00 00 01 00 00 00 73 00 00 00 88 |.;9........s....| ==>00039ab0 is in last block
> 0003a000 c0 3b 39 98 00 00 00 02 00 00 00 73 00 00 00 00 |.;9........s....|
>
>
> Normally, ext4 will first write the file contents, and then write the
> journal and journal commit. Then after some delay, it will write the meta
> data. So The journal blocks contains the meta data of the file which the
> file contents already been written before. But from above analysis, the
> journal sequence 0x73 already contain the file name(hp0000017aMhWY3i0vMv)
> and the start block number(76800). So from the kernel log, the block
> number(76800) should be available before the journal blocks but NOT after
> it. It seems that there is out of order happen.
>
> Could you please help to check this issue ? or give a explanation about
> it ? Many thanks.
>
> Best regards
>
> Weller HUANG
>
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-ext4" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
--
Jan Kara <[email protected]>
SUSE Labs, CR

2016-01-05 15:30:46

by Jan Kara

[permalink] [raw]

Subject: Re: ext4 out of order when use cfq scheduler

On Mon 04-01-16 05:25:15, HUANG Weller (CM/ESW12-CN) wrote:
> > -----Original Message-----
> > From: Jan Kara [mailto:[email protected]]
> > Sent: Tuesday, December 22, 2015 11:01 PM
> > To: HUANG Weller (CM/EPF1-CN) <[email protected]>
> > Cc: [email protected]; Li, Michael <[email protected]>
> > Subject: Re: ext4 out of order when use cfq scheduler
> >
> > Hello,
> >
> > On Tue 22-12-15 06:24:29, HUANG Weller (CM/EPF1-CN) wrote:
> > > I am doing the power failure on a storage device. We are arm
> > > embedded system.
> > >
> > > Test environment:
> > > Kernel: 3.10.63
> > > Test type: power failure
> > > File create type: O_SYNC flag enabled Mount option: data=ordered,
> > > journal_checksum,barrier=1 IO scheduler:
> > > CFQ
> > >
> > > Debug method: kernel print every block number of write request.
> > > print whether it is journal block. print whether it is (REQ_FUA |
> > > REQ_META
> > > |
> > > write) After system startup, backup journal blocks before mount the
> > > test partition.
> >
> > Do you know blktrace / blkparse tools? They would give you this
> > information without the need of patching the kernel...
>
> Yes, I know that tool. Normally, I use that tool, but in this case, I patch kernel because of following reasons:
> 1. this is power failure test, blktrace might not catch some log near to the power failure.
> 2. I add some calculation when print these block numbers in the kernel patch. So I can directly use the value print from kernel.
> blktrace give me lots of logs and I have to do block number conversion one by one.

OK, fair enough.

> > > Below is analysis which I think there is a out of order:
> > > hp0000017aMhWY3i0vMv is the file which checksum is error. Only half
> > > of the file contents is correct.
> >
> > Can you post the test program you are using? What is in the incorrect block?
> > Previous content of the file or some random garbage? If you are just
> > overwriting the file and see old contents, that could happen and is
> > legal (we just guarantee newly allocated blocks are first written out).
> >
> > Is the problem reproducible?
>
> The test tool(attached in this mail) not rewrite a file but create many
> files after delete the old test files in every new test round. The test
> tool create file in this way: filename format: hp[HEX NUMBER][RANDOM
> STRING]. For example: hp0000017aMhWY3i0vMv, hex number: 0000017a random
> string: MhWY3i0vMv
>
> The file contents has some relationship to the file name. every 512
> bytes has its own checksum and sequence number. Also contain the file
> name and the random string. So we can easily trace the file contents(see
> the attached picture).

I see.

> >What is in the incorrect block?
>
> Since I clean the test partition with /dev/zero, so what I saw is that,
> half of the file is ok. But the rest are 0. !!!! But another information
> is that:!!!! hp0000017aMhWY3i0vMv is not the last file. from the number
> in the file name , we can know there still 3 files created after it and
> these files are all checksum OK. Except the last file is zero length.
>
> This issue is very easy to reproducible. Even we test with emmc, we also
> see this issue. If you need I to do anymore test, just let me know.

So you are running in 'ws' mode of your tool, am I right? Just looking into
the sources you've sent me I've noticed that although you set O_SYNC in
openflg when mode == MODE_WS, you do not use openflg at all. So file won't
be synced at all. That would well explain why you see that not all file
contents is written. So did you just send me a different version of the
source or is your test program really buggy?

Honza

> > > [root@SiRFatlas6 ~]# debugfs /dev/nandblk0p3 debugfs 1.42.9
> > > (28-Dec-2013)
> > > debugfs: imap test/hp0000017aMhWY3i0vMv Inode 390 is part of block
> > > group 0
> > > located at block 141, offset 0x0280
> > >
> > > 00000280 80 81 00 00 10 00 04 00 c8 09 00 00 66 0a 00 00
> > > |............f...|
> > > 00000290 66 0a 00 00 00 00 00 00 00 00 01 00 04 02 00 00
> > > |f...............|
> > > 000002a0 00 00 08 00 01 00 00 00 0a f3 02 00 04 00 00 00
> > > |................|
> > > 000002b0 00 00 00 00 00 00 00 00 80 00 00 00 00 2c 01 00
> > > |.............,..| ==> the file contents is at 0x00012c00
> > > 000002c0 80 00 00 00 01 00 00 00 8e 26 01 00 00 00 00 00
> > > |.........&......|
> > >
> > >
> > > Search the block number from the journal blocks:
> > >
> > > [root@SiRFatlas6 ~]# hexdump j.bin -C | grep "00 2c 01 00"
> > > 00039ab0 00 00 00 00 00 00 00 00 80 00 00 00 00 2c 01 00
> > > |.............,..|
> > >
> > > Search file name which the file checksum is error in journal blocks:
> > >
> > > [root@SiRFatlas6 ~]# hexdump j.bin -C | grep "3i0vMv" -B1
> > > 00030c60 86 01 00 00 1c 00 14 01 68 70 30 30 30 30 30 31
> > > |........hp000001|
> > > 00030c70 37 61 4d 68 57 59 33 69 30 76 4d 76 88 01 00 00
> > > |7aMhWY3i0vMv....|
> > >
> > >
> > > List all journal block record to check which journal block records it:
> > >
> > > [root@SiRFatlas6 ~]# hexdump j.bin -C | grep "c0 3b 39 98"
> > > 00000000 c0 3b 39 98 00 00 00 04 00 00 00 00 00 00 08 00
> > > |.;9.............|
> > > 00000800 c0 3b 39 98 00 00 00 05 00 00 00 6f 00 00 00 24
> > > |.;9........o...$|
> > > 00001000 c0 3b 39 98 00 00 00 01 00 00 00 6f 00 00 00 75
> > > |.;9........o...u|
> > > 0000c800 c0 3b 39 98 00 00 00 02 00 00 00 6f 00 00 00 00
> > > |.;9........o....|
> > > 0000d000 c0 3b 39 98 00 00 00 01 00 00 00 70 00 00 00 65
> > > |.;9........p...e|
> > > 00016000 c0 3b 39 98 00 00 00 02 00 00 00 70 00 00 00 00
> > > |.;9........p....|
> > > 00016800 c0 3b 39 98 00 00 00 01 00 00 00 71 00 00 00 7c
> > > |.;9........q...||
> > > 00021000 c0 3b 39 98 00 00 00 02 00 00 00 71 00 00 00 00
> > > |.;9........q....|
> > > 00021800 c0 3b 39 98 00 00 00 01 00 00 00 72 00 00 00 82
> > > |.;9........r....|
> > > 0002d000 c0 3b 39 98 00 00 00 02 00 00 00 72 00 00 00 00
> > > |.;9........r....|
> > > 0002d800 c0 3b 39 98 00 00 00 01 00 00 00 73 00 00 00 88
> > > |.;9........s....|
> > ==>00039ab0 is in last block, the file name and the start block number
> > are all recorded in the journals.
> > > 0003a000 c0 3b 39 98 00 00 00 02 00 00 00 73 00 00 00 00
> > > |.;9........s....|
> > >
> > >
> > > Back to see the kernel log which it print all the block numbers:
> > >
> > > ...
> > > ...
> > > [ 46.222671] 244109 75277
> > > [ 46.222693]
> > > [ 46.272438] 244352 75520
> > > [ 46.272460]
> > > [ 46.348417] 238443 69611
> > > [ 46.348438]
> > > [ 46.349811] 244480 75648
> > > [ 46.352287]
> > > [ 46.404904] 244609 75777
> > > [ 46.404926]
> > > [ 46.454698] 244738 75906
> > > [ 46.454719]
> > > [ 46.505439] 244992 76160
> > > [ 46.505459]
> > > [ 46.557783] 245120 76288
> > > [ 46.557804]
> > > [ 46.610075] 245249 76417
> > > [ 46.610096]
> > > [ 46.660196] 245378 76546
> > > [ 46.660219]
> > > [ 46.709906] 201691 32859 ==> journal start is 32768, so the offset is 91,
> > block size=2048, so, the offset address in the j.bin is 0x2d800
> > > [ 46.709928] J [ 46.711233]
> > > [ 46.740635] drop to 9v
> > > [ 46.749540] 201716 32884
> > > [ 46.749560] J S
> > > [ 46.751039]
> > > [ 46.753151] 245632 76800 ==> 76800 in hex is 0x012c00, it is the same start
> > block of the file which checksum is error.
> > > [ 46.755284]
> > > nanddisk idle -> 1.
> > > [ 46.800227] 6v irq-2
> > >
> > >
> > > The j.bin offset 0x2d800
> > >
> > > 0002d800 c0 3b 39 98 00 00 00 01 00 00 00 73 00 00 00 88
> > > |.;9........s....| ==>00039ab0 is in last block
> > > 0003a000 c0 3b 39 98 00 00 00 02 00 00 00 73 00 00 00 00
> > > |.;9........s....|
> > >
> > >
> > > Normally, ext4 will first write the file contents, and then write
> > > the journal and journal commit. Then after some delay, it will write
> > > the meta data. So The journal blocks contains the meta data of the
> > > file which the file contents already been written before. But from
> > > above analysis, the journal sequence 0x73 already contain the file
> > > name(hp0000017aMhWY3i0vMv) and the start block number(76800). So
> > > from the kernel log, the block
> > > number(76800) should be available before the journal blocks but NOT
> > > after it. It seems that there is out of order happen.
> > >
> > > Could you please help to check this issue ? or give a explanation
> > > about it ? Many thanks.
> > >
> > > Best regards
> > >
> > > Weller HUANG
> > >
> > >
> > > --
> > > To unsubscribe from this list: send the line "unsubscribe linux-ext4"
> > > in the body of a message to [email protected] More majordomo
> > > info at http://vger.kernel.org/majordomo-info.html
> > --
> > Jan Kara <[email protected]>
> > SUSE Labs, CR

--
Jan Kara <[email protected]>
SUSE Labs, CR

2016-01-06 02:39:31

by HUANG Weller (CM/ESW12-CN)

[permalink] [raw]

Subject: RE: ext4 out of order when use cfq scheduler

> So you are running in 'ws' mode of your tool, am I right? Just looking into the
> sources you've sent me I've noticed that although you set O_SYNC in openflg
> when mode == MODE_WS, you do not use openflg at all. So file won't be synced
> at all. That would well explain why you see that not all file contents is written. So
> did you just send me a different version of the source or is your test program
> really buggy?
>

Yes, it is a bug of the test code. So the test tool create files without O_SYNC flag actually.
But , even in this case, is the out of order acceptable ? or is it normal ?

>
> > > > [root@SiRFatlas6 ~]# debugfs /dev/nandblk0p3 debugfs 1.42.9
> > > > (28-Dec-2013)
> > > > debugfs: imap test/hp0000017aMhWY3i0vMv Inode 390 is part of
> > > > block group 0
> > > > located at block 141, offset 0x0280
> > > >
> > > > 00000280 80 81 00 00 10 00 04 00 c8 09 00 00 66 0a 00 00
> > > > |............f...|
> > > > 00000290 66 0a 00 00 00 00 00 00 00 00 01 00 04 02 00 00
> > > > |f...............|
> > > > 000002a0 00 00 08 00 01 00 00 00 0a f3 02 00 04 00 00 00
> > > > |................|
> > > > 000002b0 00 00 00 00 00 00 00 00 80 00 00 00 00 2c 01 00
> > > > |.............,..| ==> the file contents is at 0x00012c00
> > > > 000002c0 80 00 00 00 01 00 00 00 8e 26 01 00 00 00 00 00
> > > > |.........&......|
> > > >
> > > >
> > > > Search the block number from the journal blocks:
> > > >
> > > > [root@SiRFatlas6 ~]# hexdump j.bin -C | grep "00 2c 01 00"
> > > > 00039ab0 00 00 00 00 00 00 00 00 80 00 00 00 00 2c 01 00
> > > > |.............,..|
> > > >
> > > > Search file name which the file checksum is error in journal blocks:
> > > >
> > > > [root@SiRFatlas6 ~]# hexdump j.bin -C | grep "3i0vMv" -B1
> > > > 00030c60 86 01 00 00 1c 00 14 01 68 70 30 30 30 30 30 31
> > > > |........hp000001|
> > > > 00030c70 37 61 4d 68 57 59 33 69 30 76 4d 76 88 01 00 00
> > > > |7aMhWY3i0vMv....|
> > > >
> > > >
> > > > List all journal block record to check which journal block records it:
> > > >
> > > > [root@SiRFatlas6 ~]# hexdump j.bin -C | grep "c0 3b 39 98"
> > > > 00000000 c0 3b 39 98 00 00 00 04 00 00 00 00 00 00 08 00
> > > > |.;9.............|
> > > > 00000800 c0 3b 39 98 00 00 00 05 00 00 00 6f 00 00 00 24
> > > > |.;9........o...$|
> > > > 00001000 c0 3b 39 98 00 00 00 01 00 00 00 6f 00 00 00 75
> > > > |.;9........o...u|
> > > > 0000c800 c0 3b 39 98 00 00 00 02 00 00 00 6f 00 00 00 00
> > > > |.;9........o....|
> > > > 0000d000 c0 3b 39 98 00 00 00 01 00 00 00 70 00 00 00 65
> > > > |.;9........p...e|
> > > > 00016000 c0 3b 39 98 00 00 00 02 00 00 00 70 00 00 00 00
> > > > |.;9........p....|
> > > > 00016800 c0 3b 39 98 00 00 00 01 00 00 00 71 00 00 00 7c
> > > > |.;9........q...||
> > > > 00021000 c0 3b 39 98 00 00 00 02 00 00 00 71 00 00 00 00
> > > > |.;9........q....|
> > > > 00021800 c0 3b 39 98 00 00 00 01 00 00 00 72 00 00 00 82
> > > > |.;9........r....|
> > > > 0002d000 c0 3b 39 98 00 00 00 02 00 00 00 72 00 00 00 00
> > > > |.;9........r....|
> > > > 0002d800 c0 3b 39 98 00 00 00 01 00 00 00 73 00 00 00 88
> > > > |.;9........s....|
> > > ==>00039ab0 is in last block, the file name and the start block
> > > number are all recorded in the journals.
> > > > 0003a000 c0 3b 39 98 00 00 00 02 00 00 00 73 00 00 00 00
> > > > |.;9........s....|
> > > >
> > > >
> > > > Back to see the kernel log which it print all the block numbers:
> > > >
> > > > ...
> > > > ...
> > > > [ 46.222671] 244109 75277
> > > > [ 46.222693]
> > > > [ 46.272438] 244352 75520
> > > > [ 46.272460]
> > > > [ 46.348417] 238443 69611
> > > > [ 46.348438]
> > > > [ 46.349811] 244480 75648
> > > > [ 46.352287]
> > > > [ 46.404904] 244609 75777
> > > > [ 46.404926]
> > > > [ 46.454698] 244738 75906
> > > > [ 46.454719]
> > > > [ 46.505439] 244992 76160
> > > > [ 46.505459]
> > > > [ 46.557783] 245120 76288
> > > > [ 46.557804]
> > > > [ 46.610075] 245249 76417
> > > > [ 46.610096]
> > > > [ 46.660196] 245378 76546
> > > > [ 46.660219]
> > > > [ 46.709906] 201691 32859 ==> journal start is 32768, so the offset is 91,
> > > block size=2048, so, the offset address in the j.bin is 0x2d800
> > > > [ 46.709928] J [ 46.711233]
> > > > [ 46.740635] drop to 9v
> > > > [ 46.749540] 201716 32884
> > > > [ 46.749560] J S
> > > > [ 46.751039]
> > > > [ 46.753151] 245632 76800 ==> 76800 in hex is 0x012c00, it is the same
> start
> > > block of the file which checksum is error.
> > > > [ 46.755284]
> > > > nanddisk idle -> 1.
> > > > [ 46.800227] 6v irq-2
> > > >
> > > >
> > > > The j.bin offset 0x2d800
> > > >
> > > > 0002d800 c0 3b 39 98 00 00 00 01 00 00 00 73 00 00 00 88
> > > > |.;9........s....| ==>00039ab0 is in last block
> > > > 0003a000 c0 3b 39 98 00 00 00 02 00 00 00 73 00 00 00 00
> > > > |.;9........s....|
> > > >
> > > >
> > > > Normally, ext4 will first write the file contents, and then write
> > > > the journal and journal commit. Then after some delay, it will
> > > > write the meta data. So The journal blocks contains the meta data
> > > > of the file which the file contents already been written before.
> > > > But from above analysis, the journal sequence 0x73 already
> > > > contain the file
> > > > name(hp0000017aMhWY3i0vMv) and the start block number(76800). So
> > > > from the kernel log, the block
> > > > number(76800) should be available before the journal blocks but
> > > > NOT after it. It seems that there is out of order happen.
> > > >
> > > > Could you please help to check this issue ? or give a explanation
> > > > about it ? Many thanks.
> > > >
> > > > Best regards
> > > >
> > > > Weller HUANG
> > > >
> > > >
> > > > --
> > > > To unsubscribe from this list: send the line "unsubscribe linux-ext4"
> > > > in the body of a message to [email protected] More
> > > > majordomo info at http://vger.kernel.org/majordomo-info.html
> > > --
> > > Jan Kara <[email protected]>
> > > SUSE Labs, CR
>
>
>
> --
> Jan Kara <[email protected]>
> SUSE Labs, CR

2016-01-06 19:17:51

On Thu 07-01-16 11:02:29, HUANG Weller (CM/ESW12-CN) wrote:
> > -----Original Message-----
> > From: Jan Kara [mailto:[email protected]]
> > Sent: Thursday, January 07, 2016 6:24 PM
> > To: HUANG Weller (CM/ESW12-CN) <[email protected]>
> > Cc: Jan Kara <[email protected]>; [email protected]
> > Subject: Re: ext4 out of order when use cfq scheduler
> >
> > On Thu 07-01-16 06:43:00, HUANG Weller (CM/ESW12-CN) wrote:
> > > > -----Original Message-----
> > > > From: Jan Kara [mailto:[email protected]]
> > > > Sent: Wednesday, January 06, 2016 6:06 PM
> > > > To: HUANG Weller (CM/ESW12-CN) <[email protected]>
> > > > Subject: Re: ext4 out of order when use cfq scheduler
> > > >
> > > > On Wed 06-01-16 02:39:15, HUANG Weller (CM/ESW12-CN) wrote:
> > > > > > So you are running in 'ws' mode of your tool, am I right? Just
> > > > > > looking into the sources you've sent me I've noticed that
> > > > > > although you set O_SYNC in openflg when mode == MODE_WS, you do
> > > > > > not use openflg at all. So file won't be synced at all. That
> > > > > > would well explain why you see that not all file contents is
> > > > > > written. So did you just send me a different version of the
> > > > > > source or is your test program
> > > > really buggy?
> > > > > >
> > > > >
> > > > > Yes, it is a bug of the test code. So the test tool create files
> > > > > without O_SYNC flag actually. But , even in this case, is the out
> > > > > of order acceptable ? or is it normal ?
> > > >
> > > > Without fsync(2) or O_SYNC, it is perfectly possible that some files
> > > > are written and others are not since nobody guarantees order of
> > > > writeback of inodes. OTOH you shouldn't ever see uninitialized data
> > > > in the inode (but so far it isn't clear to me whether you really see
> > > > unitialized data or whether we really wrote zeros to those blocks -
> > > > ext4 can sometimes decide to do so). Your traces and disk contents
> > > > show that the problematic inode has extent of length 128 blocks
> > > > starting at block
> > > > 0x12c00 and then extent of lenght 1 block starting at block 0x1268e.
> > > > What is the block size of the filesystem? Because inode size is only 0x40010.
> > > >
> > > > Some suggestions to try:
> > > > 1) Print also length of a write request in addition to the starting
> > > > block so that we can see how much actually got written
> > >
> > > Please see below failure analysis.
> > >
> > > > 2) Initialize the device to 0xff so that we can distinguish
> > > > uninitialized blocks from zeroed-out blocks.
> > >
> > > Yes, i Initialize the device to 0xff this time.
> > >
> > > > 3) Report exactly for which 512-byte blocks checksum matches and for
> > > > which it is wrong.
> > > The wrong contents are old file contents which are created in previous
> > > test round. It is caused by the "wrong" sequence inode data(in
> > > journal) and the file contents. So the file contents are not updated.
> >
> > So this confuses me somewhat. You previously said that you always remove files
> > after each test round and then new ones are created. Is it still the case? So the old
> > file contents you speak about above is just some random contents that happened
> > to be in disk blocks we freshly allocated to the file, am I right?
>
> Yes. You are right.
> The "old file contents" means that the disk blocks which the contents is generated from last test round, and they are allocated to a new file in new test round.
>
>
> >
> > OK, so I was looking into the code and indeed, reality is correct and my mental
> > model was wrong! ;) I thought that inode gets added to the list of inodes for which
> > we need to wait for data IO completion during transaction commit during block
> > allocation. And I was wrong. It used to happen in
> > mpage_da_map_and_submit() until commit f3b59291a69d (ext4: remove calls to
> > ext4_jbd2_file_inode() from delalloc write path) where it got removed. And that was
> > wrong because although we submit data writes before dropping handle for
> > allocating transaction and updating i_size, nobody guarantees that data IO is not
> > delayed in the block layer until transaction commit.
> > Which seems to happen in your case. I'll send a fix. Thanks for your report and
> > persistence!
> >
>
> Thanks a lot for your feedback :-)
> Because I am not familiar with the detail of the ext4 internal code. I will try to understand your explanation which you describe above. And have a look on related funcations.
> Could you send the fix in this mail ?
> And whether the kernel 3.14 also have such issue, right ?

The problem is in all kernels starting with 3.8. Attached is a patch which
should fix the issue. Can you test whether it fixes the problem for you?

Honza
--
Jan Kara <[email protected]>
SUSE Labs, CR

Attachments:

(No filename) (4.71 kB)
0001-ext4-Fix-data-exposure-after-a-crash.patch (3.03 kB)
Download all attachments

2016-01-07 12:19:00

by Jan Kara

[permalink] [raw]

Subject: Re: ext4 out of order when use cfq scheduler

On Thu 07-01-16 12:47:36, Jan Kara wrote:
> On Thu 07-01-16 11:02:29, HUANG Weller (CM/ESW12-CN) wrote:
> > > -----Original Message-----
> > > From: Jan Kara [mailto:[email protected]]
> > > Sent: Thursday, January 07, 2016 6:24 PM
> > > To: HUANG Weller (CM/ESW12-CN) <[email protected]>
> > > Cc: Jan Kara <[email protected]>; [email protected]
> > > Subject: Re: ext4 out of order when use cfq scheduler
> > >
> > > On Thu 07-01-16 06:43:00, HUANG Weller (CM/ESW12-CN) wrote:
> > > > > -----Original Message-----
> > > > > From: Jan Kara [mailto:[email protected]]
> > > > > Sent: Wednesday, January 06, 2016 6:06 PM
> > > > > To: HUANG Weller (CM/ESW12-CN) <[email protected]>
> > > > > Subject: Re: ext4 out of order when use cfq scheduler
> > > > >
> > > > > On Wed 06-01-16 02:39:15, HUANG Weller (CM/ESW12-CN) wrote:
> > > > > > > So you are running in 'ws' mode of your tool, am I right? Just
> > > > > > > looking into the sources you've sent me I've noticed that
> > > > > > > although you set O_SYNC in openflg when mode == MODE_WS, you do
> > > > > > > not use openflg at all. So file won't be synced at all. That
> > > > > > > would well explain why you see that not all file contents is
> > > > > > > written. So did you just send me a different version of the
> > > > > > > source or is your test program
> > > > > really buggy?
> > > > > > >
> > > > > >
> > > > > > Yes, it is a bug of the test code. So the test tool create files
> > > > > > without O_SYNC flag actually. But , even in this case, is the out
> > > > > > of order acceptable ? or is it normal ?
> > > > >
> > > > > Without fsync(2) or O_SYNC, it is perfectly possible that some files
> > > > > are written and others are not since nobody guarantees order of
> > > > > writeback of inodes. OTOH you shouldn't ever see uninitialized data
> > > > > in the inode (but so far it isn't clear to me whether you really see
> > > > > unitialized data or whether we really wrote zeros to those blocks -
> > > > > ext4 can sometimes decide to do so). Your traces and disk contents
> > > > > show that the problematic inode has extent of length 128 blocks
> > > > > starting at block
> > > > > 0x12c00 and then extent of lenght 1 block starting at block 0x1268e.
> > > > > What is the block size of the filesystem? Because inode size is only 0x40010.
> > > > >
> > > > > Some suggestions to try:
> > > > > 1) Print also length of a write request in addition to the starting
> > > > > block so that we can see how much actually got written
> > > >
> > > > Please see below failure analysis.
> > > >
> > > > > 2) Initialize the device to 0xff so that we can distinguish
> > > > > uninitialized blocks from zeroed-out blocks.
> > > >
> > > > Yes, i Initialize the device to 0xff this time.
> > > >
> > > > > 3) Report exactly for which 512-byte blocks checksum matches and for
> > > > > which it is wrong.
> > > > The wrong contents are old file contents which are created in previous
> > > > test round. It is caused by the "wrong" sequence inode data(in
> > > > journal) and the file contents. So the file contents are not updated.
> > >
> > > So this confuses me somewhat. You previously said that you always remove files
> > > after each test round and then new ones are created. Is it still the case? So the old
> > > file contents you speak about above is just some random contents that happened
> > > to be in disk blocks we freshly allocated to the file, am I right?
> >
> > Yes. You are right.
> > The "old file contents" means that the disk blocks which the contents is generated from last test round, and they are allocated to a new file in new test round.
> >
> >
> > >
> > > OK, so I was looking into the code and indeed, reality is correct and my mental
> > > model was wrong! ;) I thought that inode gets added to the list of inodes for which
> > > we need to wait for data IO completion during transaction commit during block
> > > allocation. And I was wrong. It used to happen in
> > > mpage_da_map_and_submit() until commit f3b59291a69d (ext4: remove calls to
> > > ext4_jbd2_file_inode() from delalloc write path) where it got removed. And that was
> > > wrong because although we submit data writes before dropping handle for
> > > allocating transaction and updating i_size, nobody guarantees that data IO is not
> > > delayed in the block layer until transaction commit.
> > > Which seems to happen in your case. I'll send a fix. Thanks for your report and
> > > persistence!
> > >
> >
> > Thanks a lot for your feedback :-)
> > Because I am not familiar with the detail of the ext4 internal code. I will try to understand your explanation which you describe above. And have a look on related funcations.
> > Could you send the fix in this mail ?
> > And whether the kernel 3.14 also have such issue, right ?
>
> The problem is in all kernels starting with 3.8. Attached is a patch which
> should fix the issue. Can you test whether it fixes the problem for you?

Oh, I have realized the patch is on top of current ext4 development tree
and it won't compile for current vanilla kernel because of
EXT4_GET_BLOCKS_ZERO check. Just remove that line when you get compilation
failure.

> + if (map->m_flags & EXT4_MAP_NEW &&
> + !(map->m_flags & EXT4_MAP_UNWRITTEN) &&
> + !(flags & EXT4_GET_BLOCKS_ZERO) &&

Just remove the above line and things should work for older kernels as
well.

> + ext4_should_order_data(inode)) {
> + ret = ext4_jbd2_file_inode(handle, inode);
> + if (ret)
> + return ret;
> + }
> }
> return retval;
> }

Honza

--
Jan Kara <[email protected]>
SUSE Labs, CR

2016-01-08 00:46:47

by HUANG Weller (CM/ESW12-CN)

[permalink] [raw]

Subject: RE: ext4 out of order when use cfq scheduler

> >
> > >
> > > OK, so I was looking into the code and indeed, reality is correct
> > > and my mental model was wrong! ;) I thought that inode gets added to
> > > the list of inodes for which we need to wait for data IO completion
> > > during transaction commit during block allocation. And I was wrong.
> > > It used to happen in
> > > mpage_da_map_and_submit() until commit f3b59291a69d (ext4: remove
> > > calls to
> > > ext4_jbd2_file_inode() from delalloc write path) where it got
> > > removed. And that was wrong because although we submit data writes
> > > before dropping handle for allocating transaction and updating
> > > i_size, nobody guarantees that data IO is not delayed in the block layer until
> transaction commit.
> > > Which seems to happen in your case. I'll send a fix. Thanks for your
> > > report and persistence!
> > >
> >
> > Thanks a lot for your feedback :-)
> > Because I am not familiar with the detail of the ext4 internal code. I will try to
> understand your explanation which you describe above. And have a look on
> related funcations.
> > Could you send the fix in this mail ?
> > And whether the kernel 3.14 also have such issue, right ?
>
> The problem is in all kernels starting with 3.8. Attached is a patch which should fix
> the issue. Can you test whether it fixes the problem for you?
>
> Honza
> --

Yes, of course I will redo the test with the patch. And also give you feedback.
Thanks.
Huang weller

> Jan Kara <[email protected]>
> SUSE Labs, CR

2016-01-08 02:18:47

by HUANG Weller (CM/ESW12-CN)

[permalink] [raw]

Subject: RE: ext4 out of order when use cfq scheduler

> -----Original Message-----
> From: Jan Kara [mailto:[email protected]]
> Sent: Thursday, January 07, 2016 8:19 PM
> To: HUANG Weller (CM/ESW12-CN) <[email protected]>
> Cc: Jan Kara <[email protected]>; [email protected]; Li, Michael
> <[email protected]>
> Subject: Re: ext4 out of order when use cfq scheduler
>
> On Thu 07-01-16 12:47:36, Jan Kara wrote:
> > On Thu 07-01-16 11:02:29, HUANG Weller (CM/ESW12-CN) wrote:
> > > > -----Original Message-----
> > > > From: Jan Kara [mailto:[email protected]]
> > > > Sent: Thursday, January 07, 2016 6:24 PM
> > > > To: HUANG Weller (CM/ESW12-CN) <[email protected]>
> > > > Cc: Jan Kara <[email protected]>; [email protected]
> > > > Subject: Re: ext4 out of order when use cfq scheduler
> > > >
> > > > On Thu 07-01-16 06:43:00, HUANG Weller (CM/ESW12-CN) wrote:
> > > > > > -----Original Message-----
> > > > > > From: Jan Kara [mailto:[email protected]]
> > > > > > Sent: Wednesday, January 06, 2016 6:06 PM
> > > > > > To: HUANG Weller (CM/ESW12-CN) <[email protected]>
> > > > > > Subject: Re: ext4 out of order when use cfq scheduler
> > > > > >
> > > > > > On Wed 06-01-16 02:39:15, HUANG Weller (CM/ESW12-CN) wrote:
> > > > > > > > So you are running in 'ws' mode of your tool, am I right?
> > > > > > > > Just looking into the sources you've sent me I've noticed
> > > > > > > > that although you set O_SYNC in openflg when mode ==
> > > > > > > > MODE_WS, you do not use openflg at all. So file won't be
> > > > > > > > synced at all. That would well explain why you see that
> > > > > > > > not all file contents is written. So did you just send me
> > > > > > > > a different version of the source or is your test program
> > > > > > really buggy?
> > > > > > > >
> > > > > > >
> > > > > > > Yes, it is a bug of the test code. So the test tool create
> > > > > > > files without O_SYNC flag actually. But , even in this
> > > > > > > case, is the out of order acceptable ? or is it normal ?
> > > > > >
> > > > > > Without fsync(2) or O_SYNC, it is perfectly possible that some
> > > > > > files are written and others are not since nobody guarantees
> > > > > > order of writeback of inodes. OTOH you shouldn't ever see
> > > > > > uninitialized data in the inode (but so far it isn't clear to
> > > > > > me whether you really see unitialized data or whether we
> > > > > > really wrote zeros to those blocks -
> > > > > > ext4 can sometimes decide to do so). Your traces and disk
> > > > > > contents show that the problematic inode has extent of length
> > > > > > 128 blocks starting at block
> > > > > > 0x12c00 and then extent of lenght 1 block starting at block 0x1268e.
> > > > > > What is the block size of the filesystem? Because inode size is only
> 0x40010.
> > > > > >
> > > > > > Some suggestions to try:
> > > > > > 1) Print also length of a write request in addition to the
> > > > > > starting block so that we can see how much actually got
> > > > > > written
> > > > >
> > > > > Please see below failure analysis.
> > > > >
> > > > > > 2) Initialize the device to 0xff so that we can distinguish
> > > > > > uninitialized blocks from zeroed-out blocks.
> > > > >
> > > > > Yes, i Initialize the device to 0xff this time.
> > > > >
> > > > > > 3) Report exactly for which 512-byte blocks checksum matches
> > > > > > and for which it is wrong.
> > > > > The wrong contents are old file contents which are created in
> > > > > previous test round. It is caused by the "wrong" sequence inode
> > > > > data(in
> > > > > journal) and the file contents. So the file contents are not updated.
> > > >
> > > > So this confuses me somewhat. You previously said that you always
> > > > remove files after each test round and then new ones are created.
> > > > Is it still the case? So the old file contents you speak about
> > > > above is just some random contents that happened to be in disk blocks we
> freshly allocated to the file, am I right?
> > >
> > > Yes. You are right.
> > > The "old file contents" means that the disk blocks which the contents is
> generated from last test round, and they are allocated to a new file in new test
> round.
> > >
> > >
> > > >
> > > > OK, so I was looking into the code and indeed, reality is correct
> > > > and my mental model was wrong! ;) I thought that inode gets added
> > > > to the list of inodes for which we need to wait for data IO
> > > > completion during transaction commit during block allocation. And
> > > > I was wrong. It used to happen in
> > > > mpage_da_map_and_submit() until commit f3b59291a69d (ext4: remove
> > > > calls to
> > > > ext4_jbd2_file_inode() from delalloc write path) where it got
> > > > removed. And that was wrong because although we submit data writes
> > > > before dropping handle for allocating transaction and updating
> > > > i_size, nobody guarantees that data IO is not delayed in the block layer until
> transaction commit.
> > > > Which seems to happen in your case. I'll send a fix. Thanks for
> > > > your report and persistence!
> > > >
> > >
> > > Thanks a lot for your feedback :-)
> > > Because I am not familiar with the detail of the ext4 internal code. I will try to
> understand your explanation which you describe above. And have a look on
> related funcations.
> > > Could you send the fix in this mail ?
> > > And whether the kernel 3.14 also have such issue, right ?
> >
> > The problem is in all kernels starting with 3.8. Attached is a patch
> > which should fix the issue. Can you test whether it fixes the problem for you?
>
> Oh, I have realized the patch is on top of current ext4 development tree and it
> won't compile for current vanilla kernel because of EXT4_GET_BLOCKS_ZERO
> check. Just remove that line when you get compilation failure.
>
> > + if (map->m_flags & EXT4_MAP_NEW &&
> > + !(map->m_flags & EXT4_MAP_UNWRITTEN) &&
> > + !(flags & EXT4_GET_BLOCKS_ZERO) &&
>
> Just remove the above line and things should work for older kernels as well.
>
> > + ext4_should_order_data(inode)) {
> > + ret = ext4_jbd2_file_inode(handle, inode);
> > + if (ret)
> > + return ret;
> > + }
> > }
> > return retval;
> > }
>

Just confirmed with you because the patch tool didn't found:

"out_sem:
ret = check_block_validity(inode, map);" in my kernel.

after checking the code, I add the modification to the end of function : ext4_map_blocks
below is the diff. please help to double confirm.

diff --git a/fs/ext4/inode.c b/fs/ext4/inode.c
index 10b71e4..d29a1d2 100644
--- a/fs/ext4/inode.c
+++ b/fs/ext4/inode.c
@@ -753,6 +753,10 @@ has_zeroout:
int ret = check_block_validity(inode, map);
if (ret != 0)
return ret;
+ if(ext4_should_order_data(inode)) {
+ ret = ext4_jbd2_file_inode(handle, inode);
+ if (ret)
+ return ret;
}
return retval;
}
@@ -1113,15 +1117,6 @@ static int ext4_write_end(struct file *file,
int i_size_changed = 0;

trace_ext4_write_end(inode, pos, len, copied);
- if (ext4_test_inode_state(inode, EXT4_STATE_ORDERED_MODE)) {
- ret = ext4_jbd2_file_inode(handle, inode);
- if (ret) {
- unlock_page(page);
- page_cache_release(page);
- goto errout;
- }
- }

2016-01-11 09:05:31

On Tue 15-03-16 11:46:34, Jan Kara wrote:
> On Mon 14-03-16 10:36:35, Ted Tso wrote:
> > On Mon, Mar 14, 2016 at 08:39:28AM +0100, Jan Kara wrote:
> > > No, that won't be enough. blkdev_issue_flush() is not guaranteed to do
> > > anything to IOs which have not reported completion before
> > > blkdev_issue_flush() was called. Specifically, CFQ will queue submitted bio
> > > in its internal RB tree, following flush request completely bypasses this
> > > tree and goes directly to the disk where it flushes caches. And only later
> > > CFQ decides to schedule async writeback from the flusher thread which is
> > > queued in the RB tree...
> >
> > Oh, right. I am forgetting about the flushing mahchinery rewrite.
> > Thanks for pointing that out.
> >
> > But what we *could* do is to swap those two calls and then in the case
> > where delalloc is enabled, could maintain a list of inodes where we
> > only need to call filemap_fdatawait(), and not initiate writeback for
> > any dirty pages which had been caused by non-allocating writes.
>
> We actually don't need to swap those two calls - page is already marked as
> under writeback in
>
> mpage_map_and_submit_buffers() -> mpage_submit_page -> ext4_bio_write_page
>
> which gets called while we still hold the transaction handle. I agree
> calling filemap_fdatawait() from JBD2 during commit should be enough to fix
> issues with delalloc writeback. I'm just somewhat afraid that it will be
> more fragile: If we add inode to transaction's list in ext4_map_blocks(),
> we are pretty sure there's no way to allocate block to an inode without
> introducing data exposure issues (which are then very hard to spot). If we
> depend on callers of ext4_map_blocks() to properly add inode to appropriate
> transaction list, we have much more places to check. I'll think whether we
> could make this more robust.

OK, I have something - Huang, can you check whether the attached patches
also fix your data exposure issues please? The first patch is the original
fix, patch two is a cleanup, patches 3 and 4 implement the speedup
suggested by Ted. Patches are only lightly tested so far. I'll run more
comprehensive tests later and in particular I want to check whether the
additional complexity actually brings us some advantage at least for
workloads which redirty pages in addition to writing some new ones using
delayed allocation.

Honza
--
Jan Kara <[email protected]>
SUSE Labs, CR

Attachments:

(No filename) (2.39 kB)
0001-ext4-Fix-data-exposure-after-a-crash.patch (3.22 kB)
0002-ext4-Remove-EXT4_STATE_ORDERED_MODE.patch (1.77 kB)
0003-jbd2-Add-support-for-avoiding-data-writes-during-tra.patch (7.67 kB)
0004-ext4-Do-not-ask-jbd2-to-write-data-for-delalloc-buff.patch (4.89 kB)
Download all attachments

2016-03-15 20:09:30

Hi Kara,

I saw the patch " fix data exposure after a crash " in the kernel 4.6.2 release.
I remember you provided 2 more patches for performance optimization. Could you tell me whether they are necessary ?

Thanks.
Best regards

Weller HUANG

-----Original Message-----
From: Jan Kara [mailto:[email protected]]
Sent: Wednesday, March 16, 2016 4:10 AM
To: Theodore Ts'o <[email protected]>
Cc: Jan Kara <[email protected]>; HUANG Weller (CM/ESW12-CN) <[email protected]>; [email protected]; Li, Michael <[email protected]>
Subject: Re: ext4 out of order when use cfq scheduler

On Tue 15-03-16 15:46:33, Jan Kara wrote:
> On Tue 15-03-16 11:46:34, Jan Kara wrote:
> > On Mon 14-03-16 10:36:35, Ted Tso wrote:
> > > On Mon, Mar 14, 2016 at 08:39:28AM +0100, Jan Kara wrote:
> > > > No, that won't be enough. blkdev_issue_flush() is not guaranteed
> > > > to do anything to IOs which have not reported completion before
> > > > blkdev_issue_flush() was called. Specifically, CFQ will queue
> > > > submitted bio in its internal RB tree, following flush request
> > > > completely bypasses this tree and goes directly to the disk
> > > > where it flushes caches. And only later CFQ decides to schedule
> > > > async writeback from the flusher thread which is queued in the RB tree...
> > >
> > > Oh, right. I am forgetting about the flushing mahchinery rewrite.
> > > Thanks for pointing that out.
> > >
> > > But what we *could* do is to swap those two calls and then in the
> > > case where delalloc is enabled, could maintain a list of inodes
> > > where we only need to call filemap_fdatawait(), and not initiate
> > > writeback for any dirty pages which had been caused by non-allocating writes.
> >
> > We actually don't need to swap those two calls - page is already
> > marked as under writeback in
> >
> > mpage_map_and_submit_buffers() -> mpage_submit_page ->
> > ext4_bio_write_page
> >
> > which gets called while we still hold the transaction handle. I
> > agree calling filemap_fdatawait() from JBD2 during commit should be
> > enough to fix issues with delalloc writeback. I'm just somewhat
> > afraid that it will be more fragile: If we add inode to
> > transaction's list in ext4_map_blocks(), we are pretty sure there's
> > no way to allocate block to an inode without introducing data
> > exposure issues (which are then very hard to spot). If we depend on
> > callers of ext4_map_blocks() to properly add inode to appropriate
> > transaction list, we have much more places to check. I'll think whether we could make this more robust.
>
> OK, I have something - Huang, can you check whether the attached
> patches also fix your data exposure issues please? The first patch is
> the original fix, patch two is a cleanup, patches 3 and 4 implement
> the speedup suggested by Ted. Patches are only lightly tested so far.
> I'll run more comprehensive tests later and in particular I want to
> check whether the additional complexity actually brings us some
> advantage at least for workloads which redirty pages in addition to
> writing some new ones using delayed allocation.

OK, there was a bug in patch 3. Attached is a new version of patches 3 and 4.
Honza

Attachments:

0003-jbd2-Add-support-for-avoiding-data-writes-during-tra.patch (7.47 kB)
0003-jbd2-Add-support-for-avoiding-data-writes-during-tra.patch 0004-ext4-Do-not-ask-jbd2-to-write-data-for-delalloc-buff.patch (4.29 kB)
0004-ext4-Do-not-ask-jbd2-to-write-data-for-delalloc-buff.patch Download all attachments

2016-06-22 13:09:26

by Jan Kara

[permalink] [raw]

Subject: Re: FW: ext4 out of order when use cfq scheduler

Hi,

On Wed 22-06-16 11:55:12, HUANG Weller (CM/ESW12-CN) wrote:
> I saw the patch " fix data exposure after a crash " in the kernel 4.6.2
> release. I remember you provided 2 more patches for performance
> optimization. Could you tell me whether they are necessary ?

They are not necessary. They may just improve performance in some cases...

Honza
--
Jan Kara <[email protected]>
SUSE Labs, CR