LKML Archive on lore.kernel.org
 help / color / Atom feed
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
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

  reply index

Thread overview: 20+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2017-10-30 22:45 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

LKML Archive on lore.kernel.org

Archives are clonable:
	git clone --mirror https://lore.kernel.org/lkml/0 lkml/git/0.git
	git clone --mirror https://lore.kernel.org/lkml/1 lkml/git/1.git
	git clone --mirror https://lore.kernel.org/lkml/2 lkml/git/2.git
	git clone --mirror https://lore.kernel.org/lkml/3 lkml/git/3.git
	git clone --mirror https://lore.kernel.org/lkml/4 lkml/git/4.git
	git clone --mirror https://lore.kernel.org/lkml/5 lkml/git/5.git
	git clone --mirror https://lore.kernel.org/lkml/6 lkml/git/6.git
	git clone --mirror https://lore.kernel.org/lkml/7 lkml/git/7.git
	git clone --mirror https://lore.kernel.org/lkml/8 lkml/git/8.git
	git clone --mirror https://lore.kernel.org/lkml/9 lkml/git/9.git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V2 lkml lkml/ https://lore.kernel.org/lkml \
		linux-kernel@vger.kernel.org
	public-inbox-index lkml

Example config snippet for mirrors

Newsgroup available over NNTP:
	nntp://nntp.lore.kernel.org/org.kernel.vger.linux-kernel


AGPL code for this site: git clone https://public-inbox.org/public-inbox.git