Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1340807 > unrolled thread
| Started by | Sergey Senozhatsky <sergey.senozhatsky@gmail.com> |
|---|---|
| First post | 2016-02-23 17:00 +0100 |
| Last post | 2016-03-02 11:50 +0100 |
| Articles | 8 — 3 participants |
Back to article view | Back to linux.kernel
This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by
below is the oldest one visible, not the original post.
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
| From | Sergey Senozhatsky <sergey.senozhatsky@gmail.com> |
|---|---|
| Date | 2016-02-23 17:00 +0100 |
| Subject | Re: [lkp] [printk] 34578dc67f: EIP is at vprintk_emit+0x1ea/0x600 |
| Message-ID | <r5nxv-7tJ-1@gated-at.bofh.it> |
On (02/23/16 22:15), Sergey Senozhatsky wrote: > On (02/23/16 08:55), kernel test robot wrote: > > [ 33.497678] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6 > > [ 33.497693] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [swapper:1] > > [ 33.497693] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [swapper:1] > > [ 33.497695] Modules linked in: > > [ 33.497695] Modules linked in: > > [ 33.497696] irq event stamp: 69018756 > > [ 33.497696] irq event stamp: 69018756 > > how may consoles do you have registered? is it possible that your > call_console_drivers() loop push the same data to different consoles, > but the messages end up in one place (serial port, etc... dunno)? > does it happen to all of the messages? oh... didn't notice there was a dmesg.xz attached. ok, so everything is "doubled" in your dmesg, starting from "console [ttyS0] enabled" line 254 [ 0.000000] vmalloc : 0xc47e0000 - 0xff7fe000 ( 944 MB) 255 [ 0.000000] lowmem : 0xb0000000 - 0xc3fe0000 ( 319 MB) 256 [ 0.000000] .init : 0xc0dc4000 - 0xc0e3a000 ( 472 kB) 257 [ 0.000000] .data : 0xc0a0a040 - 0xc0dc2560 (3809 kB) 258 [ 0.000000] .text : 0xc0600000 - 0xc0a0a040 (4136 kB) 259 [ 0.000000] Checking if this processor honours the WP bit even in supervisor mode...Ok. 260 [ 0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1 261 [ 0.000000] Running RCU self tests 262 [ 0.000000] NR_IRQS:2304 nr_irqs:256 16 263 [ 0.000000] CPU 0 irqstacks, hard=b002a000 soft=b002c000 264 [ 0.000000] console [ttyS0] enabled 265 [ 0.000000] console [ttyS0] enabled 266 [ 0.000000] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar 267 [ 0.000000] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar 268 [ 0.000000] ... MAX_LOCKDEP_SUBCLASSES: 8 269 [ 0.000000] ... MAX_LOCKDEP_SUBCLASSES: 8 270 [ 0.000000] ... MAX_LOCK_DEPTH: 48 271 [ 0.000000] ... MAX_LOCK_DEPTH: 48 272 [ 0.000000] ... MAX_LOCKDEP_KEYS: 8191 273 [ 0.000000] ... MAX_LOCKDEP_KEYS: 8191 274 [ 0.000000] ... CLASSHASH_SIZE: 4096 275 [ 0.000000] ... CLASSHASH_SIZE: 4096 276 [ 0.000000] ... MAX_LOCKDEP_ENTRIES: 32768 277 [ 0.000000] ... MAX_LOCKDEP_ENTRIES: 32768 278 [ 0.000000] ... MAX_LOCKDEP_CHAINS: 65536 279 [ 0.000000] ... MAX_LOCKDEP_CHAINS: 65536 280 [ 0.000000] ... CHAINHASH_SIZE: 32768 281 [ 0.000000] ... CHAINHASH_SIZE: 32768 282 [ 0.000000] memory used by lock dependency info: 5167 kB 283 [ 0.000000] memory used by lock dependency info: 5167 kB 284 [ 0.000000] per task-struct memory footprint: 2112 bytes 285 [ 0.000000] per task-struct memory footprint: 2112 bytes 286 [ 0.000000] ------------------------ 287 [ 0.000000] ------------------------ 288 [ 0.000000] | Locking API testsuite: 289 [ 0.000000] | Locking API testsuite: 290 [ 0.000000] ---------------------------------------------------------------------------- 291 [ 0.000000] ---------------------------------------------------------------------------- 292 [ 0.000000] | spin |wlock |rlock |mutex | wsem | rsem | 293 [ 0.000000] | spin |wlock |rlock |mutex | wsem | rsem | 294 [ 0.000000] -------------------------------------------------------------------------- 295 [ 0.000000] -------------------------------------------------------------------------- looking at your Kernel command line [ 0.000000] Kernel command line: root=/dev/ram0 user=lkp job=/lkp/scheduled/vm-kbuild-yocto-i386-53/bisect_boot-1-yocto-minimal-i386.cgz-i386-randconfig-h1-02192137-34578dc67f38c02ccbe696e4099967884caa8e15-20160220-72722-vao2m5-0.yaml ARCH=i386 kconfig=i386-randconfig-h1-02192137 branch=linux-next/master commi t=34578dc67f38c02ccbe696e4099967884caa8e15 BOOT_IMAGE=/pkg/linux/i386-randconfig-h1-02192137/gcc-5/34578dc67f38c02ccbe696e4099967884caa8e15/vmlinuz-4.5.0-rc4-00295-g34578dc max_uptime=600 RESULT_ROOT=/result/boot/1/vm-kbuild-yocto-i386/yocto-minimal-i386.cgz/i386-randconfig-h1-02192137/gcc-5/34578dc67f38c02ccbe69 6e4099967884caa8e15/9 LKP_SERVER=inn earlyprintk=ttyS0,115200 systemd.log_level=err debug apic=debug sysrq_always_enabled rcupdate.rcu_cpu_stall_timeout=100 panic=-1 softlockup_panic=1 nmi_watchdog=panic oops=panic load_ramdisk=2 prompt_ramdisk=0 console=ttyS0,115200 console=tty0 vga=normal rw ip=::::vm-kbuild-yo cto-i386-53::dhcp drbd.minor_count=8 - earlyprintk=ttyS0,115200 - console=ttyS0,115200 - console=tty0 so you have two consoles: ttyS0 and tty0? and I see "bootconsole [earlyser0] enabled" but no "bootconsole [earlyser0] disabled" message, which I'd expect to see... So how may consoles do you have? 2 or 3? so call_console_drivers() has to ->write() every log line N times; at least to ttyS0->write() and to tty0->write()? -ss
[toc] | [next] | [standalone]
| From | Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> |
|---|---|
| Date | 2016-02-24 02:20 +0100 |
| Message-ID | <r5whr-5tS-11@gated-at.bofh.it> |
| In reply to | #1340807 |
Hello,
Cc Rob, Frank, Grant
On (02/24/16 00:53), Sergey Senozhatsky wrote:
[..]
> 284 [ 0.000000] per task-struct memory footprint: 2112 bytes
> 285 [ 0.000000] per task-struct memory footprint: 2112 bytes
> 286 [ 0.000000] ------------------------
> 287 [ 0.000000] ------------------------
> 288 [ 0.000000] | Locking API testsuite:
> 289 [ 0.000000] | Locking API testsuite:
> 290 [ 0.000000] ----------------------------------------------------------------------------
> 291 [ 0.000000] ----------------------------------------------------------------------------
> 292 [ 0.000000] | spin |wlock |rlock |mutex | wsem | rsem |
> 293 [ 0.000000] | spin |wlock |rlock |mutex | wsem | rsem |
> 294 [ 0.000000] --------------------------------------------------------------------------
> 295 [ 0.000000] --------------------------------------------------------------------------
>
>
> looking at your Kernel command line
>
> [ 0.000000] Kernel command line: root=/dev/ram0 user=lkp job=/lkp/scheduled/vm-kbuild-yocto-i386-53/bisect_boot-1-yocto-minimal-i386.cgz-i386-randconfig-h1-02192137-34578dc67f38c02ccbe696e4099967884caa8e15-20160220-72722-vao2m5-0.yaml ARCH=i386 kconfig=i386-randconfig-h1-02192137 branch=linux-next/master commi t=34578dc67f38c02ccbe696e4099967884caa8e15 BOOT_IMAGE=/pkg/linux/i386-randconfig-h1-02192137/gcc-5/34578dc67f38c02ccbe696e4099967884caa8e15/vmlinuz-4.5.0-rc4-00295-g34578dc max_uptime=600 RESULT_ROOT=/result/boot/1/vm-kbuild-yocto-i386/yocto-minimal-i386.cgz/i386-randconfig-h1-02192137/gcc-5/34578dc67f38c02ccbe69 6e4099967884caa8e15/9 LKP_SERVER=inn earlyprintk=ttyS0,115200 systemd.log_level=err debug apic=debug sysrq_always_enabled rcupdate.rcu_cpu_stall_timeout=100 panic=-1 softlockup_panic=1 nmi_watchdog=panic oops=panic load_ramdisk=2 prompt_ramdisk=0 console=ttyS0,115200 console=tty0 vga=normal rw ip=::::vm-kbuild-yo cto-i386-53::dhcp drbd.minor_count=8
>
>
> - earlyprintk=ttyS0,115200
> - console=ttyS0,115200
> - console=tty0
>
> and I see "bootconsole [earlyser0] enabled" but no "bootconsole [earlyser0] disabled" message, which
> I'd expect to see...
>
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:
** 16981217 printk messages dropped **
[ 33.495591] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
** 16981217 printk messages dropped **
[ 33.495591] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
[ 33.495593] of_overlay_destroy: Could not find overlay #6
[ 33.495593] of_overlay_destroy: Could not find overlay #6
** 16981217 printk messages dropped **
[ 33.497583] of_overlay_destroy: Could not find overlay #6
[ 33.497583] of_overlay_destroy: Could not find overlay #6
[ 33.497584] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
[ 33.497584] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
[ 33.497586] of_overlay_destroy: Could not find overlay #6
[ 33.497586] of_overlay_destroy: Could not find overlay #6
[ 33.497587] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
[ 33.497587] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
[ 33.497589] of_overlay_destroy: Could not find overlay #6
[ 33.497589] of_overlay_destroy: Could not find overlay #6
[ 33.497589] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
[ 33.497589] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
[ 33.497591] of_overlay_destroy: Could not find overlay #6
[ 33.497591] of_overlay_destroy: Could not find overlay #6
[ 33.497592] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
[ 33.497592] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
[ 33.497594] of_overlay_destroy: Could not find overlay #6
[ 33.497594] of_overlay_destroy: Could not find overlay #6
[ 33.497595] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
[ 33.497595] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
[ 33.497596] of_overlay_destroy: Could not find overlay #6
[ 33.497596] of_overlay_destroy: Could not find overlay #6
[ 33.497597] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
[ 33.497597] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
[ 33.497599] of_overlay_destroy: Could not find overlay #6
[ 33.497599] of_overlay_destroy: Could not find overlay #6
[ 33.497600] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
[ 33.497600] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
[ 33.497601] of_overlay_destroy: Could not find overlay #6
[ 33.497601] of_overlay_destroy: Could not find overlay #6
[ 33.497602] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
[ 33.497602] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
[ 33.497604] of_overlay_destroy: Could not find overlay #6
[ 33.497604] of_overlay_destroy: Could not find overlay #6
[ 33.497605] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
[ 33.497605] ### dt-test ### of_unittest_destroy_tracked_overlays: overlay destroy failed for #6
the source of "too many messages to printk" is this `while (1) loop'
static void of_unittest_destroy_tracked_overlays(void)
{
int id, ret, defers;
if (overlay_first_id < 0)
return;
/* try until no defers */
do {
defers = 0;
/* remove in reverse order */
for (id = MAX_UNITTEST_OVERLAYS - 1; id >= 0; id--) {
if (!(overlay_id_bits[BIT_WORD(id)] & BIT_MASK(id)))
continue;
ret = of_overlay_destroy(id + overlay_first_id);
if (ret != 0) {
defers++;
pr_warn("%s: overlay destroy failed for #%d\n",
__func__, id + overlay_first_id);
continue;
}
overlay_id_bits[BIT_WORD(id)] &= ~BIT_MASK(id);
}
} while (defers > 0);
}
I don't know what's the root cause of missing overlay id in idr,
but in this particular case the loop transform into /* well, "defers" should
overflow at some point, but I doubt we must count on it */
do {
ret = of_overlay_destroy()->idr_find()->pr_err("Could not find overlay"), return -ENODEV
if (ret != 0) {
pr_warn("overlay destroy failed for");
continue;
}
} while (1);
the "while (1) printk();" pattern is known to be dangerous; we need to
fix printk().
so something like this perhaps.
From: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Subject: [PATCH] fix endless loop
---
drivers/of/unittest.c | 6 ++++++
1 file changed, 6 insertions(+)
diff --git a/drivers/of/unittest.c b/drivers/of/unittest.c
index 979b6e4..5058017 100644
--- a/drivers/of/unittest.c
+++ b/drivers/of/unittest.c
@@ -1165,6 +1165,12 @@ static void of_unittest_destroy_tracked_overlays(void)
continue;
ret = of_overlay_destroy(id + overlay_first_id);
+ if (ret == -ENODEV) {
+ pr_warn("%s: no overlay to destroy for #%d\n",
+ __func__, id + overlay_first_id);
+ continue;
+ }
+
if (ret != 0) {
defers++;
pr_warn("%s: overlay destroy failed for #%d\n",
--
2.7.1
[toc] | [prev] | [next] | [standalone]
| From | Petr Mladek <pmladek@suse.com> |
|---|---|
| Date | 2016-02-24 12:50 +0100 |
| Message-ID | <r5G78-3Vy-5@gated-at.bofh.it> |
| In reply to | #1341220 |
On Wed 2016-02-24 10:19:41, Sergey Senozhatsky wrote: > > Hello, > > Cc Rob, Frank, Grant > > On (02/24/16 00:53), Sergey Senozhatsky wrote: > [..] > > 284 [ 0.000000] per task-struct memory footprint: 2112 bytes > > 285 [ 0.000000] per task-struct memory footprint: 2112 bytes > > 286 [ 0.000000] ------------------------ > > 287 [ 0.000000] ------------------------ > > 288 [ 0.000000] | Locking API testsuite: > > 289 [ 0.000000] | Locking API testsuite: > > 290 [ 0.000000] ---------------------------------------------------------------------------- > > 291 [ 0.000000] ---------------------------------------------------------------------------- > > 292 [ 0.000000] | spin |wlock |rlock |mutex | wsem | rsem | > > 293 [ 0.000000] | spin |wlock |rlock |mutex | wsem | rsem | > > 294 [ 0.000000] -------------------------------------------------------------------------- > > 295 [ 0.000000] -------------------------------------------------------------------------- > > > > > > looking at your Kernel command line > > > > [ 0.000000] Kernel command line: root=/dev/ram0 user=lkp job=/lkp/scheduled/vm-kbuild-yocto-i386-53/bisect_boot-1-yocto-minimal-i386.cgz-i386-randconfig-h1-02192137-34578dc67f38c02ccbe696e4099967884caa8e15-20160220-72722-vao2m5-0.yaml ARCH=i386 kconfig=i386-randconfig-h1-02192137 branch=linux-next/master commi t=34578dc67f38c02ccbe696e4099967884caa8e15 BOOT_IMAGE=/pkg/linux/i386-randconfig-h1-02192137/gcc-5/34578dc67f38c02ccbe696e4099967884caa8e15/vmlinuz-4.5.0-rc4-00295-g34578dc max_uptime=600 RESULT_ROOT=/result/boot/1/vm-kbuild-yocto-i386/yocto-minimal-i386.cgz/i386-randconfig-h1-02192137/gcc-5/34578dc67f38c02ccbe69 6e4099967884caa8e15/9 LKP_SERVER=inn earlyprintk=ttyS0,115200 systemd.log_level=err debug apic=debug sysrq_always_enabled rcupdate.rcu_cpu_stall_timeout=100 panic=-1 softlockup_panic=1 nmi_watchdog=panic oops=panic load_ramdisk=2 prompt_ramdisk=0 console=ttyS0,115200 console=tty0 vga=normal rw ip=::::vm-kbuild-yo cto-i386-53::dhcp drbd.minor_count=8 > > > > > > - earlyprintk=ttyS0,115200 > > - console=ttyS0,115200 > > - console=tty0 > > > > and I see "bootconsole [earlyser0] enabled" but no "bootconsole [earlyser0] disabled" message, which > > I'd expect to see... > > > > > 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. 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 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... Do I miss something, please? Best Regards, Petr
[toc] | [prev] | [next] | [standalone]
| From | Sergey Senozhatsky <sergey.senozhatsky@gmail.com> |
|---|---|
| Date | 2016-02-24 14:00 +0100 |
| Message-ID | <r5HcS-4EQ-3@gated-at.bofh.it> |
| In reply to | #1341922 |
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
[toc] | [prev] | [next] | [standalone]
| From | Sergey Senozhatsky <sergey.senozhatsky@gmail.com> |
|---|---|
| Date | 2016-02-24 16:20 +0100 |
| Message-ID | <r5Jon-6qY-43@gated-at.bofh.it> |
| In reply to | #1341947 |
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
[toc] | [prev] | [next] | [standalone]
| From | Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> |
|---|---|
| Date | 2016-02-25 06:10 +0100 |
| Message-ID | <r5Wlz-7l9-3@gated-at.bofh.it> |
| In reply to | #1342120 |
Hello,
On (02/25/16 00:12), Sergey Senozhatsky wrote:
[..]
> > > 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.
No behavioral change between linux-next and linux-next modulo printk patches was observed.
next-20160224
git revert 8a30bf8ff5e07a589ad43363b06ea361ad723a0e 2822460a0ea97656ae71b2b4ddac087f79c5876a b6751672d3ac1d3d876fd5ea7ec579956eee4d6b
set PREEMPT_NONE
CONFIG_PREEMPT_NONE=y
# CONFIG_PREEMPT_VOLUNTARY is not set
# CONFIG_PREEMPT is not set
CONFIG_PREEMPT_COUNT=y
add PANIC of softlockup and panic on hung_task
CONFIG_LOCKUP_DETECTOR=y
CONFIG_HARDLOCKUP_DETECTOR=y
CONFIG_BOOTPARAM_HARDLOCKUP_PANIC=y
CONFIG_BOOTPARAM_HARDLOCKUP_PANIC_VALUE=1
CONFIG_BOOTPARAM_SOFTLOCKUP_PANIC=y <<
CONFIG_BOOTPARAM_SOFTLOCKUP_PANIC_VALUE=1
CONFIG_DETECT_HUNG_TASK=y
CONFIG_DEFAULT_HUNG_TASK_TIMEOUT=11
CONFIG_BOOTPARAM_HUNG_TASK_PANIC=y <<
CONFIG_BOOTPARAM_HUNG_TASK_PANIC_VALUE=1
CONFIG_WQ_WATCHDOG=y
CONFIG_PANIC_ON_OOPS=y
CONFIG_PANIC_ON_OOPS_VALUE=1
CONFIG_PANIC_TIMEOUT=23
modify watchdog timeout (so it detects lockup sooner) and add
printk() flood -- the code does not even disable preemption,
just busy looping, we have PREEMPT_NONE kernel.
git diff
diff --git a/drivers/block/zram/zram_drv.c b/drivers/block/zram/zram_drv.c
index 46055db..8759dbb 100644
--- a/drivers/block/zram/zram_drv.c
+++ b/drivers/block/zram/zram_drv.c
@@ -1410,6 +1410,21 @@ static int __init zram_init(void)
{
int ret;
+ /*unsigned long flags;*/
+ u64 s, e;
+
+ /*preempt_disable();*/
+ s = local_clock() >> 31UL;
+ while (1) {
+ e = local_clock() >> 31UL;
+ if (e - s > 10)
+ goto out;
+ pr_err(">>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>\n");
+ }
+out:
+ /*preempt_enable();*/
+
+
ret = class_register(&zram_control_class);
if (ret) {
pr_err("Unable to register zram-control class\n");
diff --git a/kernel/watchdog.c b/kernel/watchdog.c
index b3ace6e..8655364 100644
--- a/kernel/watchdog.c
+++ b/kernel/watchdog.c
@@ -54,7 +54,7 @@ static unsigned long __read_mostly watchdog_enabled = SOFT_WATCHDOG_ENABLED;
int __read_mostly nmi_watchdog_enabled;
int __read_mostly soft_watchdog_enabled;
int __read_mostly watchdog_user_enabled;
-int __read_mostly watchdog_thresh = 10;
+int __read_mostly watchdog_thresh = 1;
#ifdef CONFIG_SMP
int __read_mostly sysctl_softlockup_all_cpu_backtrace;
---
The test (unpatched linux-next)
NMI watchdog: BUG: soft lockup - CPU#2 stuck for 3s! [modprobe:418]
Modules linked in: ...
irq event stamp: 40679
hardirqs last enabled at (40679): [<ffffffff8108b771>] vprintk_emit+0x3f0/0x499
hardirqs last disabled at (40678): [<ffffffff8108b3d4>] vprintk_emit+0x53/0x499
softirqs last enabled at (35360): [<ffffffff810475e9>] __do_softirq+0x2d8
softirqs last disabled at (35357): [<ffffffff810478ce>] irq_exit+0x41/0x95
CPU: 2 PID: 418 Comm: modprobe Tainted: G O 4.5.0-rc5-next-20160224-dbg-00012-gfedb791-dirty #187
Hardware name: ...
task: ffff88013290ce00 ti: ffff880131f98000 task.ti: ffff880131f98000
RIP: 0010:[<ffffffff8108b2d8>] [<ffffffff8108b2d8>] console_unlock+0x3ad/0x456
RSP: 0018:ffff880131f9bbc8 EFLAGS: 00000246
RAX: ffff88013290ce00 RBX: ffffffff82891fdc RCX: 00000000ffffffff
RDX: ffffffff812c99a8 RSI: 0000000000000001 RDI: ffffffff8108b2d5
RBP: ffff880131f9bc08 R08: 0000000000000000 R09: 0000000000000000
R10: 00000000ffff00ff R11: 000000000000042b R12: 0000000000000000
R13: 0000000000000246 R14: 0000000000000003 R15: 0000000000000001
S: 00007fe6ed4fd700(0000) GS:ffff880137d00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fe6eb905000 CR3: 00000000bb7fc000 CR4: 00000000000006e0
Stack:
0000000000000000 0000000000000029 000000000001a128 00000000ffffffff
0000000000000003 0000000000000028 ffffffff82877602 0000000000000028
ffff880131f9bc60 ffffffff8108b7cb 0000000000000000 0000000000000000
Call Trace:
[<ffffffff8108b7cb>] vprintk_emit+0x44a/0x499
[<ffffffffa01f0000>] ? 0xffffffffa01f0000
[<ffffffff8108b931>] vprintk_default+0x1d/0x1f
[<ffffffff810f1b21>] printk+0x48/0x50
[<ffffffffa01f0032>] zram_init+0x32/0x1000 [zram]
[<ffffffff81000402>] do_one_initcall+0xe7/0x16
[<ffffffff810f1d5f>] ? do_init_module+0x27/0x1d9
[<ffffffff81093619>] ? rcu_read_lock_sched_held+0x61/0x69
[<ffffffff811330fa>] ? kmem_cache_alloc_trace+0x138/0x1d0
[<ffffffff810f1d5f>] ? do_init_module+0x27/0x1d9
[<ffffffff810f1d97>] do_init_module+0x5f/0x1d9
[<ffffffff810b2b2c>] load_module+0x19da/0x1eb8
[<ffffffff810830c4>] ? lock_acquire+0x10f/0x1a3
[<ffffffff810b3109>] SyS_init_module+0xff/0x125
[<ffffffff810b3109>] ? SyS_init_module+0xff/0x125
[<ffffffff8150e525>] entry_SYSCALL_64_fastpath+0x18/0xa8
Code: 89 05 11 cc 80 01 4c 89 35 0e cc 80 01 88 d0 83 e2 fe 83 e0 1e 88 53 0f 0f b6 c0 89 05 f2 cb 80 01 eb 9e e8 9e 5a ff ff 41 55 9d <e9> ed fe ff ff 48 83 3d 3b cd 80 01 00 c7 05 3d cd 80 01 00 00
Kernel panic - not syncing: softlockup: hung tasks
CPU: 2 PID: 418 Comm: modprobe Tainted: G O L 4.5.0-rc5-next-20160224-dbg-00012-gfedb791-dirty #187
Hardware name: ...
0000000000000000 ffff880137d03d68 ffffffff8123334d ffffffff817ad7c7
ffff880137d03df8 ffff880137d03de8 ffffffff810f124e ffffffff00000008
ffff880137d03df8 ffff880137d03d90 0000000000000000 00000000ffffffff
Call Trace:
<IRQ> [<ffffffff8123334d>] dump_stack+0x67/0x90
[<ffffffff810f124e>] panic+0xd1/0x212
[<ffffffff8107d1c1>] ? down_trylock+0x2d/0x37
[<ffffffff810c12c5>] watchdog_timer_fn+0x18e/0x1b0
[<ffffffff8109cee9>] __hrtimer_run_queues+0x1ee/0x418
[<ffffffff810c1137>] ? __touch_watchdog+0x1c/0x1c
[<ffffffff8109d2af>] hrtimer_interrupt+0xa8/0x192
[<ffffffff810354cd>] hpet_interrupt_handler+0x2a/0x31
[<ffffffff8108ccd8>] handle_irq_event_percpu+0xd2/0x2e4
[<ffffffff8108cf22>] handle_irq_event+0x38/0x56
[<ffffffff8108fc63>] handle_edge_irq+0xd9/0xfb
[<ffffffff810174ad>] handle_irq+0x1c/0x20
[<ffffffff81510795>] do_IRQ+0x85/0x1
[<ffffffff8150ee86>] common_interrupt+0x86/0x86
<EOI> [<ffffffff812c99a8>] ? vt_console_print+0x2f9/0x308
[<ffffffff8108b2d5>] ? console_unlock+0x3aa/0x456
[<ffffffff8108b2d8>] ? console_unlock+0x3ad/0x456
[<ffffffff8108b7cb>] vprintk_emit+0x44a/0x499
[<ffffffffa01f0000>] ? 0xffffffffa01f0000
[<ffffffff8108b931>] vprintk_default+0x1d/0x1f
[<ffffffff810f1b21>] printk+0x48/0x50
[<ffffffffa01f0032>] zram_init+0x32/0x1000 [zram]
[<ffffffff81000402>] do_one_initcall+0xe7/0x16c
[<ffffffff810f1d5f>] ? do_init_module+0x27/0x1d9
[<ffffffff81093619>] ? rcu_read_lock_sched_held+0x61/0x69
[<ffffffff811330fa>] ? kmem_cache_alloc_trace+0x138/0x1d0
[<ffffffff810f1d5f>] ? do_init_module+0x27/0x1d9
[<ffffffff810f1d97>] do_init_module+0x5f/0x1d9
[<ffffffff810b2b2c>] load_module+0x19da/0x1eb8
[<ffffffff810830c4>] ? lock_acquire+0x10f/0x1a3
[<ffffffff810b3109>] SyS_init_module+0xff/0x125
[<ffffffff810b3109>] ? SyS_init_module+0xff/0x125
[<ffffffff8150e525>] entry_SYSCALL_64_fastpath+0x18/0xa8
so in this test printk()->console_unlock() was performed on the same CPU.
but in general those can be different CPUs. one busy spinning doing printk(),
the other busy spinning doing console_unlock()->call_console_drivers().
-ss
[toc] | [prev] | [next] | [standalone]
| From | Petr Mladek <pmladek@suse.com> |
|---|---|
| Date | 2016-03-02 11:40 +0100 |
| Message-ID | <r8cme-6mR-11@gated-at.bofh.it> |
| In reply to | #1342800 |
On Thu 2016-02-25 14:10:05, Sergey Senozhatsky wrote: > CONFIG_PREEMPT_NONE=y > # CONFIG_PREEMPT_VOLUNTARY is not set > # CONFIG_PREEMPT is not set > CONFIG_PREEMPT_COUNT=y I was curious why your patch actually did not help to avoid the softlockup. The infinite printk loop was called in a safe context, CONFIG_PREEMPT_COUNT=y, so it did set console_may_schedule = 1. But it never got console_sem, never called console_unlock() and never called cond_resched() there. So, it never got preempted in the PREEMPT_NONE kernel. The console_sem was owned by another process that was busy handling the flood of messages. Note that the infinite cycle calling printk() might be interrupted anywhere by the NMI watchdog. It explains why the original report pointed at the beginning of the printk. It was not a deadlock. I got the softlockup on random locations here. Also it is not the classic softlockup in console_unlock(). The process handling the console actually could sleep if it has console_may_schedule = 1. This is why console_unlock() did not appeared in the softlockup backtrace. Conclusion: Sergey is correct and his patches are innocent here. Sergey, if you send the fix for of_unittest_destroy_tracked_overlays(), please add me into CC. Best Regards, Petr PS: I am sorry for the noise and that it took me so long to shake my head around this problem. Thanks a lot for patience.
[toc] | [prev] | [next] | [standalone]
| From | Sergey Senozhatsky <sergey.senozhatsky@gmail.com> |
|---|---|
| Date | 2016-03-02 11:50 +0100 |
| Message-ID | <r8cvU-6qw-21@gated-at.bofh.it> |
| In reply to | #1347939 |
On (03/02/16 11:30), Petr Mladek wrote: > On Thu 2016-02-25 14:10:05, Sergey Senozhatsky wrote: > > CONFIG_PREEMPT_NONE=y > > # CONFIG_PREEMPT_VOLUNTARY is not set > > # CONFIG_PREEMPT is not set > > CONFIG_PREEMPT_COUNT=y > > I was curious why your patch actually did not help to avoid the > softlockup. The infinite printk loop was called in a safe context, > CONFIG_PREEMPT_COUNT=y, so it did set console_may_schedule = 1. > > But it never got console_sem, never called console_unlock() > and never called cond_resched() there. So, it never got preempted > in the PREEMPT_NONE kernel. The console_sem was owned by > another process that was busy handling the flood of messages. > > Note that the infinite cycle calling printk() might be interrupted anywhere > by the NMI watchdog. It explains why the original report pointed > at the beginning of the printk. It was not a deadlock. > I got the softlockup on random locations here. > > Also it is not the classic softlockup in console_unlock(). > The process handling the console actually could sleep if it > has console_may_schedule = 1. This is why console_unlock() > did not appeared in the softlockup backtrace. > > > Conclusion: > > Sergey is correct and his patches are innocent here. thank you, Petr! > Sergey, if you send the fix for > of_unittest_destroy_tracked_overlays(), please add me into CC. of course, will try to send it out tonight. > PS: I am sorry for the noise and that it took me so long to shake my > head around this problem. Thanks a lot for patience. no problem at all. thank you. the more we double check it - the better. -ss
[toc] | [prev] | [standalone]
Back to top | Article view | linux.kernel
csiph-web