Skip to contentSkip to conversation

NFS commit: sync or async?

DISCUSSION Wu Fengguang 2 participants 3 messages Jul 22, 2010 – Jul 23, 2010 1 message not in the archive

Subsystems (2)
lore
Share & tools
lore
#0 lore raw

Hi Trond,

May I ask you an NFS question? I got a bit puzzled by this call trace. It happens after stopping the nfsd at server side when the client side is doing cp over NFSv3:

[49388.040091] cp            D 0000000000000082  2968  2782  28204 0x00000000
[49388.040097]  ffff8800b8587778 0000000000000002 ffff8800b85877f8 00000000001d4e40
[49388.040103]  ffff8800b8587fd8 00000000001d4e40 ffff8800b8587fd8 ffff8800b8ec4700
[49388.040110]  00000000001d4e40 ffff8800b8587fd8 00000000001d4e40 00000000001d4e40
[49388.040116] Call Trace:
[49388.040121]  [<ffffffff810de503>] ? prepare_to_wait+0x73/0xc0
[49388.040127]  [<ffffffff81b32750>] ? rpc_wait_bit_killable+0x0/0x60
[49388.040132]  [<ffffffff81b3277f>] rpc_wait_bit_killable+0x2f/0x60
[49388.040136]  [<ffffffff81babded>] __wait_on_bit+0x8d/0xe0
[49388.040140]  [<ffffffff81b32750>] ? rpc_wait_bit_killable+0x0/0x60
[49388.040144]  [<ffffffff81babec6>] out_of_line_wait_on_bit+0x86/0xa0
[49388.040149]  [<ffffffff810de170>] ? wake_bit_function+0x0/0x70
[49388.040154]  [<ffffffff81b333bf>] __rpc_execute+0x16f/0x3f0
[49388.040158]  [<ffffffff81b3367b>] rpc_execute+0x3b/0x50
[49388.040162]  [<ffffffff81b28d31>] rpc_run_task+0x51/0xc0
[49388.040167]  [<ffffffff81366ad6>] nfs_commit_list+0x1f6/0x3e0
[49388.040172]  [<ffffffff81366de9>] nfs_commit_inode+0x129/0x170
[49388.040176]  [<ffffffff813677fa>] nfs_write_inode+0x7a/0xf0
[49388.040180]  [<ffffffff81239a8b>] writeback_single_inode+0x28b/0x3f0
[49388.040186]  [<ffffffff8123ac08>] writeback_inodes_wb+0x318/0x650
[49388.040191]  [<ffffffff8123b1d2>] writeback_inodes_wbc+0x22/0x30
[49388.040196]  [<ffffffff811a5a00>] balance_dirty_pages_ratelimited_nr+0x400/0x5d0
[49388.040202]  [<ffffffff81196306>] ? iov_iter_copy_from_user_atomic+0xa6/0x1c0
[49388.040207]  [<ffffffff81196898>] generic_file_buffered_write+0x258/0x370
[49388.040213]  [<ffffffff81199b7a>] __generic_file_aio_write+0x2ea/0x5f0
[49388.040218]  [<ffffffff81bad374>] ? mutex_lock_nested+0x394/0x530
[49388.040223]  [<ffffffff81199edf>] ? generic_file_aio_write+0x5f/0x100
[49388.040229]  [<ffffffff81199ef9>] generic_file_aio_write+0x79/0x100
[49388.040235]  [<ffffffff81353f00>] nfs_file_write+0xe0/0x2a0
[49388.040240]  [<ffffffff8120a138>] do_sync_write+0xe8/0x140
[49388.040246]  [<ffffffff811bd7b6>] ? might_fault+0xd6/0xf0
[49388.040251]  [<ffffffff8120b156>] vfs_write+0xb6/0x220
[49388.040255]  [<ffffffff8120b406>] sys_write+0x66/0xb0
[49388.040260]  [<ffffffff8104ab72>] system_call_fastpath+0x16/0x1b
Quoted 1 line

From simple code review I cannot explain why out_of_line_wait_on_bit()

is called inside __rpc_execute() for a commit request.

nfs_commit_rpcsetup() sets RPC_TASK_ASYNC for task_setup_data.flags, which is transferred to task->tk_flags in rpc_init_task(). __rpc_execute() should then return on task_is_async=1 and skip the out_of_line_wait_on_bit() call. However the trace shows that out_of_line_wait_on_bit() is called. I'm a bit puzzled. I must have missed something. Is this the expected behavior?

Thanks,
Fengguang

#1 lore raw
Quoted 42 lines · Wu Fengguang

Hi Trond,

May I ask you an NFS question? I got a bit puzzled by this call trace. It happens after stopping the nfsd at server side when the client side is doing cp over NFSv3:

