xfs
[Top] [All Lists]

Re: posix_fallocate

To: Eric Sandeen <sandeen@xxxxxxxxxxx>
Subject: Re: posix_fallocate
From: Dave Chinner <david@xxxxxxxxxxxxx>
Date: Sat, 8 May 2010 08:16:52 +1000
Cc: Krzysztof Błaszkowski <kb@xxxxxxxxxxxxxxx>, xfs@xxxxxxxxxxx
In-reply-to: <4BE44587.6090603@xxxxxxxxxxx>
References: <201005071022.37863.kb@xxxxxxxxxxxxxxx> <4BE43F34.40309@xxxxxxxxxxx> <4BE44587.6090603@xxxxxxxxxxx>
User-agent: Mutt/1.5.20 (2009-06-14)
On Fri, May 07, 2010 at 11:53:27AM -0500, Eric Sandeen wrote:
> Eric Sandeen wrote:
> > Krzysztof Błaszkowski wrote:
> >> Hello,
> >>
> >> I use this to preallocate large space but found an issue. Posix_fallocate 
> >> works right with sizes like 100G, 1T and even 10T on some boxes (on some 
> >> other can fail after e.g. 7T threshold) but if i tried e.g. 16T the user 
> >> space process would be "R"unning forever and it is not interruptible. 
> >> Furthermore some other not related processes like sshd, bash enter D 
> >> state. 
> >> There is nothing in kernel log.
> 
> Oh, one thing you should know is that depending on your version of glibc,
> posix_fallocate may be writing 0s and not using preallocation calls.
> 
> Do you know which yours is using?  strace should tell you on a small
> file test.
> 
> Anyway, I am seeing things get stuck around 8T it seems...
> 
> # touch /mnt/test/bigfile
> # xfs_io -c "resvsp 0 16t" /mnt/test/bigfile 
> 
> ... wait ... in other window ...
> 
> # du -hc /mnt/test/bigfile 
> 8.0G  /mnt/test/bigfile
> 8.0G  total
> 
> # echo t > /proc/sysrq-trigger 
> # dmesg | grep -A20 xfs_io
> xfs_io        R  running task     3576 29444  29362 0x00000006
>  ffff8809cfbb4920 ffffffff81478d9f ffffffffa032d3c5 0000000000000246
>  ffff8809cfbb4920 ffffffff814788bc 0000000000000000 ffffffff81ba3510
>  ffff8809d3429a68 ffffffffa032b60f ffff8809d3429aa8 000000000000001e
> Call Trace:
>  [<ffffffff81478d9f>] ? __mutex_lock_common+0x36d/0x392
>  [<ffffffffa032d3c5>] ? xfs_icsb_modify_counters+0x17f/0x1ac [xfs]
>  [<ffffffffa032b60f>] ? xfs_icsb_unlock_all_counters+0x4d/0x60 [xfs]
>  [<ffffffffa032b8bf>] ? xfs_icsb_disable_counter+0x8c/0x95 [xfs]
>  [<ffffffff81478e88>] ? mutex_lock_nested+0x3e/0x43
>  [<ffffffffa032d3d3>] ? xfs_icsb_modify_counters+0x18d/0x1ac [xfs]
>  [<ffffffffa032d536>] ? xfs_mod_incore_sb+0x29/0x6e [xfs]
>  [<ffffffffa033052c>] ? _xfs_trans_alloc+0x27/0x61 [xfs]
>  [<ffffffffa03303d3>] ? xfs_trans_reserve+0x6c/0x19e [xfs]
>  [<ffffffff8106fb45>] ? up_write+0x2b/0x32
>  [<ffffffffa0335e55>] ? xfs_alloc_file_space+0x163/0x306 [xfs]
>  [<ffffffff8107120a>] ? sched_clock_cpu+0xc3/0xce
>  [<ffffffffa0336122>] ? xfs_change_file_space+0x12a/0x2b8 [xfs]
>  [<ffffffff8106f9bf>] ? down_write_nested+0x80/0x8b
>  [<ffffffffa031b8ce>] ? xfs_ilock+0x30/0xb4 [xfs]
>  [<ffffffffa033e0e4>] ? xfs_vn_fallocate+0x80/0xf4 [xfs]
> --
> R         xfs_io 29444  86014624.786617       162   120  86014624.786617    
> 137655.161327       408.979977 /
> 
> # uname -r
> 2.6.34-0.4.rc0.git2.fc14.x86_64
> 
> I'll look into  it.

On my current delayed-logging branch on a 30GB filesystem:

# xfs_io -f -c "resvsp 0 16t" /mnt/scratch/bigfile 

And in dmesg:

