| 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: <20171031171622.GA28688@roeck-us.net>
Date: Tue, 31 Oct 2017 10:16:22 -0700
From: Guenter Roeck <linux@...ck-us.net>
To: Peter Zijlstra <peterz@...radead.org>
Cc: Thomas Gleixner <tglx@...utronix.de>, linux-kernel@...r.kernel.org,
Don Zickus <dzickus@...hat.com>, Ingo Molnar <mingo@...nel.org>
Subject: Re: Crashes in perf_event_ctx_lock_nested
On Tue, Oct 31, 2017 at 02:48:50PM +0100, Peter Zijlstra wrote:
> On Mon, Oct 30, 2017 at 03:45:12PM -0700, Guenter Roeck wrote:
> > I added some logging and a long msleep() in hardlockup_detector_perf_cleanup().
> > Here is the result:
> >
> > [ 0.274361] NMI watchdog: ############ hardlockup_detector_perf_init
> > [ 0.274915] NMI watchdog: ############ hardlockup_detector_event_create(0)
> > [ 0.277049] NMI watchdog: ############ hardlockup_detector_perf_cleanup
> > [ 0.277593] NMI watchdog: ############ hardlockup_detector_perf_enable(0)
> > [ 0.278027] NMI watchdog: ############ hardlockup_detector_event_create(0)
> > [ 1.312044] NMI watchdog: ############ hardlockup_detector_perf_cleanup done
> > [ 1.385122] NMI watchdog: ############ hardlockup_detector_perf_enable(1)
> > [ 1.386028] NMI watchdog: ############ hardlockup_detector_event_create(1)
> > [ 1.466102] NMI watchdog: ############ hardlockup_detector_perf_enable(2)
> > [ 1.475536] NMI watchdog: ############ hardlockup_detector_event_create(2)
> > [ 1.535099] NMI watchdog: ############ hardlockup_detector_perf_enable(3)
> > [ 1.535101] NMI watchdog: ############ hardlockup_detector_event_create(3)
>
> > [ 7.222816] NMI watchdog: ############ hardlockup_detector_perf_disable(0)
> > [ 7.230567] NMI watchdog: ############ hardlockup_detector_perf_disable(1)
> > [ 7.243138] NMI watchdog: ############ hardlockup_detector_perf_disable(2)
> > [ 7.250966] NMI watchdog: ############ hardlockup_detector_perf_disable(3)
> > [ 7.258826] NMI watchdog: ############ hardlockup_detector_perf_enable(1)
> > [ 7.258827] NMI watchdog: ############ hardlockup_detector_perf_cleanup
> > [ 7.258831] NMI watchdog: ############ hardlockup_detector_perf_enable(2)
> > [ 7.258833] NMI watchdog: ############ hardlockup_detector_perf_enable(0)
> > [ 7.258834] NMI watchdog: ############ hardlockup_detector_event_create(2)
> > [ 7.258835] NMI watchdog: ############ hardlockup_detector_event_create(0)
> > [ 7.260169] NMI watchdog: ############ hardlockup_detector_perf_enable(3)
> > [ 7.260170] NMI watchdog: ############ hardlockup_detector_event_create(3)
> > [ 7.494251] NMI watchdog: ############ hardlockup_detector_event_create(1)
> > [ 8.287135] NMI watchdog: ############ hardlockup_detector_perf_cleanup done
> >
> > Looks like there are a number of problems: hardlockup_detector_event_create()
> > creates the event data structure even if it is already created,
>
> Right, that does look dodgy. And on its own should be fairly straight
> forward to cure. But I'd like to understand the rest of it first.
>
> > and hardlockup_detector_perf_cleanup() runs unprotected and in
> > parallel to the enable/create functions.
>
> Well, looking at the code, cpu_maps_update_begin() aka.
> cpu_add_remove_lock is serializing cpu_up() and cpu_down() and _should_
> thereby also serialize cleanup vs the smp_hotplug_thread operations.
>
> Your trace does indeed indicate this is not the case, but I cannot, from
> the code, see how this could happen.
>
> Could you use trace_printk() instead and boot with
> "trace_options=stacktrace" ?
>
Attached. Let me know if you need more information. Note this is with
msleep(1000) in the cleanup function to avoid the crash.
> > ALso, the following message is seen twice.
> >
> > [ 0.278758] NMI watchdog: Enabled. Permanently consumes one hw-PMU counter.
> > [ 7.258838] NMI watchdog: Enabled. Permanently consumes one hw-PMU counter.
> >
> > I don't offer a proposed patch since I have no idea how to best solve the
> > problem.
> >
> > Also, is the repeated enable/disable/cleanup as part of the normal boot
> > really necessary ?
>
> That's weird, I don't see that on my machines. We very much only bring
> up the CPUs _once_. Also note they're 7s apart. Did you do something
> funny like resume-from-disk or so?
No, just whatever Chrome OS does when it starts the kernel. The hardware
used in this test is a Google Pixelbook, though we have also seen the problem
with other Chromebooks.
Guenter
---
# tracer: nop
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
swapper/0-1 [000] .... 0.350933: hardlockup_detector_perf_init: ############ hardlockup_detector_perf_init
swapper/0-1 [000] .... 0.350938: <stack trace>
=> kernel_init_freeable
=> kernel_init
=> ret_from_fork
swapper/0-1 [000] .... 0.350942: hardlockup_detector_event_create: ############ hardlockup_detector_event_create(0)
swapper/0-1 [000] .... 0.350946: <stack trace>
=> kernel_init_freeable
=> kernel_init
=> ret_from_fork
swapper/0-1 [000] .... 0.352637: hardlockup_detector_perf_cleanup: ############ hardlockup_detector_perf_cleanup
swapper/0-1 [000] .... 0.352641: <stack trace>
=> kernel_init_freeable
=> kernel_init
=> ret_from_fork
watchdog/0-12 [000] .... 0.352649: hardlockup_detector_perf_enable: ############ hardlockup_detector_perf_enable(0)
watchdog/0-12 [000] .... 0.352653: <stack trace>
=> kthread
=> ret_from_fork
watchdog/0-12 [000] .... 0.352655: hardlockup_detector_event_create: ############ hardlockup_detector_event_create(0)
watchdog/0-12 [000] .... 0.352658: <stack trace>
=> smpboot_thread_fn
=> kthread
=> ret_from_fork
swapper/0-1 [000] .... 1.394555: hardlockup_detector_perf_cleanup: ############ hardlockup_detector_perf_cleanup done
swapper/0-1 [000] .... 1.394559: <stack trace>
=> kernel_init_freeable
=> kernel_init
=> ret_from_fork
watchdog/1-15 [001] .... 1.534624: hardlockup_detector_perf_enable: ############ hardlockup_detector_perf_enable(1)
watchdog/1-15 [001] .... 1.534636: <stack trace>
=> kthread
=> ret_from_fork
watchdog/1-15 [001] .... 1.534640: hardlockup_detector_event_create: ############ hardlockup_detector_event_create(1)
watchdog/1-15 [001] .... 1.534646: <stack trace>
=> smpboot_thread_fn
=> kthread
=> ret_from_fork
watchdog/2-21 [002] .... 1.637496: hardlockup_detector_perf_enable: ############ hardlockup_detector_perf_enable(2)
watchdog/2-21 [002] .... 1.637505: <stack trace>
=> kthread
=> ret_from_fork
watchdog/2-21 [002] .... 1.637507: hardlockup_detector_event_create: ############ hardlockup_detector_event_create(2)
watchdog/2-21 [002] .... 1.637510: <stack trace>
=> smpboot_thread_fn
=> kthread
=> ret_from_fork
watchdog/3-27 [003] .... 1.742245: hardlockup_detector_perf_enable: ############ hardlockup_detector_perf_enable(3)
watchdog/3-27 [003] .... 1.742253: <stack trace>
=> kthread
=> ret_from_fork
watchdog/3-27 [003] .... 1.742255: hardlockup_detector_event_create: ############ hardlockup_detector_event_create(3)
watchdog/3-27 [003] .... 1.742258: <stack trace>
=> smpboot_thread_fn
=> kthread
=> ret_from_fork
watchdog/0-12 [000] .... 7.535105: hardlockup_detector_perf_disable: ############ hardlockup_detector_perf_disable(0)
watchdog/0-12 [000] .... 7.535108: <stack trace>
=> kthread
=> ret_from_fork
watchdog/1-15 [001] .... 7.535136: hardlockup_detector_perf_disable: ############ hardlockup_detector_perf_disable(1)
watchdog/1-15 [001] .... 7.535138: <stack trace>
=> kthread
=> ret_from_fork
watchdog/2-21 [002] .... 7.535155: hardlockup_detector_perf_disable: ############ hardlockup_detector_perf_disable(2)
watchdog/2-21 [002] .... 7.535157: <stack trace>
=> kthread
=> ret_from_fork
watchdog/3-27 [003] .... 7.535188: hardlockup_detector_perf_disable: ############ hardlockup_detector_perf_disable(3)
watchdog/3-27 [003] .... 7.535190: <stack trace>
=> kthread
=> ret_from_fork
watchdog/2-21 [002] .... 7.535206: hardlockup_detector_perf_enable: ############ hardlockup_detector_perf_enable(2)
watchdog/2-21 [002] .... 7.535221: <stack trace>
=> kthread
=> ret_from_fork
watchdog/2-21 [002] .... 7.535222: hardlockup_detector_event_create: ############ hardlockup_detector_event_create(2)
watchdog/2-21 [002] .... 7.535223: <stack trace>
=> smpboot_thread_fn
=> kthread
=> ret_from_fork
watchdog/2-21 [002] .... 7.535224: hardlockup_detector_event_create: ############## perf event for CPU 2 already created, skipping
watchdog/2-21 [002] .... 7.535225: <stack trace>
=> smpboot_thread_fn
=> kthread
=> ret_from_fork
watchdog/0-12 [000] .... 7.535225: hardlockup_detector_perf_enable: ############ hardlockup_detector_perf_enable(0)
watchdog/1-15 [001] .... 7.535225: hardlockup_detector_perf_enable: ############ hardlockup_detector_perf_enable(1)
watchdog/1-15 [001] .... 7.535228: <stack trace>
=> kthread
=> ret_from_fork
watchdog/0-12 [000] .... 7.535228: <stack trace>
=> kthread
=> ret_from_fork
watchdog/0-12 [000] .... 7.535229: hardlockup_detector_event_create: ############ hardlockup_detector_event_create(0)
watchdog/1-15 [001] .... 7.535229: hardlockup_detector_event_create: ############ hardlockup_detector_event_create(1)
watchdog/0-12 [000] .... 7.535232: <stack trace>
=> smpboot_thread_fn
=> kthread
=> ret_from_fork
watchdog/1-15 [001] .... 7.535232: <stack trace>
=> smpboot_thread_fn
=> kthread
=> ret_from_fork
watchdog/0-12 [000] .... 7.535233: hardlockup_detector_event_create: ############## perf event for CPU 0 already created, skipping
watchdog/1-15 [001] .... 7.535233: hardlockup_detector_event_create: ############## perf event for CPU 1 already created, skipping
watchdog/0-12 [000] .... 7.535236: <stack trace>
=> smpboot_thread_fn
=> kthread
=> ret_from_fork
watchdog/1-15 [001] .... 7.535236: <stack trace>
=> smpboot_thread_fn
=> kthread
=> ret_from_fork
sysctl-148 [000] .... 7.536879: hardlockup_detector_perf_cleanup: ############ hardlockup_detector_perf_cleanup
sysctl-148 [000] .... 7.536881: <stack trace>
=> proc_watchdog_thresh
=> proc_sys_call_handler
=> proc_sys_write
=> __vfs_write
=> vfs_write
=> SyS_write
=> entry_SYSCALL_64_fastpath
watchdog/3-27 [003] .... 7.536888: hardlockup_detector_perf_enable: ############ hardlockup_detector_perf_enable(3)
watchdog/3-27 [003] .... 7.536890: <stack trace>
=> kthread
=> ret_from_fork
watchdog/3-27 [003] .... 7.536891: hardlockup_detector_event_create: ############ hardlockup_detector_event_create(3)
watchdog/3-27 [003] .... 7.536892: <stack trace>
=> smpboot_thread_fn
=> kthread
=> ret_from_fork
watchdog/3-27 [003] .... 7.536893: hardlockup_detector_event_create: ############## perf event for CPU 3 already created, skipping
watchdog/3-27 [003] .... 7.536895: <stack trace>
=> smpboot_thread_fn
=> kthread
=> ret_from_fork
sysctl-148 [000] .... 8.551925: hardlockup_detector_perf_cleanup: ############ hardlockup_detector_perf_cleanup done
sysctl-148 [000] .... 8.551928: <stack trace>
=> proc_watchdog_thresh
=> proc_sys_call_handler
=> proc_sys_write
=> __vfs_write
=> vfs_write
=> SyS_write
=> entry_SYSCALL_64_fastpath
Powered by blists - more mailing lists