Re: [lkp] [printk] 34578dc67f: EIP is at vprintk_emit+0x1ea/0x600

From	Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Newsgroups	linux.kernel
Subject	Re: [lkp] [printk] 34578dc67f: EIP is at vprintk_emit+0x1ea/0x600
Date	2016-02-24 16:20 +0100
Message-ID	<r5Jon-6qY-43@gated-at.bofh.it> (permalink)
References	(1 earlier) <r5nxv-7tJ-3@gated-at.bofh.it> <r5nxv-7tJ-1@gated-at.bofh.it> <r5whr-5tS-11@gated-at.bofh.it> <r5G78-3Vy-5@gated-at.bofh.it> <r5HcS-4EQ-3@gated-at.bofh.it>
Organization	linux.* mail to news gateway

Show all headers | View raw

On (02/24/16 21:50), Sergey Senozhatsky wrote:
> On (02/24/16 12:46), Petr Mladek wrote:
> [..]
> > > and you get the NMI watchdog softlockup because you have a whole bunch of
> > > 
> > >    "of_overlay_destroy: Could not find overlay #6"
> > >    "### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6"
> > > 
> > > messages to print. seems that somehitng just pushes them in a loop.
> > > there are too many of them:
> > 
> > This sounds like a reasonable explanation. It seems that
> > of_unittest_destroy_tracked_overlays() really ended in an infinite
> > loop.
> > 
> > But I am still curious why the softlookup points to
> > 
> > [   33.497718] EIP is at vprintk_emit+0x1ea/0x600
> > 
> > Also there is on the stack
> > 
> > [   33.497741]  [<c068e712>] vprintk_default+0x32/0x40
> > [   33.497741]  [<c068e712>] vprintk_default+0x32/0x40
> > [   33.497744]  [<c06fdf6e>] printk+0x11/0x13
> > [   33.497744]  [<c06fdf6e>] printk+0x11/0x13
> > [   33.497748]  [<c0df5eec>] of_unittest_overlay+0x8d1/0x900
> > [   33.497748]  [<c0df5eec>] of_unittest_overlay+0x8d1/0x900
> > [   33.497750]  [<c0df6b1f>] of_unittest+0xc04/0xc2d
> > [   33.497750]  [<c0df6b1f>] of_unittest+0xc04/0xc2d
> > 
> > I would expect that the soft lookup happens in console_unlock()
> > called with IRQs disabled. It seems to me that of_unittest_overlay()
> > is called with IRQs enabled.

hm... both of the logbuf_lock/irq reqions in vprintk_emit/console_unlock
are not modified by the patch set. there is, however, one thing that has
changed -- additional console_cont_flush() calls, which does spin_lock_irq
logbuf_lock and spin_unlock_irq logbuf_lock.

> > I want to be sure that the patch in printk() did not introduce
> > a deadlock that is visible only under a high printk load.

I'll do more tests, certainly.

	-ss

Thread

Re: [lkp] [printk] 34578dc67f: EIP is at vprintk_emit+0x1ea/0x600 Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-02-23 17:00 +0100
  Re: [lkp] [printk] 34578dc67f: EIP is at vprintk_emit+0x1ea/0x600 Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-02-24 02:20 +0100
    Re: [lkp] [printk] 34578dc67f: EIP is at vprintk_emit+0x1ea/0x600 Petr Mladek <pmladek@suse.com> - 2016-02-24 12:50 +0100
      Re: [lkp] [printk] 34578dc67f: EIP is at vprintk_emit+0x1ea/0x600 Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-02-24 14:00 +0100
        Re: [lkp] [printk] 34578dc67f: EIP is at vprintk_emit+0x1ea/0x600 Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-02-24 16:20 +0100
          Re: [lkp] [printk] 34578dc67f: EIP is at vprintk_emit+0x1ea/0x600 Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-02-25 06:10 +0100
            Re: [lkp] [printk] 34578dc67f: EIP is at vprintk_emit+0x1ea/0x600 Petr Mladek <pmladek@suse.com> - 2016-03-02 11:40 +0100
              Re: [lkp] [printk] 34578dc67f: EIP is at vprintk_emit+0x1ea/0x600 Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-03-02 11:50 +0100

csiph-web