From: Guenter Roeck <linux@roeck-us.net>
To: Peter Zijlstra <peterz@infradead.org>
Cc: Thomas Gleixner <tglx@linutronix.de>,
linux-kernel@vger.kernel.org, Don Zickus <dzickus@redhat.com>,
Ingo Molnar <mingo@kernel.org>
Subject: Re: Crashes in perf_event_ctx_lock_nested
Date: Tue, 31 Oct 2017 10:16:22 -0700 [thread overview]
Message-ID: <20171031171622.GA28688@roeck-us.net> (raw)
In-Reply-To: <20171031134850.ynix2zqypmca2mtt@hirez.programming.kicks-ass.net>
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
next prev parent reply other threads:[~2017-10-31 17:16 UTC|newest]
Thread overview: 20+ messages / expand[flat|nested] mbox.gz Atom feed top
2017-10-30 22:45 Crashes in perf_event_ctx_lock_nested Guenter Roeck
2017-10-31 13:48 ` Peter Zijlstra
2017-10-31 17:16 ` Guenter Roeck [this message]
2017-10-31 18:50 ` Don Zickus
2017-10-31 20:12 ` Guenter Roeck
2017-10-31 20:23 ` Don Zickus
2017-10-31 21:32 ` Thomas Gleixner
2017-10-31 22:11 ` Guenter Roeck
2017-11-01 18:11 ` Don Zickus
2017-11-01 18:34 ` Guenter Roeck
2017-11-01 19:46 ` [tip:core/urgent] watchdog/hardlockup/perf: Use atomics to track in-use cpu counter tip-bot for Don Zickus
2017-11-01 20:28 ` tip-bot for Don Zickus
2017-11-01 18:22 ` Crashes in perf_event_ctx_lock_nested Thomas Gleixner
2017-11-01 8:14 ` Peter Zijlstra
2017-11-01 8:26 ` Thomas Gleixner
2017-11-01 19:46 ` [tip:core/urgent] watchdog/harclockup/perf: Revert a33d44843d45 ("watchdog/hardlockup/perf: Simplify deferred event destroy") tip-bot for Thomas Gleixner
2017-11-01 20:32 ` Guenter Roeck
2017-11-01 20:52 ` Thomas Gleixner
2017-11-01 20:27 ` tip-bot for Thomas Gleixner
2017-10-31 18:48 ` Crashes in perf_event_ctx_lock_nested Don Zickus
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20171031171622.GA28688@roeck-us.net \
--to=linux@roeck-us.net \
--cc=dzickus@redhat.com \
--cc=linux-kernel@vger.kernel.org \
--cc=mingo@kernel.org \
--cc=peterz@infradead.org \
--cc=tglx@linutronix.de \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.