Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1757373Ab3ILSTW (ORCPT ); Thu, 12 Sep 2013 14:19:22 -0400 Received: from hrndva-omtalb.mail.rr.com ([71.74.56.122]:2920 "EHLO hrndva-omtalb.mail.rr.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1756604Ab3ILSTR (ORCPT ); Thu, 12 Sep 2013 14:19:17 -0400 X-Authority-Analysis: v=2.0 cv=V4T/IJbi c=1 sm=0 a=Sro2XwOs0tJUSHxCKfOySw==:17 a=Drc5e87SC40A:10 a=8G3D-EVed2cA:10 a=5SG0PmZfjMsA:10 a=kj9zAlcOel0A:10 a=meVymXHHAAAA:8 a=KGjhK52YXX0A:10 a=znGwHLDW1tUA:10 a=20KFwNOVAAAA:8 a=D19gQVrFAAAA:8 a=vTr9H3xdAAAA:8 a=edQcBa8ewUHbUfjaiBcA:9 a=CjuIK1q_8ugA:10 a=jEp0ucaQiEUA:10 a=Sro2XwOs0tJUSHxCKfOySw==:117 X-Cloudmark-Score: 0 X-Authenticated-User: X-Originating-IP: 67.255.60.225 Date: Thu, 12 Sep 2013 14:19:13 -0400 From: Steven Rostedt To: Dave Jones Cc: Linux Kernel , Peter Zijlstra , Frederic Weisbecker , Ingo Molnar Subject: Re: trinity finds ftrace/perf bug. Film at 11. Message-ID: <20130912141913.2ffc7077@gandalf.local.home> In-Reply-To: <20130911135434.GA678@redhat.com> References: <20130911135434.GA678@redhat.com> X-Mailer: Claws Mail 3.9.2 (GTK+ 2.24.20; x86_64-pc-linux-gnu) Mime-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 6159 Lines: 123 This is something that either Peter or Frederic need to look at. -- Steve On Wed, 11 Sep 2013 09:54:34 -0400 Dave Jones wrote: > Usual story. I'm trying to narrow down on a tracing bug I'd reported that we had no > understanding of (https://lkml.org/lkml/2013/8/27/646) and had hacked up > trinity to just only use perf fds, and left it running overnight. > > Woke up to _another_ bug. > > WARNING: CPU: 1 PID: 23361 at kernel/events/core.c:5566 perf_swevent_add+0x18d/0x1a0() > Modules linked in: bnep can_bcm caif_socket caif phonet af_rxrpc bluetooth llc2 af_key rose netrom bridge stp snd_seq_dummy tun fuse scsi_transport_iscsi ipt_ULOG pppoe pppox ppp_generic slhc can_raw can af_802154 nfnetlink nfc rfkill irda crc_ccitt rds x25 atm appletalk ipx p8023 psnap p8022 llc ax25 xfs libcrc32c snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm snd_page_alloc snd_timer snd e1000e pcspkr usb_debug ptp pps_core soundcore > CPU: 1 PID: 23361 Comm: trinity-child31 Not tainted 3.11.0+ #66 > ffffffff81a2a90b ffff8801fe4e9a68 ffffffff8171d32b 0000000000000000 > ffff8801fe4e9aa0 ffffffff81053e5d ffff880102728948 ffff8802459cf3e0 > 0000000000000008 0000000000000001 000000002fa8ce99 ffff8801fe4e9ab0 > Call Trace: > [] dump_stack+0x54/0x74 > [] warn_slowpath_common+0x7d/0xa0 > [] warn_slowpath_null+0x1a/0x20 > [] perf_swevent_add+0x18d/0x1a0 > [] event_sched_in.isra.78+0x87/0x1c0 > [] group_sched_in+0x6a/0x1c0 > [] ctx_sched_in+0x101/0x290 > [] perf_event_sched_in+0x60/0x90 > [] perf_event_context_sched_in+0x7b/0xc0 > [] __perf_event_task_sched_in+0x477/0x490 > [] ? arch_vtime_task_switch+0x94/0xa0 > [] finish_task_switch+0xf0/0x180 > [] __schedule+0x34c/0x9b0 > [] schedule+0x29/0x70 > [] schedule_timeout+0x1c1/0x360 > [] ? trace_hardirqs_off_caller+0x1f/0xc0 > [] ? trace_hardirqs_off+0xd/0x10 > [] ? local_clock+0x3f/0x50 > [] ? _raw_spin_unlock_irq+0x2c/0x40 > [] ? trace_hardirqs_on_caller+0x115/0x1e0 > [] wait_for_completion+0xd4/0x110 > [] ? wake_up_state+0x20/0x20 > [] __synchronize_srcu+0x12d/0x1f0 > [] ? call_srcu+0x80/0x80 > [] ? complete+0x1d/0x50 > [] synchronize_srcu+0x1d/0x20 > [] fsnotify_destroy_group+0x1e/0x40 > [] SyS_inotify_init1+0xe8/0x110 > [] sys_inotify_init+0x10/0x20 > [] tracesys+0xdd/0xe2 > ---[ end trace 2e7ee66c64149375 ]--- > > That's this in perf_swevent_add > > 5564 > 5565 head = find_swevent_head(swhash, event); > 5566 if (WARN_ON_ONCE(!head)) > 5567 return -EINVAL; > 5568 > 5569 hlist_add_head_rcu(&event->hlist_entry, head); > 5570 > 5571 return 0; > 5572 } > 5573 > > Of the 8 syscalls that trinity was running, three were perf_event_open > inotify_init, and newlstat. > > So then I tried running trinity with just those three syscalls. > > And got the same WARN_ON, but from a slightly different path.. > > WARNING: CPU: 3 PID: 861 at kernel/events/core.c:5566 perf_swevent_add+0x18d/0x1a0() > Modules linked in: ipt_ULOG nfnetlink can_bcm can scsi_transport_iscsi ax25 nfc rfkill af_802154 irda crc_ccitt rds x25 atm appletalk ipx p8023 psnap p8022 llc snd_hda_codec_realtek snd_hda_codec_hdmi xfs snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm snd_page_alloc libcrc32c snd_timer snd e1000e pcspkr ptp pps_core soundcore usb_debug > CPU: 3 PID: 861 Comm: trinity-child31 Not tainted 3.11.0+ #67 > ffffffff81a2aa43 ffff8801e6c65ae8 ffffffff8171d5cb 0000000000000000 > ffff8801e6c65b20 ffffffff81053e5d ffff8801e66a2e68 ffff880245dcf3e0 > 0000000000000004 0000000000000001 0000000004392ac6 ffff8801e6c65b30 > Call Trace: > [] dump_stack+0x54/0x74 > [] warn_slowpath_common+0x7d/0xa0 > [] warn_slowpath_null+0x1a/0x20 > [] perf_swevent_add+0x18d/0x1a0 > [] event_sched_in.isra.78+0x87/0x1c0 > [] group_sched_in+0x6a/0x1c0 > [] ctx_sched_in+0x17c/0x290 > [] perf_event_sched_in+0x3a/0x90 > [] perf_event_context_sched_in+0x7b/0xc0 > [] __perf_event_task_sched_in+0x477/0x490 > [] ? arch_vtime_task_switch+0x94/0xa0 > [] finish_task_switch+0xf0/0x180 > [] __schedule+0x344/0xa20 > [] __cond_resched+0x26/0x30 > [] _cond_resched+0x3a/0x50 > [] clear_inode+0x2e/0x80 > [] proc_evict_inode+0x23/0x70 > [] evict+0xa3/0x1a0 > [] iput+0xf5/0x190 > [] dput+0x245/0x260 > [] path_put+0x16/0x30 > [] vfs_fstatat+0x6d/0xa0 > [] SYSC_newlstat+0x22/0x40 > [] SyS_newlstat+0xe/0x10 > [] tracesys+0xdd/0xe2 > > The good news is I can reproduce that very quickly. > (Apply http://paste.fedoraproject.org/38721/37890755 on top of trinity.git, > and run ./trinity -l off -q -C32 -c inotify_init1 -c perf_event_open -c newlstat) > > > (There's a different kernel build on the two traces fwiw, but the commits are > just 8d7551eb1916832f2a5b27346edf24e7b2382f67 -> bf83e61464803d386d0ec3fc92e5449d7963a409, > which is just a bunch of drm stuff). > > Dave -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/