Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]


Groups > linux.kernel > #1341947

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 14:00 +0100
Message-ID <r5HcS-4EQ-3@gated-at.bofh.it> (permalink)
References <r59uy-5YU-13@gated-at.bofh.it> <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>
Organization linux.* mail to news gateway

Show all headers | View raw


Hello,

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.

watchdog has two different parts: hrtimer part (via IRQ) checks the
touch_ts and wakeups the updater smpboot kthread; and updater kthread,
that updates touch_ts. to get a lockup you can just keep the preemption
disabled for 20+ seconds, so updater kthread will not update touch_ts.
the next hrtimer irq will detect lockup. and the .config we have is

CONFIG_PREEMPT_NONE=y
# CONFIG_PREEMPT_VOLUNTARY is not set
# CONFIG_PREEMPT is not set

that can add up to the issue.

(well, at least watchdog was working this way the last time I saw it).


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

sure. I did additional intensive tests today, and saw no issues.
schematically, something like this:

	u64 start = local_lock() >> 31UL:

	{ preempt_disable(), local_irq_save() }
	while (1) {
		u64 now = local_clock() >> 31UL;
		if (now - start > TIMEOUT)
			goto out;
		pr_err(">>>>>\n");
	}
out:
	{ preempt_enable(), local_irq_restore() }


> I guess that the softlookup was not visible before the
> printk patch was applied. I wonder if the patch made something
> worse. It was supposed to improve things but...

I think the softlockup under the given conditions (endless printk and
no preemption) will show up regardless the patches being applied; but
I see you point, of course.

	-ss

Back to linux.kernel | Previous | NextPrevious in thread | Next in thread | Find similar | Unroll thread


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