From mboxrd@z Thu Jan 1 00:00:00 1970 From: Peter Hurley Subject: Re: ast: cursor flashing softlockups Date: Tue, 17 May 2016 07:29:04 -0700 Message-ID: <573B2AB0.7070004@hurleysoftware.com> References: Mime-Version: 1.0 Content-Type: text/plain; charset="utf-8" Content-Transfer-Encoding: base64 Return-path: Received: from mail-pa0-x22b.google.com (mail-pa0-x22b.google.com [IPv6:2607:f8b0:400e:c03::22b]) by gabe.freedesktop.org (Postfix) with ESMTPS id 1E77A6E3BF for ; Tue, 17 May 2016 14:29:08 +0000 (UTC) Received: by mail-pa0-x22b.google.com with SMTP id xk12so7261041pac.0 for ; Tue, 17 May 2016 07:29:08 -0700 (PDT) In-Reply-To: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: dri-devel-bounces@lists.freedesktop.org Sender: "dri-devel" To: Ming Lei , Dann Frazier , Scot Doyle Cc: Greg Kroah-Hartman , Linux Kernel Mailing List , dri-devel@lists.freedesktop.org, "Chintakuntla, Radha" , Pavel Machek , Jiri Slaby List-Id: dri-devel@lists.freedesktop.org WyArdG8gU2NvdCBEb3lsZSBdCgpTY290LCBwbGVhc2UgdGFrZSBhIGxvb2sgYXQgdGhpcyBzb2Z0 IGxvY2t1cC4KClJlZ2FyZHMsClBldGVyIEh1cmxleQoKCkhpIE1pbmcsCgpPbiAwNS8xNy8yMDE2 IDAyOjEyIEFNLCBNaW5nIExlaSB3cm90ZToKPiBIaSwKPiAKPiBPbiBUdWUsIE1heSAxNywgMjAx NiBhdCA0OjA3IEFNLCBEYW5uIEZyYXppZXIKPiA8ZGFubi5mcmF6aWVyQGNhbm9uaWNhbC5jb20+ IHdyb3RlOgo+PiBIaSwKPj4gIEknbSBvYnNlcnZpbmcgYSBzb2Z0IGxvY2t1cCBpc3N1ZSB3LyB0 aGUgQVNQRUVEIGNvbnRyb2xsZXIgb24gYW4KPj4gYXJtNjQgc2VydmVyIHBsYXRmb3JtLiBUaGlz IHdhcyBvcmlnaW5hbGx5IHNlZW4gb24gVWJ1bnR1J3MgNC40Cj4+IGtlcm5lbCwgYnV0IGl0IGlz IHJlcHJvZHVjaWJsZSB3LyB2YW5pbGxhIDQuNi1yYzcgYXMgd2VsbC4KPj4KPj4gWyAgIDMyLjc5 MjY1Nl0gTk1JIHdhdGNoZG9nOiBCVUc6IHNvZnQgbG9ja3VwIC0gQ1BVIzM4IHN0dWNrIGZvciAy MnMhCj4+IFtzd2FwcGVyLzM4OjBdCj4+Cj4+IEkgb2JzZXJ2ZSB0aGlzIGp1c3Qgb25jZSBlYWNo IHRpbWUgSSBib290IGludG8gZGViaWFuLWluc3RhbGxlciAoSSdtCj4+IHVzaW5nIGEgc2VyaWFs IGNvbnNvbGUsIGJ1dCB0aGUgYXN0IG1vZHVsZSBnZXRzIGxvYWRlZCBkdXJpbmcKPj4gc3RhcnR1 cCkuCj4gCj4gSSBoYXZlIGZpZ3VyZWQgb3V0IHRoYXQgaXQgaXMgY2F1c2VkIGJ5ICdtb2RfdGlt ZXIodGltZXIsIGppZmZpZXMpJyBhbmQKPiAnb3BzLT5jdXJfYmxpbmtfamlmZmllcycgaXMgb2Jz ZXJ2ZWQgYXMgemVybyBpbiBjdXJzb3JfdGltZXJfaGFuZGxlcigpCj4gd2hlbiB0aGUgaXNzdWUg aGFwcGVuZWQuCgpUaGFua3MgZm9yIHRyYWNraW5nIHRoaXMgZG93bi4KClRoaXMgc29mdGxvY2t1 cCBsb29rcyB0byBiZSBjYXVzZWQgYnk6CgoJY29tbWl0IDI3YTRjODI3YzM0YWM0MjU2YTE5MGNj OWQyNDYwN2Y5NTNjMWM0NTkKCUF1dGhvcjogU2NvdCBEb3lsZSA8bGttbDE0QHNjb3Rkb3lsZS5j b20+CglEYXRlOiAgIFRodSBNYXIgMjYgMTM6NTY6MzggMjAxNSArMDAwMAoKCSAgICBmYmNvbjog dXNlIHRoZSBjdXJzb3IgYmxpbmsgaW50ZXJ2YWwgcHJvdmlkZWQgYnkgdnQKICAgIAoJICAgIHZ0 IG5vdyBwcm92aWRlcyBhIGN1cnNvciBibGluayBpbnRlcnZhbCB2aWEgdmNfZGF0YS4gVXNlIHRo aXMKCSAgICBpbnRlcnZhbCBpbnN0ZWFkIG9mIHRoZSBjdXJyZW50bHkgaGFyZGNvZGVkIDIwMCBt c2Vjcy4gU3RvcmUgaXQgaW4KCSAgICBmYmNvbl9vcHMgdG8gYXZvaWQgbG9ja2luZyB0aGUgY29u c29sZSBpbiBjdXJzb3JfdGltZXJfaGFuZGxlcigpLgogICAgCgkgICAgU2lnbmVkLW9mZi1ieTog U2NvdCBEb3lsZSA8bGttbDE0QHNjb3Rkb3lsZS5jb20+CgkgICAgQWNrZWQtYnk6IFBhdmVsIE1h Y2hlayA8cGF2ZWxAdWN3LmN6PgoJICAgIFNpZ25lZC1vZmYtYnk6IEdyZWcgS3JvYWgtSGFydG1h biA8Z3JlZ2toQGxpbnV4Zm91bmRhdGlvbi5vcmc+CgphbmQKCgljb21taXQgYmQ2MzM2NGNhYThk ZjM4YmFkMmIyNWIxMWIyYTFiODQ5NDc1Y2NlNQoJQXV0aG9yOiBTY290IERveWxlIDxsa21sMTRA c2NvdGRveWxlLmNvbT4KCURhdGU6ICAgVGh1IE1hciAyNiAxMzo1NDozOSAyMDE1ICswMDAwCgoJ ICAgIHZ0OiBhZGQgY3Vyc29yIGJsaW5rIGludGVydmFsIGVzY2FwZSBzZXF1ZW5jZQogICAgCgkg ICAgQWRkIGFuIGVzY2FwZSBzZXF1ZW5jZSB0byBzcGVjaWZ5IHRoZSBjdXJyZW50IGNvbnNvbGUn cyBjdXJzb3IgYmxpbmsKCSAgICBpbnRlcnZhbC4gVGhlIGludGVydmFsIGlzIHNwZWNpZmllZCBh cyBhIG51bWJlciBvZiBtaWxsaXNlY29uZHMgdW50aWwKCSAgICB0aGUgbmV4dCBjdXJzb3IgZGlz cGxheSBzdGF0ZSB0b2dnbGUsIGZyb20gNTAgdG8gNjU1MzUuIC9wcm9jL2xvYWRhdmcKCSAgICBk aWQgbm90IHNob3cgYSBkaWZmZXJlbmNlIHdpdGggYSBvbmUgbXNlYyBpbnRlcnZhbCwgYnV0IHRo ZSBsb3dlcgoJICAgIGJvdW5kIGlzIHNldCB0byA1MCBtc2VjcyBzaW5jZSBzbG93ZXIgaGFyZHdh cmUgd2Fzbid0IHRlc3RlZC4KICAgIAoJICAgIFN0b3JlIHRoZSBpbnRlcnZhbCBpbiB0aGUgdmNf ZGF0YSBzdHJ1Y3R1cmUgZm9yIGxhdGVyIGFjY2VzcyBieSBmYmNvbiwKCSAgICBpbml0aWFsaXpp bmcgdGhlIHZhbHVlIHRvIGZiY29uJ3MgY3VycmVudCBoYXJkY29kZWQgdmFsdWUgb2YgMjAwIG1z ZWNzLgogICAgCgkgICAgU2lnbmVkLW9mZi1ieTogU2NvdCBEb3lsZSA8bGttbDE0QHNjb3Rkb3ls ZS5jb20+CgkgICAgQWNrZWQtYnk6IFBhdmVsIE1hY2hlayA8cGF2ZWxAdWN3LmN6PgoJICAgIFNp Z25lZC1vZmYtYnk6IEdyZWcgS3JvYWgtSGFydG1hbiA8Z3JlZ2toQGxpbnV4Zm91bmRhdGlvbi5v cmc+CgoKCj4gTG9va3MgaXQgaXMgYSByZWFsIGZiY29uL3Z0IGlzc3VlLCBzZWUgZm9sbG93aW5n Ogo+IAo+IGZiY29uX2luaXQoKQo+ICAgICA8LS5jb25faW5pdAo+ICAgICAgICAgICA8LXZpc3Vh bF9pbml0KCkKPiAKPiByZXNldF90ZXJtaW5hbCgpCj4gICAgIDwtdmNfaW5pdCgpCj4gCj4gdmMt PnZjX2N1cl9ibGlua19tcyBpcyBqdXN0IHNldCBpbiByZXNldF90ZXJtaW5hbCgpIGZyb20gdmNf aW5pdCgpIHBhdGgsCj4gYW5kIG9wcy0+Y3VyX2JsaW5rX2ppZmZpZXMgaXMgZmlndXJlZCBvdXQg ZnJvbSB2Yy0+dmNfY3VyX2JsaW5rX21zCj4gaW4gZmJjb25faW5pdCgpLgo+IAo+IEFuZCB2aXN1 YWxfaW5pdCgpIGlzIGFsd2F5cyBydW4gYmVmb3JlIHZjX2luaXQoKSwgc28gb3BzLT5jdXJfYmxp bmtfamlmZmllcwo+IGlzIGluaXRpYWxpemVkIGFzIHplcm8gYW5kIGNhdXNlIHRoZSBzb2Z0IGxv Y2t1cCBpc3N1ZSBmaW5hbGx5Lgo+IAo+IFRoYW5rcywKPiBNaW5nCj4gCj4+Cj4+IHBlcmYgc2hv d3MgdGhhdCB0aGUgQ1BVIGNhdWdodCBieSB0aGUgTk1JIGlzIHR5cGljYWxseSBpbiBjb2RlCj4+ IHVwZGF0aW5nIHRoZSBjdXJzb3IgdGltZXI6Cj4+Cj4+IC0gICAxNi45MiUgIHN3YXBwZXIgIFtr ZXJuZWwua2FsbHN5bXNdICAgICAgW2tdIF9yYXdfc3Bpbl91bmxvY2tfaXJxcmVzdG9yZQo+PiAg ICAtIF9yYXdfc3Bpbl91bmxvY2tfaXJxcmVzdG9yZQo+PiAgICAgICArIDE2Ljg3JSBtb2RfdGlt ZXIKPj4gICAgICAgKyAwLjA1JSBjdXJzb3JfdGltZXJfaGFuZGxlcgo+PiAtICAgMTIuMTUlICBz d2FwcGVyICBba2VybmVsLmthbGxzeW1zXSAgICAgIFtrXSBxdWV1ZV93b3JrX29uCj4+ICAgIC0g cXVldWVfd29ya19vbgo+PiAgICAgICArIDEyLjAwJSBjdXJzb3JfdGltZXJfaGFuZGxlcgo+PiAg ICAgICArIDAuMTUlIGNhbGxfdGltZXJfZm4KPj4gKyAgIDEwLjk4JSAgc3dhcHBlciAgW2tlcm5l bC5rYWxsc3ltc10gICAgICBba10gcnVuX3RpbWVyX3NvZnRpcnEKPj4gLSAgICAyLjIzJSAgc3dh cHBlciAgW2tlcm5lbC5rYWxsc3ltc10gICAgICBba10gbW9kX3RpbWVyCj4+ICAgIC0gbW9kX3Rp bWVyCj4+ICAgICAgICsgMS45NyUgY3Vyc29yX3RpbWVyX2hhbmRsZXIKPj4gICAgICAgKyAwLjI2 JSBjYWxsX3RpbWVyX2ZuCj4+Cj4+IER1cmluZyB0aGUgc2FtZSBwZXJpb2QsIEkgY2FuIHNlZSB0 aGF0IGFub3RoZXIgQ1BVIGlzIGFjdGl2ZWx5Cj4+IGV4ZWN1dGluZyB0aGUgdGltZXIgZnVuY3Rp b246Cj4+Cj4+IC0gICA0Mi4xOCUgIGt3b3JrZXIvdTk2OjIgIFtrZXJuZWwua2FsbHN5bXNdICBb a10gd3dfbXV0ZXhfdW5sb2NrCj4+ICAgIC0gd3dfbXV0ZXhfdW5sb2NrCj4+ICAgICAgIC0gNDAu NzAlIGFzdF9kaXJ0eV91cGRhdGUKPj4gICAgICAgICAgICBhc3RfaW1hZ2VibGl0Cj4+ICAgICAg ICAgICAgc29mdF9jdXJzb3IKPj4gICAgICAgICAgICBiaXRfY3Vyc29yCj4+ICAgICAgICAgICAg ZmJfZmxhc2hjdXJzb3IKPj4gICAgICAgICAgICBwcm9jZXNzX29uZV93b3JrCj4+ICAgICAgICAg ICAgd29ya2VyX3RocmVhZAo+PiAgICAgICAgICAgIGt0aHJlYWQKPj4gICAgICAgICAgICByZXRf ZnJvbV9mb3JrCj4+ICAgICAgICsgMS40OCUgYXN0X2ltYWdlYmxpdAo+PiAtICAgNDAuMTUlICBr d29ya2VyL3U5NjoyICBba2VybmVsLmthbGxzeW1zXSAgW2tdIF9fbWVtY3B5X3RvaW8KPj4gICAg LSBfX21lbWNweV90b2lvCj4+ICAgICAgICsgMzEuNTQlIGFzdF9kaXJ0eV91cGRhdGUKPj4gICAg ICAgKyA4LjYxJSBhc3RfaW1hZ2VibGl0Cj4+Cj4+IFVzaW5nIHRoZSBncmFwaCBmdW5jdGlvbiB0 cmFjZXIgb24gZmJfZmxhc2hjdXJzb3IoKSwgSSBzZWUgdGhhdAo+PiBhc3RfZGlydHlfdXBkYXRl IHVzdWFsbHkgdGFrZXMgYXJvdW5kIDYwIHVzLCBpbiB3aGljaCBpdCBtYWtlcyAxNgo+PiBjYWxs cyB0byBfX21lbWNweV90b2lvKCkuIEhvd2V2ZXIsIHRoZXJlIGlzIGFsd2F5cyBvbmUgaW5zdGFu Y2Ugb24KPj4gZXZlcnkgYm9vdCBvZiB0aGUgaW5zdGFsbGVyIHdoZXJlIGFzdF9kaXJ0eV91cGRh dGUoKSB0YWtlcyB+OTggKm1zKiB0bwo+PiBjb21wbGV0ZSwgZHVyaW5nIHdoaWNoIGl0IG1ha2Vz IDc0MyBjYWxscyB0byBfX21lbWNweV90b2lvKCkuIFdoaWxlCj4+IHRoYXQgIGRvZXNuJ3QgZGly ZWN0bHkgYWNjb3VudCBmb3IgdGhlIGZ1bGwgMjJzLCBJIGRvIHdvbmRlciBpZiB0aGF0Cj4+IG1h eWJlIGEgc21va2luZyBndW4uCj4+Cj4+IGZ5aSwgdGhpcyBpcyBiZWluZyB0cmFja2VkIGF0OiBo dHRwczovL2J1Z3MubGF1bmNocGFkLm5ldC9idWdzLzE1NzQ4MTQKPj4KPj4gICAtZGFubgoKX19f X19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX18KZHJpLWRldmVsIG1h aWxpbmcgbGlzdApkcmktZGV2ZWxAbGlzdHMuZnJlZWRlc2t0b3Aub3JnCmh0dHBzOi8vbGlzdHMu ZnJlZWRlc2t0b3Aub3JnL21haWxtYW4vbGlzdGluZm8vZHJpLWRldmVsCg== From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S932209AbcEQO3L (ORCPT ); Tue, 17 May 2016 10:29:11 -0400 Received: from mail-pa0-f52.google.com ([209.85.220.52]:34008 "EHLO mail-pa0-f52.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750758AbcEQO3I (ORCPT ); Tue, 17 May 2016 10:29:08 -0400 Subject: Re: ast: cursor flashing softlockups To: Ming Lei , Dann Frazier , Scot Doyle References: Cc: David Airlie , dri-devel@lists.freedesktop.org, "Chintakuntla, Radha" , Greg Kroah-Hartman , Jiri Slaby , Pavel Machek , Linux Kernel Mailing List From: Peter Hurley Message-ID: <573B2AB0.7070004@hurleysoftware.com> Date: Tue, 17 May 2016 07:29:04 -0700 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:38.0) Gecko/20100101 Thunderbird/38.7.2 MIME-Version: 1.0 In-Reply-To: Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org [ +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 > 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 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 Acked-by: Pavel Machek Signed-off-by: Greg Kroah-Hartman and commit bd63364caa8df38bad2b25b11b2a1b849475cce5 Author: Scot Doyle 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 Acked-by: Pavel Machek Signed-off-by: Greg Kroah-Hartman > 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