lkml.org 
[lkml]   [2009]   [Jul]   [16]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
SubjectRe: 2.6.31-rc1-mmotm0702 - ps command hangs inside kernel
From
Date
On Tue, 14 Jul 2009 07:31:19 +0200, Stefani Seibold said:
> Am Montag, den 13.07.2009, 14:38 -0700 schrieb Andrew Morton:
> > On Mon, 13 Jul 2009 16:54:51 -0400
> > Valdis.Kletnieks@vt.edu wrote:
> >
> > > Several times recently, I've had the 'ps' command hang inside the kernel
> > > for extended periods of time - usually around 1100 seconds, but today I
> > > had one that hung there for 2351 seconds.

> i am the author of the get_stack_usage_bytes(). Because i have currently
> no 64bit machine running, i am not able to analyse your problem. Does it
> only happen on 32bit application on a 64bit kernel? Is it only affected
> to pcsd?

I've only seen it happen to pcscd. However, most of the time it's one of
the very few 32-bit apps running on my laptop (I've got exactly *one* legacy
app for a secure-token that is stuck in 32-bit land). So I can't tell if it's
a generic 32-bit issue.

> Can you give me a more accurate info what exactly the problem is?


>
> > OK, thanks for the analysis.
> >
> > > Here's the traceback of the ps, as reported by 2 alt-sysrq-t several
> > > minutes apart:
> > >
> > >
> > > ps R running task 3936 26646 26580 0x00000080
> > > ffff88005a599bd8 ffffffff81499842 ffff88000213bf80 0000000000000000
> > > ffff88005a599b78 ffffffff8103589b ffffffff81035805 ffff88007e71ea40
> > > ffff88000213bf80 ffff8800657d8fe0 000000000000df78 ffff8800657d8fe8
> > > Call Trace:
> > > [<ffffffff81499842>] ? thread_return+0xb6/0xfa
> > > [<ffffffff8103589b>] ? finish_task_switch+0xd1/0xf4
> > > [<ffffffff81035805>] ? finish_task_switch+0x3b/0xf4
> > > [<ffffffff81065f3f>] ? trace_hardirqs_on_caller+0x1f/0x145
> > > [<ffffffff8149b2a6>] ? trace_hardirqs_on_thunk+0x3a/0x3f
> > > [<ffffffff8101f76b>] smp_apic_timer_interrupt+0x81/0x8f
> > > [<ffffffff81046231>] ? irq_exit+0xaf/0xb4
> > > [<ffffffff8100bd80>] ? restore_args+0x0/0x30
> > > [<ffffffff810b8222>] ? IS_ERR+0x25/0x2c
> > > [<ffffffff810b8222>] ? IS_ERR+0x25/0x2c
> > > [<ffffffff810b8f22>] ? follow_page+0x28/0x2e3
> > > [<ffffffff810b91d9>] ? follow_page+0x2df/0x2e3
> > > [<ffffffff811219d8>] ? proc_pid_status+0x5e0/0x694
> > > [<ffffffff81066072>] ? trace_hardirqs_on+0xd/0xf
> > > [<ffffffff8111e42c>] ? proc_single_show+0x57/0x74
> > > [<ffffffff810e90b4>] ? seq_read+0x249/0x49b
> > > [<ffffffff8116c840>] ? security_file_permission+0x11/0x13
> > > [<ffffffff810d05e1>] ? vfs_read+0xe0/0x141
> > > [<ffffffff810d8191>] ? path_put+0x1d/0x21
> > > [<ffffffff810d06f8>] ? sys_read+0x45/0x69
> > > [<ffffffff8100b2ab>] ? system_call_fastpath+0x16/0x1b
> >
> The double follow_page looks strange for me... I will have a look on it.

It's possible that one of the two follow_page() entries is stale and just
happened to be left on the stack. A large chunk of proc_pid_status() is
inlined, so it's possible that two calls were made and left their return
addresses in different locations on the stack.

I am pretty sure that follow_page+0x28 is the correct one, as I see it
in 2 more tracebacks today (see below)...

Got a better idea than just sticking in a printk() to dump the starting
values of stkpage and vma->vm_start in get_stack_usage_in_bytes()? I suspect
that for a 32-bit process, those 2 values aren't lined up the way we think
they are, and as a result that for loop ends up walking across a *lot* of
pages unintentionally.