[60173.119760] Assertion failed: tp->t_blk_res_used <= tp->t_blk_res, file: 
fs/xfs/xfs_trans.c, line: 475
[60173.121263] ------------[ cut here ]------------
[60173.121771] kernel BUG at fs/xfs/support/debug.c:109!
[60173.121771] invalid opcode: 0000 [#1] SMP
[60173.121771] last sysfs file: 
/sys/devices/virtio-pci/virtio2/block/vdb/removable
[60173.121771] CPU 7
[60173.121771] Modules linked in: [last unloaded: scsi_wait_scan]
[60173.121771]
[60173.121771] Pid: 3596, comm: xfs_io Not tainted 2.6.34-rc1-dgc #138 /Bochs
[60173.121771] RIP: 0010:[<ffffffff8135db5f>]  [<ffffffff8135db5f>] 
assfail+0x1f/0x30
[60173.121771] RSP: 0018:ffff880112043808  EFLAGS: 00010292
[60173.121771] RAX: 000000000000006d RBX: ffff880105038da0 RCX: 0000000000000000
[60173.121771] RDX: ffff880003600000 RSI: 0000000000000000 RDI: 0000000000000246
[60173.121771] RBP: ffff880112043808 R08: 0000000000000002 R09: 0000000000000000
[60173.121771] R10: ffffffff81a70bb8 R11: 0000000000000000 R12: ffffffffffe20082
[60173.121771] R13: ffff88011cea5000 R14: 0000000000000001 R15: 0000000000000000
[60173.121771] FS:  00007f0311cda6f0(0000) GS:ffff880003600000(0000) 
knlGS:0000000000000000
[60173.121771] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[60173.121771] CR2: 00007f031164d750 CR3: 000000011bc59000 CR4: 00000000000006e0
[60173.121771] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[60173.121771] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[60173.121771] Process xfs_io (pid: 3596, threadinfo ffff880112042000, task 
ffff88011629a740)
[60173.121771] Stack:
[60173.121771]  ffff880112043838 ffffffff81342415 00000000001dff7e 
ffff880112043928
[60173.121771] <0> 00000000001dff7e 0000000000000004 ffff880112043858 
ffffffff812e82ce
[60173.121771] <0> ffff880112043928 ffff88011cea5000 ffff8801120438c8 
ffffffff812e9008
[60173.121771] Call Trace:
[60173.121771]  [<ffffffff81342415>] xfs_trans_mod_sb+0x2f5/0x330
[60173.121771]  [<ffffffff812e82ce>] xfs_alloc_ag_vextent+0x18e/0x2b0
[60173.121771]  [<ffffffff812e9008>] xfs_alloc_vextent+0x598/0x870
[60173.121771]  [<ffffffff812f9c0f>] xfs_bmap_btalloc+0x29f/0x7b0
[60173.121771]  [<ffffffff812f4af1>] ? xfs_bmap_search_multi_extents+0x71/0x110
[60173.121771]  [<ffffffff812fa141>] xfs_bmap_alloc+0x21/0x40
[60173.121771]  [<ffffffff812fd43c>] xfs_bmapi+0xf2c/0x1a90
[60173.121771]  [<ffffffff81333f55>] ? xlog_grant_log_space+0x35/0x640
[60173.121771]  [<ffffffff8132293b>] ? xfs_ilock+0x10b/0x190
[60173.121771]  [<ffffffff81349660>] xfs_alloc_file_space+0x190/0x440
[60173.121771]  [<ffffffff810b41cd>] ? trace_hardirqs_on+0xd/0x10
[60173.121771]  [<ffffffff8134c7a4>] xfs_change_file_space+0x2d4/0x380
[60173.121771]  [<ffffffff810a291e>] ? down_write_nested+0x9e/0xb0
[60173.121771]  [<ffffffff81322918>] ? xfs_ilock+0xe8/0x190
[60173.121771]  [<ffffffff81358a87>] xfs_vn_fallocate+0x87/0x110
[60173.121771]  [<ffffffff8112661c>] ? __do_fault+0x12c/0x450
[60173.121771]  [<ffffffff81124ebc>] ? might_fault+0x5c/0xb0
[60173.121771]  [<ffffffff81126889>] ? __do_fault+0x399/0x450
[60173.121771]  [<ffffffff8114cfb3>] do_fallocate+0x103/0x110
[60173.121771]  [<ffffffff8115dd8c>] ioctl_preallocate+0x8c/0xb0
[60173.121771]  [<ffffffff8115e1c5>] do_vfs_ioctl+0x415/0x5b0
[60173.121771]  [<ffffffff810a2a43>] ? up_read+0x23/0x40
[60173.121771]  [<ffffffff8115e3e1>] sys_ioctl+0x81/0xa0
[60173.121771]  [<ffffffff81036032>] system_call_fastpath+0x16/0x1b

So there's been a transaction overrun, which tends to imply we're
allocating too much in a single transaction. I'd say there's an
overflow happening somewhere in this path.

Cheers,

Dave.
-- 
Dave Chinner
david@xxxxxxxxxxxxx

<Prev in Thread] Current Thread [Next in Thread>