Re: Data lost in Android app for not write new checkpoint

[He YunLei <heyunlei@huawei.com>]

On 2015/8/6 18:17, Chao Yu wrote:
>> -----Original Message-----
>> From: He YunLei [mailto:heyunlei@huawei.com]
>> Sent: Tuesday, August 04, 2015 9:16 PM
>> To: Chao Yu
>> Cc: 'Bintian'; 'Jaegeuk Kim'; cm224.lee@samsung.com; linux-f2fs-devel@lists.sourceforge.net
>> Subject: Re: [f2fs-dev] Data lost in Android app for not write new checkpoint
>>
>> On 2015/7/31 18:49, Chao Yu wrote:
>>> Hi Bintian,
>>>
>>>> -----Original Message-----
>>>> From: He YunLei [mailto:heyunlei@huawei.com]
>>>> Sent: Friday, July 31, 2015 10:29 AM
>>>> To: linux-f2fs-devel@lists.sourceforge.net; Jaegeuk Kim
>>>> Cc: Chao Yu; cm224.lee@samsung.com; Bintian
>>>> Subject: [f2fs-dev] Data lost in Android app for not write new checkpoint
>>>>
>>>> Hi all,
>>>> 	Recently I did some test with f2fs on my Android phone, and found a problem
>>>> which I didn't know how to tackle it.
>>>> 	I use my Android phone with /data partition formatted  by mkfs.f2fs. When the
>>>> phone just started, I check the f2fs status by reading the file /sys/kernel/debug/f2fs/status
>>>> in debugfs.
>>>>
>>>> CP calls: 10
>>>> GC calls: 19 (BG: 19)
>>>>      - data segments : 19 (19)
>>>>      - node segments : 0 (0)
>>>>
>>>> 	We can see /data partition has done 10 times write_checkpoint since f2fs is mounted
>>>> on the phone, it also has triggered 19 times background GC.
>>>>
>>>> ******
>>>>
>>>> Here I took some photos consecutively, and check the file /sys/kernel/debug/f2fs/status again
>>>>
>>>> ******
>>>>
>>>> CP calls: 10
>>>> GC calls: 20 (BG: 20)
>>>>      - data segments : 20 (20)
>>>>      - node segments : 0 (0)
>>>>
>>>> 	there is no change in CP calls number and background GC doesn't write new checkpoint.
>>>> if then a sudden power failure or system crash occur, the photos will be lost when the phone
>>>> restart, and a sync before crash will avoid the data lost.
>>>> 	I think this problem is bad for user experience of using Android phone with f2fs.
>>>> How do we deal with such situation? I wish you and other developers in this list could help
>>>> me in a correct way.
>>>
>>> IMO, it's better to figure out whether this is a bug of f2fs first or not.
>>>
>>> You can enable some traces in f2fs to see whether fsync is called or not.
>>>
>>> enable trace by:
>>> echo 1 > /sys/kernel/debug/tracing/events/f2fs/f2fs_sync_file_enter/enable
>>> echo 1 > /sys/kernel/debug/tracing/events/f2fs/f2fs_sync_file_exit/enable
>>> print trace by:
>>> cat /sys/kernel/debug/tracing/trace
>>>
>>> If fsync is not be called, I think in ext4 there must be the same problem,
>>> but I guess fortunately journal commit thread save its data since it commit
>>> transaction per 5 second by default. You can try to configure (commit=nrsec)
>>> it with larger value for verification the issue with ext4 filesystem.
>>>
>>
>> I enable the event xxx_sync_file_enter both in f2fs and ext4, and find neither of
>> them was triggered by photo files.
>>
>> Then I try f2fs_writepages and ext4_da_write_pages:
>>
>>      ino     file_name
>>
>>      65573   IMG_20150804_031619.jpg
>>      65575   IMG_20150804_031619_1.jpg
>>      65576   IMG_20150804_031620.jpg
>>      65577   IMG_20150804_031620_1.jpg
>>
>>    ext4_da_write_pages: dev 259,0 ino 65573 b_blocknr 0 b_size 0 b_state 0x0000 first_page 0
>> io_done 0 pages_written 0 sync_mode 0
>>    ext4_da_write_pages: dev 259,0 ino 65575 b_blocknr 0 b_size 2408448 b_state 0x0221 first_page
>> 0 io_done 1 pages_written 588 sync_mode 0
>>    ext4_da_write_pages: dev 259,0 ino 65575 b_blocknr 0 b_size 0 b_state 0x0000 first_page 0
>> io_done 0 pages_written 0 sync_mode 0
>>    ext4_da_write_pages: dev 259,0 ino 65576 b_blocknr 0 b_size 2428928 b_state 0x0221 first_page
>> 0 io_done 1 pages_written 593 sync_mode 0
>>    ext4_da_write_pages: dev 259,0 ino 65576 b_blocknr 0 b_size 0 b_state 0x0000 first_page 0
>> io_done 0 pages_written 0 sync_mode 0
>>    ext4_da_write_pages: dev 259,0 ino 65577 b_blocknr 0 b_size 2383872 b_state 0x0221 first_page
>> 0 io_done 1 pages_written 582 sync_mode 0
>>    ext4_da_write_pages: dev 259,0 ino 65577 b_blocknr 0 b_size 0 b_state 0x0000 first_page 0
>> io_done 0 pages_written 0 sync_mode 0
>>
>> f2fs_writepages doesn't appear in the test of f2fs
>
> Weird, was IO triggered from DIO/reclaim path? As Jaegeuk said, it's better
> to check the IOs in block layer.
>
   I am sorry that I leave out f2fs_writepages message for the reason of huge trace log. I repeat the test
