lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
Open Source and information security mailing list archives
| ||
|
Message-ID: <573B2AB0.7070004@hurleysoftware.com> Date: Tue, 17 May 2016 07:29:04 -0700 From: Peter Hurley <peter@...leysoftware.com> To: Ming Lei <ming.lei@...onical.com>, Dann Frazier <dann.frazier@...onical.com>, Scot Doyle <lkml14@...tdoyle.com> Cc: David Airlie <airlied@...ux.ie>, dri-devel@...ts.freedesktop.org, "Chintakuntla, Radha" <Radha.Chintakuntla@...iumnetworks.com>, Greg Kroah-Hartman <gregkh@...uxfoundation.org>, Jiri Slaby <jslaby@...e.com>, Pavel Machek <pavel@....cz>, Linux Kernel Mailing List <linux-kernel@...r.kernel.org> Subject: Re: ast: cursor flashing softlockups [ +to Scot Doyle ] Scot, please take a look at this soft lockup. Regards, Peter Hurley Hi Ming, On 05/17/2016 02:12 AM, Ming Lei wrote: > Hi, > > On Tue, May 17, 2016 at 4:07 AM, Dann Frazier > <dann.frazier@...onical.com> wrote: >> Hi, >> I'm observing a soft lockup issue w/ the ASPEED controller on an >> arm64 server platform. This was originally seen on Ubuntu's 4.4 >> kernel, but it is reproducible w/ vanilla 4.6-rc7 as well. >> >> [ 32.792656] NMI watchdog: BUG: soft lockup - CPU#38 stuck for 22s! >> [swapper/38:0] >> >> I observe this just once each time I boot into debian-installer (I'm >> using a serial console, but the ast module gets loaded during >> startup). > > I have figured out that it is caused by 'mod_timer(timer, jiffies)' and > 'ops->cur_blink_jiffies' is observed as zero in cursor_timer_handler() > when the issue happened. Thanks for tracking this down. This softlockup looks to be caused by: commit 27a4c827c34ac4256a190cc9d24607f953c1c459 Author: Scot Doyle <lkml14@...tdoyle.com> Date: Thu Mar 26 13:56:38 2015 +0000 fbcon: use the cursor blink interval provided by vt vt now provides a cursor blink interval via vc_data. Use this interval instead of the currently hardcoded 200 msecs. Store it in fbcon_ops to avoid locking the console in cursor_timer_handler(). Signed-off-by: Scot Doyle <lkml14@...tdoyle.com> Acked-by: Pavel Machek <pavel@....cz> Signed-off-by: Greg Kroah-Hartman <gregkh@...uxfoundation.org> and commit bd63364caa8df38bad2b25b11b2a1b849475cce5 Author: Scot Doyle <lkml14@...tdoyle.com> Date: Thu Mar 26 13:54:39 2015 +0000 vt: add cursor blink interval escape sequence Add an escape sequence to specify the current console's cursor blink interval. The interval is specified as a number of milliseconds until the next cursor display state toggle, from 50 to 65535. /proc/loadavg did not show a difference with a one msec interval, but the lower bound is set to 50 msecs since slower hardware wasn't tested. Store the interval in the vc_data structure for later access by fbcon, initializing the value to fbcon's current hardcoded value of 200 msecs. Signed-off-by: Scot Doyle <lkml14@...tdoyle.com> Acked-by: Pavel Machek <pavel@....cz> Signed-off-by: Greg Kroah-Hartman <gregkh@...uxfoundation.org> > Looks it is a real fbcon/vt issue, see following: > > fbcon_init() > <-.con_init > <-visual_init() > > reset_terminal() > <-vc_init() > > vc->vc_cur_blink_ms is just set in reset_terminal() from vc_init() path, > and ops->cur_blink_jiffies is figured out from vc->vc_cur_blink_ms > in fbcon_init(). > > And visual_init() is always run before vc_init(), so ops->cur_blink_jiffies > is initialized as zero and cause the soft lockup issue finally. > > Thanks, > Ming > >> >> perf shows that the CPU caught by the NMI is typically in code >> updating the cursor timer: >> >> - 16.92% swapper [kernel.kallsyms] [k] _raw_spin_unlock_irqrestore >> - _raw_spin_unlock_irqrestore >> + 16.87% mod_timer >> + 0.05% cursor_timer_handler >> - 12.15% swapper [kernel.kallsyms] [k] queue_work_on >> - queue_work_on >> + 12.00% cursor_timer_handler >> + 0.15% call_timer_fn >> + 10.98% swapper [kernel.kallsyms] [k] run_timer_softirq >> - 2.23% swapper [kernel.kallsyms] [k] mod_timer >> - mod_timer >> + 1.97% cursor_timer_handler >> + 0.26% call_timer_fn >> >> During the same period, I can see that another CPU is actively >> executing the timer function: >> >> - 42.18% kworker/u96:2 [kernel.kallsyms] [k] ww_mutex_unlock >> - ww_mutex_unlock >> - 40.70% ast_dirty_update >> ast_imageblit >> soft_cursor >> bit_cursor >> fb_flashcursor >> process_one_work >> worker_thread >> kthread >> ret_from_fork >> + 1.48% ast_imageblit >> - 40.15% kworker/u96:2 [kernel.kallsyms] [k] __memcpy_toio >> - __memcpy_toio >> + 31.54% ast_dirty_update >> + 8.61% ast_imageblit >> >> Using the graph function tracer on fb_flashcursor(), I see that >> ast_dirty_update usually takes around 60 us, in which it makes 16 >> calls to __memcpy_toio(). However, there is always one instance on >> every boot of the installer where ast_dirty_update() takes ~98 *ms* to >> complete, during which it makes 743 calls to __memcpy_toio(). While >> that doesn't directly account for the full 22s, I do wonder if that >> maybe a smoking gun. >> >> fyi, this is being tracked at: https://bugs.launchpad.net/bugs/1574814 >> >> -dann
Powered by blists - more mailing lists