[49388.040091] cp            D 0000000000000082  2968  2782  28204 0x00000000
[49388.040097]  ffff8800b8587778 0000000000000002 ffff8800b85877f8 00000000001d4e40
[49388.040103]  ffff8800b8587fd8 00000000001d4e40 ffff8800b8587fd8 ffff8800b8ec4700
[49388.040110]  00000000001d4e40 ffff8800b8587fd8 00000000001d4e40 00000000001d4e40
[49388.040116] Call Trace:
[49388.040121]  [<ffffffff810de503>] ? prepare_to_wait+0x73/0xc0
[49388.040127]  [<ffffffff81b32750>] ? rpc_wait_bit_killable+0x0/0x60
[49388.040132]  [<ffffffff81b3277f>] rpc_wait_bit_killable+0x2f/0x60
[49388.040136]  [<ffffffff81babded>] __wait_on_bit+0x8d/0xe0
[49388.040140]  [<ffffffff81b32750>] ? rpc_wait_bit_killable+0x0/0x60
[49388.040144]  [<ffffffff81babec6>] out_of_line_wait_on_bit+0x86/0xa0
[49388.040149]  [<ffffffff810de170>] ? wake_bit_function+0x0/0x70
[49388.040154]  [<ffffffff81b333bf>] __rpc_execute+0x16f/0x3f0
[49388.040158]  [<ffffffff81b3367b>] rpc_execute+0x3b/0x50
[49388.040162]  [<ffffffff81b28d31>] rpc_run_task+0x51/0xc0
[49388.040167]  [<ffffffff81366ad6>] nfs_commit_list+0x1f6/0x3e0
[49388.040172]  [<ffffffff81366de9>] nfs_commit_inode+0x129/0x170
[49388.040176]  [<ffffffff813677fa>] nfs_write_inode+0x7a/0xf0
[49388.040180]  [<ffffffff81239a8b>] writeback_single_inode+0x28b/0x3f0
[49388.040186]  [<ffffffff8123ac08>] writeback_inodes_wb+0x318/0x650
[49388.040191]  [<ffffffff8123b1d2>] writeback_inodes_wbc+0x22/0x30
[49388.040196]  [<ffffffff811a5a00>] balance_dirty_pages_ratelimited_nr+0x400/0x5d0
[49388.040202]  [<ffffffff81196306>] ? iov_iter_copy_from_user_atomic+0xa6/0x1c0
[49388.040207]  [<ffffffff81196898>] generic_file_buffered_write+0x258/0x370
[49388.040213]  [<ffffffff81199b7a>] __generic_file_aio_write+0x2ea/0x5f0
[49388.040218]  [<ffffffff81bad374>] ? mutex_lock_nested+0x394/0x530
[49388.040223]  [<ffffffff81199edf>] ? generic_file_aio_write+0x5f/0x100
[49388.040229]  [<ffffffff81199ef9>] generic_file_aio_write+0x79/0x100
[49388.040235]  [<ffffffff81353f00>] nfs_file_write+0xe0/0x2a0
[49388.040240]  [<ffffffff8120a138>] do_sync_write+0xe8/0x140
[49388.040246]  [<ffffffff811bd7b6>] ? might_fault+0xd6/0xf0
[49388.040251]  [<ffffffff8120b156>] vfs_write+0xb6/0x220
[49388.040255]  [<ffffffff8120b406>] sys_write+0x66/0xb0
[49388.040260]  [<ffffffff8104ab72>] system_call_fastpath+0x16/0x1b
Quoted 1 line

From simple code review I cannot explain why out_of_line_wait_on_bit()

Quoted 8 lines

is called inside __rpc_execute() for a commit request.

nfs_commit_rpcsetup() sets RPC_TASK_ASYNC for task_setup_data.flags, which is transferred to task->tk_flags in rpc_init_task(). __rpc_execute() should then return on task_is_async=1 and skip the out_of_line_wait_on_bit() call. However the trace shows that out_of_line_wait_on_bit() is called. I'm a bit puzzled. I must have missed something. Is this the expected behavior?

Hi Fengguang,

Are you sure this trace is from a recent kernel? In all kernels prior to 2.6.34-rc3, COMMIT was a synchronous RPC call, which would explain the above trace.

Cheers
Trond

#3 lore raw
In reply to a message not in the archive
Quoted 5 lines

Hi Fengguang,

Are you sure this trace is from a recent kernel? In all kernels prior to 2.6.34-rc3, COMMIT was a synchronous RPC call, which would explain the above trace.

My god. I was running 2.6.34-rc1 and reading 2.6.35-rc4 code ..

Sorry for the noise!

Thanks,
Fengguang