We've been running some tests to understand how the 2.6.25 "intr/
nointr" behavior affects signal handling during I/O on NFS mounts.
While running an Oracle database workload, we signal the database
(this is a normal way administrative tools control database
activity). Subsequently all of the I/O threads block on the inode
mutex in nfs_invalidate_mapping() except this one:
INFO: task oracle:27214 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
message.
oracle D f6d85e84 1592 27214 1
c93d2920 00200086 00000001 f6d85e84 c04a0080 c04a0080 c04a0080
c93d2b84
c93d2b84 c4021f80 00000001 cc072000 f341c900 f6d85e7c 10a1a042
f6d85e7c
cc072ddc c4021f80 03b7e000 cc072ddc c40082b4 c036e21c cc072dd4
00000001
Call Trace:
[<c036e21c>] io_schedule+0x4c/0x90
[<c015f63c>] sync_page+0x2c/0x40
[<c036e3e5>] __wait_on_bit_lock+0x45/0x70
[<c015f610>] sync_page+0x0/0x40
[<c015f5f3>] __lock_page+0x73/0x80
[<c013cad0>] wake_bit_function+0x0/0x80
[<c0167f98>] invalidate_inode_pages2_range+0xb8/0x200
[<f905d1a8>] nfs_writepages+0x68/0x90 [nfs]
[<f905489f>] nfs_invalidate_mapping_nolock+0x1f/0xd0 [nfs]
[<f9054ffa>] nfs_invalidate_mapping+0x5a/0x60 [nfs]
[<f90538a5>] nfs_file_read+0x85/0x120 [nfs]
[<c0182685>] do_sync_read+0xd5/0x120
[<c016cf4a>] __do_fault+0x1ca/0x400
[<c011c277>] __update_rq_clock+0x27/0x180
[<c013ca80>] autoremove_wake_function+0x0/0x50
[<c0136b25>] k_getrusage+0x1f5/0x200
[<c01e525c>] security_file_permission+0xc/0x10
[<c0182736>] rw_verify_area+0x66/0xd0
[<c0136b52>] getrusage+0x22/0x40
[<c0182f81>] vfs_read+0xa1/0x140
[<c01825b0>] do_sync_read+0x0/0x120
[<c01835da>] sys_pread64+0x6a/0x70
[<c0103e62>] syscall_call+0x7/0xb
I haven't looked too closely at this, but maybe the signal caused a
lost I/O interrupt?
What would be the next steps to troubleshoot this further?
--
Chuck Lever
chuck[dot]lever[at]oracle[dot]com
On Thu, 2008-05-22 at 10:57 -0400, Chuck Lever wrote:
> We've been running some tests to understand how the 2.6.25 "intr/
> nointr" behavior affects signal handling during I/O on NFS mounts.
>
> While running an Oracle database workload, we signal the database
> (this is a normal way administrative tools control database
> activity). Subsequently all of the I/O threads block on the inode
> mutex in nfs_invalidate_mapping() except this one:
>
> INFO: task oracle:27214 blocked for more than 120 seconds.
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
> message.
> oracle D f6d85e84 1592 27214 1
> c93d2920 00200086 00000001 f6d85e84 c04a0080 c04a0080 c04a0080
> c93d2b84
> c93d2b84 c4021f80 00000001 cc072000 f341c900 f6d85e7c 10a1a042
> f6d85e7c
> cc072ddc c4021f80 03b7e000 cc072ddc c40082b4 c036e21c cc072dd4
> 00000001
> Call Trace:
> [<c036e21c>] io_schedule+0x4c/0x90
> [<c015f63c>] sync_page+0x2c/0x40
> [<c036e3e5>] __wait_on_bit_lock+0x45/0x70
> [<c015f610>] sync_page+0x0/0x40
> [<c015f5f3>] __lock_page+0x73/0x80
> [<c013cad0>] wake_bit_function+0x0/0x80
> [<c0167f98>] invalidate_inode_pages2_range+0xb8/0x200
> [<f905d1a8>] nfs_writepages+0x68/0x90 [nfs]
> [<f905489f>] nfs_invalidate_mapping_nolock+0x1f/0xd0 [nfs]
> [<f9054ffa>] nfs_invalidate_mapping+0x5a/0x60 [nfs]
> [<f90538a5>] nfs_file_read+0x85/0x120 [nfs]
> [<c0182685>] do_sync_read+0xd5/0x120
> [<c016cf4a>] __do_fault+0x1ca/0x400
> [<c011c277>] __update_rq_clock+0x27/0x180
> [<c013ca80>] autoremove_wake_function+0x0/0x50
> [<c0136b25>] k_getrusage+0x1f5/0x200
> [<c01e525c>] security_file_permission+0xc/0x10
> [<c0182736>] rw_verify_area+0x66/0xd0
> [<c0136b52>] getrusage+0x22/0x40
> [<c0182f81>] vfs_read+0xa1/0x140
> [<c01825b0>] do_sync_read+0x0/0x120
> [<c01835da>] sys_pread64+0x6a/0x70
> [<c0103e62>] syscall_call+0x7/0xb
>
> I haven't looked too closely at this, but maybe the signal caused a
> lost I/O interrupt?
>
> What would be the next steps to troubleshoot this further?
'cat /proc/1592/status' should tell you if there is a signal that is
being blocked.
--
Trond Myklebust
Linux NFS client maintainer
NetApp
[email protected]
http://www.netapp.com
On Thu, May 22, 2008 at 10:57:35AM -0400, Chuck Lever wrote:
> We've been running some tests to understand how the 2.6.25 "intr/
> nointr" behavior affects signal handling during I/O on NFS mounts.
I believe intr is now a no-op ... we still recognise the option, but it
does nothing.
> While running an Oracle database workload, we signal the database
> (this is a normal way administrative tools control database
> activity). Subsequently all of the I/O threads block on the inode
> mutex in nfs_invalidate_mapping() except this one:
>
> INFO: task oracle:27214 blocked for more than 120 seconds.
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
> message.
> oracle D f6d85e84 1592 27214 1
> c93d2920 00200086 00000001 f6d85e84 c04a0080 c04a0080 c04a0080
> c93d2b84
> c93d2b84 c4021f80 00000001 cc072000 f341c900 f6d85e7c 10a1a042
> f6d85e7c
> cc072ddc c4021f80 03b7e000 cc072ddc c40082b4 c036e21c cc072dd4
> 00000001
> Call Trace:
> [<c036e21c>] io_schedule+0x4c/0x90
> [<c015f63c>] sync_page+0x2c/0x40
> [<c036e3e5>] __wait_on_bit_lock+0x45/0x70
> [<c015f610>] sync_page+0x0/0x40
> [<c015f5f3>] __lock_page+0x73/0x80
> [<c013cad0>] wake_bit_function+0x0/0x80
> [<c0167f98>] invalidate_inode_pages2_range+0xb8/0x200
> [<f905d1a8>] nfs_writepages+0x68/0x90 [nfs]
[...]
This isn't jumping out screaming that it's my fault (obviously it
probably is, but ...). invalidate_inode_pages2_range calls lock_page()
... which uses TASK_UNINTERRUPTIBLE. If it were calling
lock_page_killable(), I'd understand.
Maybe this isn't the problem task though. Maybe this is just the
canary that dropped dead, and we should stop trying to autopsy it and
start running. [ok, I'll stop with the bad analogies now]
It might be informative to do something like:
int __fatal_signal_pending(struct task_struct *tsk)
{
- return sigismember(&tsk->pending.signal, SIGKILL);
+ if (sigismember(&tsk->pending.signal, SIGKILL)) {
+ dump_stack();
+ return 1;
+ }
+ return 0;
}
> I haven't looked too closely at this, but maybe the signal caused a
> lost I/O interrupt?
I wonder if the signal caused something bad to happen to the page that
we're trying to sync? Maybe dumping the page struct would give us some
useful information?
--
Intel are signing my paycheques ... these opinions are still mine
"Bill, look, we understand that you're interested in selling us this
operating system, but compare it to ours. We can't possibly take such
a retrograde step."
On May 22, 2008, at 11:50 PM, Matthew Wilcox wrote:
> On Thu, May 22, 2008 at 10:57:35AM -0400, Chuck Lever wrote:
>> We've been running some tests to understand how the 2.6.25 "intr/
>> nointr" behavior affects signal handling during I/O on NFS mounts.
>
> I believe intr is now a no-op ... we still recognise the option, but
> it
> does nothing.
Understood...
>> While running an Oracle database workload, we signal the database
>> (this is a normal way administrative tools control database
>> activity). Subsequently all of the I/O threads block on the inode
>> mutex in nfs_invalidate_mapping() except this one:
>>
>> INFO: task oracle:27214 blocked for more than 120 seconds.
>> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
>> message.
>> oracle D f6d85e84 1592 27214 1
>> c93d2920 00200086 00000001 f6d85e84 c04a0080 c04a0080 c04a0080
>> c93d2b84
>> c93d2b84 c4021f80 00000001 cc072000 f341c900 f6d85e7c 10a1a042
>> f6d85e7c
>> cc072ddc c4021f80 03b7e000 cc072ddc c40082b4 c036e21c cc072dd4
>> 00000001
>> Call Trace:
>> [<c036e21c>] io_schedule+0x4c/0x90
>> [<c015f63c>] sync_page+0x2c/0x40
>> [<c036e3e5>] __wait_on_bit_lock+0x45/0x70
>> [<c015f610>] sync_page+0x0/0x40
>> [<c015f5f3>] __lock_page+0x73/0x80
>> [<c013cad0>] wake_bit_function+0x0/0x80
>> [<c0167f98>] invalidate_inode_pages2_range+0xb8/0x200
>> [<f905d1a8>] nfs_writepages+0x68/0x90 [nfs]
> [...]
>
> This isn't jumping out screaming that it's my fault (obviously it
> probably is, but ...). invalidate_inode_pages2_range calls
> lock_page()
> ... which uses TASK_UNINTERRUPTIBLE. If it were calling
> lock_page_killable(), I'd understand.
I don't think it's directly caused by your changes, but my concern is
that you may have exposed a latent bug, or exposed an underlying
design assumption in the NFS/RPC client stack that causes the hang in
this situation.
> Maybe this isn't the problem task though. Maybe this is just the
> canary that dropped dead, and we should stop trying to autopsy it and
> start running. [ok, I'll stop with the bad analogies now]
This appears to be the only task that is in this state. All the
others in the dump are waiting for this inode's mutex. I don't know
if the dump is complete, though.
> It might be informative to do something like:
>
> int __fatal_signal_pending(struct task_struct *tsk)
> {
> - return sigismember(&tsk->pending.signal, SIGKILL);
> + if (sigismember(&tsk->pending.signal, SIGKILL)) {
> + dump_stack();
> + return 1;
> + }
> + return 0;
> }
>
>> I haven't looked too closely at this, but maybe the signal caused a
>> lost I/O interrupt?
>
> I wonder if the signal caused something bad to happen to the page that
> we're trying to sync? Maybe dumping the page struct would give us
> some
> useful information?
I've passed your suggestions along to our testers.
--
Chuck Lever
chuck[dot]lever[at]oracle[dot]com
On Tue, May 27, 2008 at 11:59:00AM -0400, Chuck Lever wrote:
> >This isn't jumping out screaming that it's my fault (obviously it
> >probably is, but ...). invalidate_inode_pages2_range calls
> >lock_page()
> >... which uses TASK_UNINTERRUPTIBLE. If it were calling
> >lock_page_killable(), I'd understand.
>
> I don't think it's directly caused by your changes, but my concern is
> that you may have exposed a latent bug, or exposed an underlying
> design assumption in the NFS/RPC client stack that causes the hang in
> this situation.
Certainly possible.
> >Maybe this isn't the problem task though. Maybe this is just the
> >canary that dropped dead, and we should stop trying to autopsy it and
> >start running. [ok, I'll stop with the bad analogies now]
>
> This appears to be the only task that is in this state. All the
> others in the dump are waiting for this inode's mutex. I don't know
> if the dump is complete, though.
My thought is that the task which caused the problem has gone away and
left this page in a state where sync_page will never finish.
> I've passed your suggestions along to our testers.
Thanks! I'm keen to get this fixed.
--
Intel are signing my paycheques ... these opinions are still mine
"Bill, look, we understand that you're interested in selling us this
operating system, but compare it to ours. We can't possibly take such
a retrograde step."
On May 27, 2008, at May 27, 2008, 1:35 PM, Matthew Wilcox wrote:
> On Tue, May 27, 2008 at 11:59:00AM -0400, Chuck Lever wrote:
>>> This isn't jumping out screaming that it's my fault (obviously it
>>> probably is, but ...). invalidate_inode_pages2_range calls
>>> lock_page()
>>> ... which uses TASK_UNINTERRUPTIBLE. If it were calling
>>> lock_page_killable(), I'd understand.
>>
>> I don't think it's directly caused by your changes, but my concern is
>> that you may have exposed a latent bug, or exposed an underlying
>> design assumption in the NFS/RPC client stack that causes the hang in
>> this situation.
>
> Certainly possible.
>
>>> Maybe this isn't the problem task though. Maybe this is just the
>>> canary that dropped dead, and we should stop trying to autopsy it
>>> and
>>> start running. [ok, I'll stop with the bad analogies now]
>>
>> This appears to be the only task that is in this state. All the
>> others in the dump are waiting for this inode's mutex. I don't know
>> if the dump is complete, though.
>
> My thought is that the task which caused the problem has gone away and
> left this page in a state where sync_page will never finish.
One thing to note: NFS doesn't have a sync_page() a_op. So this
shouldn't be the problem, right?
>> I've passed your suggestions along to our testers.
>
> Thanks! I'm keen to get this fixed.
--
Chuck Lever
chuck[dot]lever[at]oracle[dot]com