several times and now make sure f2fs_writepages is triggered but very little compare to ext4.

   Another problem is that roll_forward recovery  can just resume writeback files users fsynced , not including
files whose pages written back by bdi flusher ?

>>
>> I also try modify commit=300(default 5), but it doesn't work. Maybe somewhere else in ext4
>> launch the ext4_da_write_pages operation.
>
> Maybe it's triggered by bdi flusher, can you try to configure parameters
> under /proc/sys/vm/ e.g. dirty_writeback_centisecs/dirty_background_ratio
> for delaying ->writepages in ext4?
>
>>
>> At the end, I try to mount f2fs with disable_roll_forward, when system reboot, the f2fs is
>> inconsistent,
>> there are several failed check items in fsck.
>
> Can you share the log?

The log is below:

[FSCK] Unreachable nat entries                        [Fail] [0x64b]
[FSCK] SIT valid block bitmap checking                [Fail]
[FSCK] Hard link checking for regular file            [Ok..] [0x0]
[FSCK] valid_block_count matching with CP             [Ok..] [0x579b6]
[FSCK] valid_node_count matcing with CP (de lookup)   [Ok..] [0x7b0]
[FSCK] valid_node_count matcing with CP (nat lookup)  [Fail] [0xdfb]
[FSCK] valid_inode_count matched with CP              [Ok..] [0x664]
[FSCK] free segment_count matched with CP             [Ok..] [0x238]
[FSCK] next block offset is free                      [Ok..]
[FSCK] other corrupted bugs                           [Fail]

I repeat the test about 5 times, the fsck failed just one time.
When I use disable_roll_forward mount option, I find some photos don't lose occasionally.
There are also some incomplete photo files exit on my photo.  Does roll_forward recovery
think pages written back by bdi flusher is unreliable, and clean them ?

Thanks,
He

>
> Thanks,
>
>>
>> Thanks,
>> He
>>
>>> As a quick thought, maybe we can add one commit data thread, periodically
>>> writebacking user data written by user previously, then do checkpoint for
>>> persistence.
>>>
>>> So by this way, at most, we just lose our data for last configured time of
>>> commit period.
>>>
>>> Thanks,
>>>
>>>>
>>>> Thanks,
>>>> He
>>>
>>>
>>>
>>> .
>>>
>
>
> .
>


------------------------------------------------------------------------------