On 1 October 2013 19:34, Josef Bacik <jba...@fusionio.com> wrote: > On Mon, Sep 30, 2013 at 11:07:20PM +0200, Aastha Mehta wrote: >> On 30 September 2013 22:47, Josef Bacik <jba...@fusionio.com> wrote: >> > On Mon, Sep 30, 2013 at 10:30:59PM +0200, Aastha Mehta wrote: >> >> On 30 September 2013 22:11, Josef Bacik <jba...@fusionio.com> wrote: >> >> > On Mon, Sep 30, 2013 at 09:32:54PM +0200, Aastha Mehta wrote: >> >> >> On 29 September 2013 15:12, Josef Bacik <jba...@fusionio.com> wrote: >> >> >> > On Sun, Sep 29, 2013 at 11:22:36AM +0200, Aastha Mehta wrote: >> >> >> >> Thank you very much for the reply. That clarifies a lot of things. >> >> >> >> >> >> >> >> I was trying a small test case that opens a file, writes a block of >> >> >> >> data, calls fsync and then closes the file. If I understand >> >> >> >> correctly, >> >> >> >> fsync would return only after all in-memory buffers have been >> >> >> >> committed to disk. I have added few print statements in the >> >> >> >> __extent_writepage function, and I notice that the function gets >> >> >> >> called a bit later after fsync returns. It seems that I am not >> >> >> >> guaranteed to see the data going to disk by the time fsync returns. >> >> >> >> >> >> >> >> Am I doing something wrong, or am I looking at the wrong place for >> >> >> >> disk write? This happens both with tree logging enabled as well as >> >> >> >> with notreelog. >> >> >> >> >> >> >> > >> >> >> > So 3.1 was a long time ago and to be sure it had issues I don't >> >> >> > think it was >> >> >> > _that_ broken. You are probably better off instrumenting a recent >> >> >> > kernel, 3.11 >> >> >> > or just build btrfs-next from git. But if I were to make a guess >> >> >> > I'd say that >> >> >> > __extent_writepage was how both data and metadata was written out at >> >> >> > the time (I >> >> >> > don't think I changed it until 3.2 or something later) so what you >> >> >> > are likely >> >> >> > seeing is the normal transaction commit after the fsync. In the >> >> >> > case of >> >> >> > notreelog we are likely starting another transaction and you are >> >> >> > seeing that >> >> >> > commit (at the time the transaction kthread would start a >> >> >> > transaction even if >> >> >> > none had been started yet.) Thanks, >> >> >> > >> >> >> > Josef >> >> >> >> >> >> Is there any special handling for very small file write, less than 4K? >> >> >> As >> >> >> I understand there is an optimization to inline the first extent in a >> >> >> file if >> >> >> it is smaller than 4K, does it affect the writeback on fsync as well? >> >> >> I did >> >> >> set the max_inline mount option to 0, but even then it seems there is >> >> >> some difference in fsync behaviour for writing first extent of less >> >> >> than 4K >> >> >> size and writing 4K or more. >> >> >> >> >> > >> >> > Yeah if the file is an inline extent then it will be copied into the log >> >> > directly and the log will be written out, no going through the data >> >> > write path >> >> > at all. Max inline == 0 should make it so we don't inline, so if it >> >> > isn't >> >> > honoring that then that may be a bug. Thanks, >> >> > >> >> > Josef >> >> >> >> I tried it on 3.12-rc2 release, and it seems there is a bug then. >> >> Please find attached logs to confirm. >> >> Also, probably on the older release. >> >> >> > >> > Oooh ok I understand, you have your printk's in the wrong place ;). >> > do_writepages doesn't necessarily mean you are writing something. If you >> > want >> > to see if stuff got written to the disk I'd put a printk at >> > run_delalloc_range >> > and have it spit out the range it is writing out since thats what we think >> > is >> > actually dirty. Thanks, >> > >> > Josef >> >> No, but I also placed dump_stack() in the beginning of >> __extent_writepage. run_delalloc_range is being called only from >> __extent_writepage, if it were to be called, the dump_stack() at the >> top of __extent_writepage would have printed as well, no? >> > > Ok I've done the same thing and I'm not seeing what you are seeing. Are you > using any mount options other than notreelog and max_inline=0? Could you > adjust > your printk to print out the root objectid for the inode as well? It could be > possible that this is the writeout for the space cache or inode cache. > Thanks, > > Josef
I actually printed the stack only when the root objectid is 5. I have attached another log for writing the first 500 bytes in a file. I also print the root objectid for the inode in run_delalloc and __extent_writepage. Thanks -- Aastha Mehta MPI-SWS, Germany E-mail: aasth...@mpi-sws.org
write success, size: 500 fsync:: Success file size: 500 fclose:: Success [ 829.847483] btrfs: device fsid 4d2767ea-85cc-443c-88bd-2d8c693f7c7c devid 1 transid 2201 /dev/sdd [ 829.848199] btrfs: max_inline at 0 [ 829.848201] btrfs: disabling tree log [ 829.848202] btrfs: disk space caching is enabled [ 835.266483] [do_writepages] inum: 258, nr_to_write: 9223372036854775807, writepages fn: ffffffff8129ce40 [ 835.266492] CPU: 0 PID: 10021 Comm: bb Not tainted 3.12.0-rc2-latest+ #7 [ 835.266494] Hardware name: innotek GmbH VirtualBox, BIOS VirtualBox 12/01/2006 [ 835.266496] ffff88003cdc5e60 ffff88003cdc5e28 ffffffff817a8acf ffff88003fc0eb48 [ 835.266511] ffff88001f478b28 ffff88003cdc5e48 ffffffff81105c1f ffff88001f4789e0 [ 835.266515] ffff880037557400 ffff88003cdc5e88 ffffffff810fb689 ffff88003fc12c00 [ 835.266518] Call Trace: [ 835.266528] [<ffffffff817a8acf>] dump_stack+0x46/0x58 [ 835.266534] [<ffffffff81105c1f>] do_writepages+0x4f/0x90 [ 835.266538] [<ffffffff810fb689>] __filemap_fdatawrite_range+0x49/0x50 [ 835.266542] [<ffffffff810fc41e>] filemap_fdatawrite_range+0xe/0x10 [ 835.266546] [<ffffffff812ab01c>] btrfs_sync_file+0xac/0x380 [ 835.266553] [<ffffffff817aee32>] ? __schedule+0x692/0x730 [ 835.266559] [<ffffffff811752d8>] do_fsync+0x58/0x90 [ 835.266563] [<ffffffff81148a6d>] ? SyS_write+0x4d/0xa0 [ 835.266568] [<ffffffff8117565b>] SyS_fsync+0xb/0x10 [ 835.266572] [<ffffffff817b8422>] system_call_fastpath+0x16/0x1b [ 835.266579] [btrfs_sync_file] inum: (258, 5), called write_range, start: 0, end: 9223372036854775807, ret: 0 [ 835.266581] [btrfs_sync_file] inum: (258, 5), calling btrfs_wait_ordered_range, start: 0, end: 9223372036854775807 [ 835.266584] [do_writepages] inum: 258, nr_to_write: 9223372036854775807, writepages fn: ffffffff8129ce40 [ 835.266587] CPU: 0 PID: 10021 Comm: bb Not tainted 3.12.0-rc2-latest+ #7 [ 835.266589] Hardware name: innotek GmbH VirtualBox, BIOS VirtualBox 12/01/2006 [ 835.266590] ffff88003cdc5e20 ffff88003cdc5de8 ffffffff817a8acf 0000000000000007 [ 835.266593] ffff88001f478b28 ffff88003cdc5e08 ffffffff81105c1f 0000000000000000 [ 835.266596] ffff88001f4789e0 ffff88003cdc5e48 ffffffff810fb689 ffff880037557400 [ 835.266599] Call Trace: [ 835.266603] [<ffffffff817a8acf>] dump_stack+0x46/0x58 [ 835.266607] [<ffffffff81105c1f>] do_writepages+0x4f/0x90 [ 835.266610] [<ffffffff810fb689>] __filemap_fdatawrite_range+0x49/0x50 [ 835.266613] [<ffffffff810fc41e>] filemap_fdatawrite_range+0xe/0x10 [ 835.266618] [<ffffffff812b2ad8>] btrfs_wait_ordered_range+0x58/0x100 [ 835.266621] [<ffffffff812ab118>] btrfs_sync_file+0x1a8/0x380 [ 835.266625] [<ffffffff817aee32>] ? __schedule+0x692/0x730 [ 835.266629] [<ffffffff811752d8>] do_fsync+0x58/0x90 [ 835.266632] [<ffffffff81148a6d>] ? SyS_write+0x4d/0xa0 [ 835.266636] [<ffffffff8117565b>] SyS_fsync+0xb/0x10 [ 835.266640] [<ffffffff817b8422>] system_call_fastpath+0x16/0x1b [ 835.266647] [btrfs_sync_file] inum: (258, 5), return from log_dentry, start: 0, end: 9223372036854775807, ret: 1 [ 865.312082] [do_writepages] inum: 258, nr_to_write: 3072, writepages fn: ffffffff8129ce40 [ 865.312090] CPU: 0 PID: 711 Comm: kworker/u2:5 Not tainted 3.12.0-rc2-latest+ #7 [ 865.312093] Hardware name: innotek GmbH VirtualBox, BIOS VirtualBox 12/01/2006 [ 865.312100] Workqueue: writeback bdi_writeback_workfn (flush-btrfs-2) [ 865.312104] ffff88003c793b60 ffff88003c793a88 ffffffff817a8acf ffff88003fc0eb48 [ 865.312107] ffff88001f478b28 ffff88003c793aa8 ffffffff81105c1f ffff88001f4789e0 [ 865.312110] ffff88003c793b60 ffff88003c793b08 ffffffff8116ea30 ffff880039caf398 [ 865.312113] Call Trace: [ 865.312121] [<ffffffff817a8acf>] dump_stack+0x46/0x58 [ 865.312126] [<ffffffff81105c1f>] do_writepages+0x4f/0x90 [ 865.312131] [<ffffffff8116ea30>] __writeback_single_inode+0xa0/0x260 [ 865.312135] [<ffffffff8116f741>] writeback_sb_inodes+0x2b1/0x430 [ 865.312139] [<ffffffff8116f93e>] __writeback_inodes_wb+0x7e/0xc0 [ 865.312143] [<ffffffff8117000b>] wb_writeback+0x18b/0x2e0 [ 865.312147] [<ffffffff811701e3>] wb_check_old_data_flush+0x83/0xb0 [ 865.312151] [<ffffffff81171aac>] bdi_writeback_workfn+0x1dc/0x440 [ 865.312157] [<ffffffff8105f19c>] process_one_work+0x2bc/0x430 [ 865.312161] [<ffffffff810600c5>] worker_thread+0x215/0x320 [ 865.312165] [<ffffffff8105feb0>] ? manage_workers.isra.18+0x2b0/0x2b0 [ 865.312169] [<ffffffff810666f6>] kthread+0xb6/0xc0 [ 865.312172] [<ffffffff81066640>] ? flush_kthread_worker+0xa0/0xa0 [ 865.312178] [<ffffffff817b837c>] ret_from_fork+0x7c/0xb0 [ 865.312181] [<ffffffff81066640>] ? flush_kthread_worker+0xa0/0xa0 [ 865.312188] [__extent_writepage] inum: (258, 5) [ 865.312191] CPU: 0 PID: 711 Comm: kworker/u2:5 Not tainted 3.12.0-rc2-latest+ #7 [ 865.312192] Hardware name: innotek GmbH VirtualBox, BIOS VirtualBox 12/01/2006 [ 865.312196] Workqueue: writeback bdi_writeback_workfn (flush-btrfs-2) [ 865.312198] ffffea0000b93700 ffff88003c793808 ffffffff817a8acf 0000000000000007 [ 865.312201] ffff88001f478850 ffff88003c793918 ffffffff812b7cf2 ffff88003c793878 [ 865.312204] ffffffff817a36ae ffff88003c793888 ffffffff00000020 ffff88003c793888 [ 865.312207] Call Trace: [ 865.312211] [<ffffffff817a8acf>] dump_stack+0x46/0x58 [ 865.312216] [<ffffffff812b7cf2>] __extent_writepage+0x82/0x770 [ 865.312219] [<ffffffff817a36ae>] ? printk+0x5c/0x5e [ 865.312222] [<ffffffff81066640>] ? flush_kthread_worker+0xa0/0xa0 [ 865.312226] [<ffffffff810fac71>] ? find_get_pages_tag+0x121/0x160 [ 865.312231] [<ffffffff812b85b2>] extent_write_cache_pages.isra.24.constprop.31+0x1d2/0x380 [ 865.312235] [<ffffffff81005877>] ? show_trace_log_lvl+0x57/0x70 [ 865.312239] [<ffffffff812b8a39>] extent_writepages+0x49/0x60 [ 865.312244] [<ffffffff8129f160>] ? btrfs_submit_direct+0x6c0/0x6c0 [ 865.312247] [<ffffffff8129ce63>] btrfs_writepages+0x23/0x30 [ 865.312251] [<ffffffff81105c3e>] do_writepages+0x6e/0x90 [ 865.312255] [<ffffffff8116ea30>] __writeback_single_inode+0xa0/0x260 [ 865.312259] [<ffffffff8116f741>] writeback_sb_inodes+0x2b1/0x430 [ 865.312263] [<ffffffff8116f93e>] __writeback_inodes_wb+0x7e/0xc0 [ 865.312267] [<ffffffff8117000b>] wb_writeback+0x18b/0x2e0 [ 865.312271] [<ffffffff811701e3>] wb_check_old_data_flush+0x83/0xb0 [ 865.312275] [<ffffffff81171aac>] bdi_writeback_workfn+0x1dc/0x440 [ 865.312279] [<ffffffff8105f19c>] process_one_work+0x2bc/0x430 [ 865.312283] [<ffffffff810600c5>] worker_thread+0x215/0x320 [ 865.312287] [<ffffffff8105feb0>] ? manage_workers.isra.18+0x2b0/0x2b0 [ 865.312290] [<ffffffff810666f6>] kthread+0xb6/0xc0 [ 865.312293] [<ffffffff81066640>] ? flush_kthread_worker+0xa0/0xa0 [ 865.312297] [<ffffffff817b837c>] ret_from_fork+0x7c/0xb0 [ 865.312301] [<ffffffff81066640>] ? flush_kthread_worker+0xa0/0xa0 [ 865.312309] [run_delalloc_range] inum: (258, 5), alloc start: 0, end: 4095