> > Another possibility is that pcscd has gone off on a long in-kernel sulk
> > (polling hardware?) while holding some lock which ps needs (eg, mmap_sem).
> >
> > It would be useful if you can grab a pcscd backtrace during the stall.

Got bit again this morning - here's the relevant tracebacks. Looks like pcscd
is off sulking in select() and nanosleep(), which are pretty normal places for
programs to go sulk.

(pcscd has 2 threads, apparently. I had 2 ps commands hung up, thus the
two entries for it)

pcscd S 0000000000000000 4656 2100 1 0x00020080
ffff88007da3f948 0000000000000046 ffff88007da3f8b8 ffffffff81052b2e
ffff88007f90e340 ffff88007e08db30 0000000000000000 0000000000000001
ffff88007da3f8d8 ffff880074ee4fa0 000000000000df78 ffff880074ee4fa0
Call Trace:
[<ffffffff81052b2e>] ? queue_work_on+0x5e/0x6c
[<ffffffff81056bec>] ? add_wait_queue+0x1b/0x42
[<ffffffff8149a70b>] schedule_hrtimeout_range+0x3f/0x11f
[<ffffffff8149bb91>] ? _spin_unlock_irqrestore+0x72/0x80
[<ffffffff81056c0b>] ? add_wait_queue+0x3a/0x42
[<ffffffff81065f3f>] ? trace_hardirqs_on_caller+0x1f/0x145
[<ffffffff81066072>] ? trace_hardirqs_on+0xd/0xf
[<ffffffff810de040>] poll_schedule_timeout+0x33/0x4c
[<ffffffff810deb82>] do_select+0x4b7/0x4f5
[<ffffffff810df064>] ? __pollwait+0x0/0xc7
[<ffffffff810df12b>] ? pollwake+0x0/0x51
[<ffffffff810a8d3a>] ? get_page_from_freelist+0x38a/0x63c
[<ffffffff811bb5c4>] ? list_del+0xbc/0xea
[<ffffffff810a7561>] ? __rmqueue+0x124/0x2bf
[<ffffffff81034de2>] ? get_parent_ip+0x11/0x42
[<ffffffff8149e770>] ? sub_preempt_count+0x35/0x49
[<ffffffff810a8ed8>] ? get_page_from_freelist+0x528/0x63c
[<ffffffff8105b908>] ? __update_sched_clock+0x2f/0x8e
[<ffffffff8105bb72>] ? sched_clock_cpu+0x20b/0x219
[<ffffffff81065f3f>] ? trace_hardirqs_on_caller+0x1f/0x145
[<ffffffff81066072>] ? trace_hardirqs_on+0xd/0xf
[<ffffffff810542bf>] ? alloc_pid+0x2ce/0x3e3
[<ffffffff810542bf>] ? alloc_pid+0x2ce/0x3e3
[<ffffffff81034de2>] ? get_parent_ip+0x11/0x42
[<ffffffff81065f3f>] ? trace_hardirqs_on_caller+0x1f/0x145
[<ffffffff81107bf7>] compat_core_sys_select+0x183/0x23d
[<ffffffff8149e770>] ? sub_preempt_count+0x35/0x49
[<ffffffff8149bb91>] ? _spin_unlock_irqrestore+0x72/0x80
[<ffffffff81030930>] ? task_rq_unlock+0xc/0xe
[<ffffffff8103ab25>] ? wake_up_new_task+0x169/0x174
[<ffffffff8103eaf6>] ? do_fork+0x37a/0x424
[<ffffffff8105e2e2>] ? current_kernel_time+0x28/0x50
[<ffffffff81107f48>] compat_sys_select+0x96/0xbe
[<ffffffff8107d8b0>] ? audit_syscall_entry+0x170/0x19c
[<ffffffff8102b538>] sysenter_dispatch+0x7/0x2c
pcscd S ffff88007e1fbf48 5640 2106 1 0x00020080
ffff88007e1fbe28 0000000000000046 ffff88007e1fbd88 ffffffff8149bb91
ffff88007e1fbe78 0000000000000001 ffff88007e1fbe18 ffffffff81059d91
0000000000000000 ffff880074d6ac20 000000000000df78 ffff880074d6ac20
Call Trace:
[<ffffffff8149bb91>] ? _spin_unlock_irqrestore+0x72/0x80
[<ffffffff81059d91>] ? __hrtimer_start_range_ns+0x35b/0x36d
[<ffffffff8149a882>] do_nanosleep+0x88/0xee
[<ffffffff81059e75>] hrtimer_nanosleep+0xac/0x121
[<ffffffff8105935d>] ? hrtimer_wakeup+0x0/0x21
[<ffffffff81075da2>] compat_sys_nanosleep+0x7b/0xe1
[<ffffffff8102b538>] sysenter_dispatch+0x7/0x2c
[<ffffffff8149b2a6>] ? trace_hardirqs_on_thunk+0x3a/0x3f
ps R running task 3936 45836 45832 0x00000080
ffff88004dc09b98 ffffffff81065f3f 0000000000000001 00000388525af000
ffff88004dc09bb8 ffffffff81065f3f 0000000000000000 000003886bc2b000
ffff88004dc09ce8 ffffffff8149b2a6 0000000000000000 ffff88000212cf68
Call Trace:
[<ffffffff81065f3f>] ? trace_hardirqs_on_caller+0x1f/0x145
[<ffffffff81065f3f>] trace_hardirqs_on_caller+0x1f/0x145
[<ffffffff8149b2a6>] trace_hardirqs_on_thunk+0x3a/0x3f
[<ffffffff81065f3f>] ? trace_hardirqs_on_caller+0x1f/0x145
[<ffffffff8149b2a6>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[<ffffffff8101f76b>] ? smp_apic_timer_interrupt+0x81/0x8f
[<ffffffff810b8222>] ? IS_ERR+0x25/0x2c
[<ffffffff810b8f22>] ? follow_page+0x28/0x2e3
[<ffffffff811219d8>] proc_pid_status+0x5e0/0x694
[<ffffffff81066072>] ? trace_hardirqs_on+0xd/0xf
[<ffffffff8111e42c>] proc_single_show+0x57/0x74
[<ffffffff810e90b4>] seq_read+0x249/0x49b
[<ffffffff8116c840>] ? security_file_permission+0x11/0x13
[<ffffffff810d05e1>] vfs_read+0xe0/0x141
[<ffffffff810d8191>] ? path_put+0x1d/0x21
[<ffffffff810d06f8>] sys_read+0x45/0x69
[<ffffffff8100b2ab>] system_call_fastpath+0x16/0x1b
ps R running task 5584 45948 45868 0x00000080
ffff88004de81bb8 0000000000000046 ffff88004de81b18 ffffffff81035142
ffff880002120f80 0000000000000000 ffff88004de81b68 ffffffff8103589b
ffffffff81035805 ffff8800653fc460 000000000000df78 ffff8800653fc468
Call Trace:
[<ffffffff81035142>] ? mmdrop+0x2b/0x3d
[<ffffffff8103589b>] ? finish_task_switch+0xd1/0xf4
[<ffffffff81035805>] ? finish_task_switch+0x3b/0xf4
[<ffffffff81499842>] ? thread_return+0xb6/0xfa
[<ffffffff814999d1>] preempt_schedule_irq+0x56/0x74
[<ffffffff8100be96>] retint_kernel+0x26/0x30
[<ffffffff81094996>] ? ftrace_likely_update+0x12/0x14
[<ffffffff8100bd80>] ? restore_args+0x0/0x30
[<ffffffff810b8222>] IS_ERR+0x25/0x2c
[<ffffffff810b8f22>] follow_page+0x28/0x2e3
[<ffffffff81094990>] ? ftrace_likely_update+0xc/0x14
[<ffffffff811219d8>] proc_pid_status+0x5e0/0x694
[<ffffffff81066072>] ? trace_hardirqs_on+0xd/0xf
[<ffffffff8111e42c>] proc_single_show+0x57/0x74
[<ffffffff810e90b4>] seq_read+0x249/0x49b
[<ffffffff8116c840>] ? security_file_permission+0x11/0x13
[<ffffffff810d05e1>] vfs_read+0xe0/0x141
[<ffffffff810d8191>] ? path_put+0x1d/0x21
[<ffffffff810d06f8>] sys_read+0x45/0x69
[<ffffffff8100b2ab>] system_call_fastpath+0x16/0x1b
Just for comparison, here's the pcscd stack traces right now, when things
are working just fine. One thread in select, one in nanosleep, just like
when it was broken.

pcscd S 0000000000000000 4656 2000 1 0x00020080
ffff880073037948 0000000000000046 ffff8800730378a8 ffffffff81030461
0000000000000000 0000000000000000 ffff880000000000 ffffffff81499842
ffff8800730378d8 ffff88007ebf9120 000000000000df78 ffff88007ebf9120
Call Trace:
[<ffffffff81030461>] ? need_resched+0x3a/0x40
[<ffffffff81499842>] ? thread_return+0xb6/0xfa
[<ffffffff81056bec>] ? add_wait_queue+0x1b/0x42
[<ffffffff8149a70b>] schedule_hrtimeout_range+0x3f/0x11f
[<ffffffff8149bb91>] ? _spin_unlock_irqrestore+0x72/0x80
[<ffffffff81056c0b>] ? add_wait_queue+0x3a/0x42
[<ffffffff810df122>] ? __pollwait+0xbe/0xc7
[<ffffffff810de040>] poll_schedule_timeout+0x33/0x4c
[<ffffffff810deb82>] do_select+0x4b7/0x4f5
[<ffffffff810df064>] ? __pollwait+0x0/0xc7
[<ffffffff810df12b>] ? pollwake+0x0/0x51
[<ffffffff810a8d3a>] ? get_page_from_freelist+0x38a/0x63c
[<ffffffff811bb5c4>] ? list_del+0xbc/0xea
[<ffffffff810a7561>] ? __rmqueue+0x124/0x2bf
[<ffffffff81034de2>] ? get_parent_ip+0x11/0x42
[<ffffffff8149e770>] ? sub_preempt_count+0x35/0x49
[<ffffffff810a8ed8>] ? get_page_from_freelist+0x528/0x63c
[<ffffffff81035805>] ? finish_task_switch+0x3b/0xf4
[<ffffffff81065f3f>] ? trace_hardirqs_on_caller+0x1f/0x145
[<ffffffff8149bc01>] ? _spin_unlock_irq+0x62/0x6f
[<ffffffff8103589b>] ? finish_task_switch+0xd1/0xf4
[<ffffffff81035805>] ? finish_task_switch+0x3b/0xf4
[<ffffffff81030461>] ? need_resched+0x3a/0x40
[<ffffffff81499842>] ? thread_return+0xb6/0xfa
[<ffffffff81065f3f>] ? trace_hardirqs_on_caller+0x1f/0x145
[<ffffffff81107bf7>] compat_core_sys_select+0x183/0x23d
[<ffffffff81499a4d>] ? preempt_schedule+0x5e/0x67
[<ffffffff8149bb9a>] ? _spin_unlock_irqrestore+0x7b/0x80
[<ffffffff81030930>] ? task_rq_unlock+0xc/0xe
[<ffffffff8103ab25>] ? wake_up_new_task+0x169/0x174
[<ffffffff8103eaf6>] ? do_fork+0x37a/0x424
[<ffffffff81107f48>] compat_sys_select+0x96/0xbe
[<ffffffff8107d80b>] ? audit_syscall_entry+0xcb/0x19c
[<ffffffff8102b538>] sysenter_dispatch+0x7/0x2c
pcscd S ffff88007cf99f48 4896 2006 1 0x00020080
ffff88007cf99e28 0000000000000046 ffff88007cf99d88 ffffffff8149bb91
ffff88007cf99e78 0000000000000001 ffff88007cf99e18 ffffffff81059d91
0000000000000000 ffff88007e4da3e0 000000000000df78 ffff88007e4da3e0
Call Trace:
[<ffffffff8149bb91>] ? _spin_unlock_irqrestore+0x72/0x80
[<ffffffff81059d91>] ? __hrtimer_start_range_ns+0x35b/0x36d
[<ffffffff8149a882>] do_nanosleep+0x88/0xee
[<ffffffff81059e75>] hrtimer_nanosleep+0xac/0x121
[<ffffffff8105935d>] ? hrtimer_wakeup+0x0/0x21
[<ffffffff81075da2>] compat_sys_nanosleep+0x7b/0xe1
[<ffffffff8102b538>] sysenter_dispatch+0x7/0x2c
[<ffffffff8149b2a6>] ? trace_hardirqs_on_thunk+0x3a/0x3f

[unhandled content-type:application/pgp-signature]
\
 
 \ /
  Last update: 2009-07-16 21:15    [from the cache]
©2003-2011 Jasper Spaans