From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753885AbdJaRQ1 (ORCPT ); Tue, 31 Oct 2017 13:16:27 -0400 Received: from mail-pg0-f52.google.com ([74.125.83.52]:43410 "EHLO mail-pg0-f52.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753703AbdJaRQZ (ORCPT ); Tue, 31 Oct 2017 13:16:25 -0400 X-Google-Smtp-Source: ABhQp+Q+c9Xa11si7zKIods7KclVPhBiwaNqs3Soyc2v/FgCoz2CECAullCKnjmOcGqMTBVm+kJdkQ== Date: Tue, 31 Oct 2017 10:16:22 -0700 From: Guenter Roeck To: Peter Zijlstra Cc: Thomas Gleixner , linux-kernel@vger.kernel.org, Don Zickus , Ingo Molnar Subject: Re: Crashes in perf_event_ctx_lock_nested Message-ID: <20171031171622.GA28688@roeck-us.net> References: <20171030224512.GA13592@roeck-us.net> <20171031134850.ynix2zqypmca2mtt@hirez.programming.kicks-ass.net> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20171031134850.ynix2zqypmca2mtt@hirez.programming.kicks-ass.net> User-Agent: Mutt/1.5.24 (2015-08-30) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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: => 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: => 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: => 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: => 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: => 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: => 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: => 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: => 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: => 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: => 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: => 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: => 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: => 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: => 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: => 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: => 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: => 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: => 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: => 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: => kthread => ret_from_fork watchdog/0-12 [000] .... 7.535228: => 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: => smpboot_thread_fn => kthread => ret_from_fork watchdog/1-15 [001] .... 7.535232: => 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: => smpboot_thread_fn => kthread => ret_from_fork watchdog/1-15 [001] .... 7.535236: => 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: => 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: => 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: => 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: => 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: => proc_watchdog_thresh => proc_sys_call_handler => proc_sys_write => __vfs_write => vfs_write => SyS_write => entry_SYSCALL_64_fastpath