From owner-freebsd-dtrace@FreeBSD.ORG Sun Aug 25 20:04:15 2013 Return-Path: Delivered-To: freebsd-dtrace@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [8.8.178.115]) (using TLSv1 with cipher ADH-AES256-SHA (256/256 bits)) (No client certificate requested) by hub.freebsd.org (Postfix) with ESMTP id 3F723D8E; Sun, 25 Aug 2013 20:04:15 +0000 (UTC) (envelope-from markjdb@gmail.com) Received: from mail-ie0-x22e.google.com (mail-ie0-x22e.google.com [IPv6:2607:f8b0:4001:c03::22e]) (using TLSv1 with cipher ECDHE-RSA-RC4-SHA (128/128 bits)) (No client certificate requested) by mx1.freebsd.org (Postfix) with ESMTPS id 071FD2FAF; Sun, 25 Aug 2013 20:04:14 +0000 (UTC) Received: by mail-ie0-f174.google.com with SMTP id k14so3775997iea.33 for ; Sun, 25 Aug 2013 13:04:13 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=sender:date:from:to:cc:subject:message-id:references:mime-version :content-type:content-disposition:in-reply-to:user-agent; bh=2ZK4AH4NR6lYb5mRqMxozH2mHX0JLGw5VW/Md+PeszQ=; b=smwHLVPdMJ7PZ9bvIvtXORnVUE6V6MOx6DqkcFcz6gWAo37YHnJWiMWG9kaM/avtv4 +9m4+OenDwVfBAuepn0oRByjnOr3Iozt94dWAtdVFKuID/+MUvZqkPm1TryC1P/ITXD7 W+SblsZeMQy3SEgVdJWaoxI6ml6WHiN2HNtXmZ9sVXVPZaJxzI6NrvSdXcoClQjjaTzA nO64vXUNFlSEYpgizB/nliTA+YZwrt/+bPibKa4+YJbPRs3P+iwUpkXL4rmbRa0M2z3I SRtcgjBENEdXg5+itD3EBzGXj0O/Kftby03oW1gpYDt3Nq8XQCAiYQMK0WjD6sRAamKV 6FgQ== X-Received: by 10.50.2.99 with SMTP id 3mr4422328igt.51.1377461053563; Sun, 25 Aug 2013 13:04:13 -0700 (PDT) Received: from raichu (24-212-218-13.cable.teksavvy.com. [24.212.218.13]) by mx.google.com with ESMTPSA id oq3sm13004417igb.1.1969.12.31.16.00.00 (version=TLSv1 cipher=ECDHE-RSA-RC4-SHA bits=128/128); Sun, 25 Aug 2013 13:04:12 -0700 (PDT) Sender: Mark Johnston Date: Sun, 25 Aug 2013 16:04:07 -0400 From: Mark Johnston To: Yuri Subject: Re: DTrace network providers Message-ID: <20130825200407.GA76615@raichu> References: <20130821045926.GA17196@raichu> <52168B0E.1050308@rawbw.com> <5216FC0B.1060304@rawbw.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <5216FC0B.1060304@rawbw.com> User-Agent: Mutt/1.5.21 (2010-09-15) Cc: freebsd-net@freebsd.org, freebsd-dtrace@freebsd.org X-BeenThere: freebsd-dtrace@freebsd.org X-Mailman-Version: 2.1.14 Precedence: list List-Id: "A discussion list for developers working on DTrace in FreeBSD." List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sun, 25 Aug 2013 20:04:15 -0000 On Thu, Aug 22, 2013 at 11:07:07PM -0700, Yuri wrote: > On 08/22/2013 15:30, Mark Johnston wrote: > > My apologies! It looks like r254523 introduced a conflict. r254468 is a > > minimum dependency. > > > > I'd suggest trying again with r254523 or later. > > I don't know what the problem is, but I tried on r254523 and on the > later r254677, and am getting build error during buildkernel, see below. > And I did successful buildworld and installworld before this. > I suspect that you didn't delete the files added by the patch before applying the patch a second time. That'll result in two concatenated copies of the new files, which will cause the build to fail at in_kdtrace.c. I just made the same mistake myself. :) > > --- buildkernel errors --- > /usr/src/sys/netinet/in_kdtrace.c:165:1: error: redefinition of > 'sdt_provider_ip' > SDT_PROVIDER_DEFINE(ip); > ^ > /usr/src/sys/sys/sdt.h:136:22: note: expanded from macro > 'SDT_PROVIDER_DEFINE' > struct sdt_provider sdt_provider_##prov[1] = > { \ > ^ > :127:1: note: expanded from here > sdt_provider_ip > ^ > /usr/src/sys/netinet/in_kdtrace.c:38:1: note: previous definition is here > SDT_PROVIDER_DEFINE(ip); > ^ > /usr/src/sys/sys/sdt.h:136:22: note: expanded from macro > 'SDT_PROVIDER_DEFINE' > struct sdt_provider sdt_provider_##prov[1] = > { \ > ^ > :203:1: note: expanded from here > sdt_provider_ip > ^ > /usr/src/sys/netinet/in_kdtrace.c:166:1: error: redefinition of > 'sdt_provider_tcp' > SDT_PROVIDER_DEFINE(tcp); > ^ > /usr/src/sys/sys/sdt.h:136:22: note: expanded from macro > 'SDT_PROVIDER_DEFINE' > struct sdt_provider sdt_provider_##prov[1] = > { \ > ^ > From owner-freebsd-dtrace@FreeBSD.ORG Thu Aug 29 11:01:45 2013 Return-Path: Delivered-To: freebsd-dtrace@FreeBSD.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) (using TLSv1 with cipher ADH-AES256-SHA (256/256 bits)) (No client certificate requested) by hub.freebsd.org (Postfix) with ESMTP id 7702CFDA; Thu, 29 Aug 2013 11:01:45 +0000 (UTC) (envelope-from avg@FreeBSD.org) Received: from citadel.icyb.net.ua (citadel.icyb.net.ua [212.40.38.140]) by mx1.freebsd.org (Postfix) with ESMTP id 9636C2C39; Thu, 29 Aug 2013 11:01:44 +0000 (UTC) Received: from porto.starpoint.kiev.ua (porto-e.starpoint.kiev.ua [212.40.38.100]) by citadel.icyb.net.ua (8.8.8p3/ICyb-2.3exp) with ESMTP id OAA25424; Thu, 29 Aug 2013 14:01:43 +0300 (EEST) (envelope-from avg@FreeBSD.org) Received: from localhost ([127.0.0.1]) by porto.starpoint.kiev.ua with esmtp (Exim 4.34 (FreeBSD)) id 1VEzyw-0002qn-P9; Thu, 29 Aug 2013 14:01:42 +0300 Message-ID: <521F29F2.2020208@FreeBSD.org> Date: Thu, 29 Aug 2013 14:01:06 +0300 From: Andriy Gapon User-Agent: Mozilla/5.0 (X11; FreeBSD amd64; rv:17.0) Gecko/20130810 Thunderbird/17.0.8 MIME-Version: 1.0 To: freebsd-dtrace@FreeBSD.org, Mark Johnston Subject: sdt deadlock X-Enigmail-Version: 1.5.1 Content-Type: text/plain; charset=X-VIET-VPS Content-Transfer-Encoding: 7bit X-BeenThere: freebsd-dtrace@freebsd.org X-Mailman-Version: 2.1.14 Precedence: list List-Id: "A discussion list for developers working on DTrace in FreeBSD." List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 29 Aug 2013 11:01:45 -0000 We've just experienced a deadlock between dtrace_lock and sdt_sx. Mark, could you please take a look at the following debugging data if you have some time? Does it look like something that could be fixed by your recent big change to the related code? Debug session follows. (kgdb) tid 101190 (kgdb) bt #0 sched_switch (td=0xfffffe007a109490, newtd=0xfffffe0018c7c920, flags=) at /usr/src/sys/kern/sched_ule.c:1920 #1 0xffffffff80942634 in mi_switch (flags=260, newtd=0x0) at /usr/src/sys/kern/kern_synch.c:485 #2 0xffffffff8097da72 in sleepq_wait (wchan=0xffffffff81e7d300, pri=0) at /usr/src/sys/kern/subr_sleepqueue.c:623 #3 0xffffffff80941ad6 in _sx_xlock_hard (sx=0xffffffff81e7d300, tid=18446741876734203024, opts=, file=, line=) at /usr/src/sys/kern/kern_sx.c:669 #4 0xffffffff80942295 in _sx_xlock (sx=, opts=, file=, line=) at sx.h:161 #5 0xffffffff81c57d1b in dtrace_register (name=0xffffffff80f50e60 "sctp", pap=0xffffffff81ea73f8, priv=2, cr=0x0, pops=0xffffffff81ea7420, arg=0x0, idp=0xffffffff812fbde8) at /usr/src/sys/modules/dtrace/dtrace/../../../cddl/contrib/opensolaris/uts/common/dtrace/dtrace.c:7471 #6 0xffffffff81ea7220 in sdt_provider_reg_callback (prov=, arg=) at /usr/src/sys/modules/dtrace/sdt/../../../cddl/dev/sdt/sdt.c:182 #7 0xffffffff80936ed5 in sdt_provider_listall_locked (callback_func=0xffffffff81ea71f0 , arg=0x0) at /usr/src/sys/kern/kern_sdt.c:246 #8 0xffffffff80937424 in sdt_register_callbacks (register_prov=0xffffffff81ea71f0 , reg_prov_arg=0x0, deregister_prov=0xffffffff81ea71e0 , dereg_prov_arg=0x0, register_probe=0xffffffff81ea7100 , reg_probe_arg=0x0) at /usr/src/sys/kern/kern_sdt.c:320 #9 0xffffffff8091aefe in linker_load_module (kldname=, modname=0xffffffff81c3d0c4 "sdt", parent=0xfffffe02b6b5e800, verinfo=0xffffffff81c3d38c, lfpp=0x0) at /usr/src/sys/kern/kern_linker.c:239 #10 0xffffffff8091b44c in linker_load_dependencies (lf=0xfffffe02b6b5e800) at /usr/src/sys/kern/kern_linker.c:2131 #11 0xffffffff80d42690 in link_elf_load_file (cls=, filename=, result=0xffffff91e59998f8) at /usr/src/sys/kern/link_elf_obj.c:845 #12 0xffffffff8091adef in linker_load_module (kldname=, modname=0xfffffe010cd64c00 "dtraceall", parent=0x0, verinfo=0x0, lfpp=0xffffff91e5999958) at linker_if.h:161 #13 0xffffffff8091b538 in kern_kldload (td=0xfffffe007a109490, file=, fileid=0xffffff91e59999b4) at /usr/src/sys/kern/kern_linker.c:1039 #14 0xffffffff8091b754 in sys_kldload (td=0xfffffe007a109490, uap=) at /usr/src/sys/kern/kern_linker.c:1073 #15 0xffffffff80cd523a in amd64_syscall (td=0xfffffe007a109490, traced=0) at subr_syscall.c:135 #16 0xffffffff80cbf7f7 in Xfast_syscall () at /usr/src/sys/amd64/amd64/exception.S:387 #17 0x000000080087e6fc in ?? () Previous frame inner to this frame (corrupt stack?) (kgdb) fr 3 #3 0xffffffff80941ad6 in _sx_xlock_hard (sx=0xffffffff81e7d300, tid=18446741876734203024, opts=, file=, line=) at /usr/src/sys/kern/kern_sx.c:669 669 /usr/src/sys/kern/kern_sx.c: No such file or directory. in /usr/src/sys/kern/kern_sx.c (kgdb) p *sx $1 = {lock_object = {lo_name = 0xffffffff81c6e9dd "dtrace_provider_lock", lo_flags = 41091072, lo_data = 0, lo_witness = 0x0}, sx_lock = 18446741876595964196} (kgdb) p/x *sx $2 = {lock_object = {lo_name = 0xffffffff81c6e9dd, lo_flags = 0x2730000, lo_data = 0x0, lo_witness = 0x0}, sx_lock = 0xfffffe0071d33924} (kgdb) p ((struct thread*)0xfffffe0071d33920)->td_tid $3 = 100433 (kgdb) tid 100433 (kgdb) bt #0 sched_switch (td=0xfffffe0071d33920, newtd=0xfffffe0018c88920, flags=) at /usr/src/sys/kern/sched_ule.c:1920 #1 0xffffffff80942634 in mi_switch (flags=260, newtd=0x0) at /usr/src/sys/kern/kern_synch.c:485 #2 0xffffffff8097da72 in sleepq_wait (wchan=0xffffffff813ac880, pri=0) at /usr/src/sys/kern/subr_sleepqueue.c:623 #3 0xffffffff80941ad6 in _sx_xlock_hard (sx=0xffffffff813ac880, tid=18446741876595964192, opts=, file=, line=) at /usr/src/sys/kern/kern_sx.c:669 #4 0xffffffff80937793 in sdt_provider_listall (callback_func=0xffffffff81ea7280 , arg=0x0) at sx.h:161 #5 0xffffffff81c523da in dtrace_probe_provide (desc=0x0, prv=0xfffffe011d7bb000) at /usr/src/sys/modules/dtrace/dtrace/../../../cddl/contrib/opensolaris/uts/common/dtrace/dtrace.c:7984 #6 0xffffffff81c52487 in dtrace_open (dev=0xfffffe02b6b5bc00, oflags=, devtype=, td=) at /usr/src/sys/modules/dtrace/dtrace/../../../cddl/contrib/opensolaris/uts/common/dtrace/dtrace.c:15418 #7 0xffffffff80820658 in devfs_open (ap=0xffffff91e4ad07d0) at /usr/src/sys/fs/devfs/devfs_vnops.c:1084 #8 0xffffffff80d6b434 in VOP_OPEN_APV (vop=0xffffffff812be940, a=0xffffff91e4ad07d0) at vnode_if.c:447 #9 0xffffffff809e826b in vn_open_cred (ndp=0xffffff91e4ad0880, flagp=0xffffff91e4ad087c, cmode=0, vn_open_flags=, cred=0xfffffe0018c6da00, fp=0xfffffe02b6ed36e0) at vnode_if.h:196 #10 0xffffffff809e3faa in kern_openat (td=0xfffffe0071d33920, fd=-100, path=0x800aa89b2 , pathseg=UIO_USERSPACE, flags=3, mode=) at /usr/src/sys/kern/vfs_syscalls.c:1132 #11 0xffffffff80cd523a in amd64_syscall (td=0xfffffe0071d33920, traced=0) at subr_syscall.c:135 #12 0xffffffff80cbf7f7 in Xfast_syscall () at /usr/src/sys/amd64/amd64/exception.S:387 #13 0x0000000801a2f50c in ?? () (kgdb) fr 3 #3 0xffffffff80941ad6 in _sx_xlock_hard (sx=0xffffffff813ac880, tid=18446741876595964192, opts=, file=, line=) at /usr/src/sys/kern/kern_sx.c:669 669 /usr/src/sys/kern/kern_sx.c: No such file or directory. in /usr/src/sys/kern/kern_sx.c (kgdb) p/x *sx $4 = {lock_object = {lo_name = 0xffffffff80f340fa, lo_flags = 0x2310000, lo_data = 0x0, lo_witness = 0x0}, sx_lock = 0xfffffe007a109494} (kgdb) p ((struct thread*)0xfffffe007a109490)->td_tid $5 = 101190 The related snippets from the source code: int dtrace_register(const char *name, const dtrace_pattr_t *pap, uint32_t priv, cred_t *cr, const dtrace_pops_t *pops, void *arg, dtrace_provider_id_t *idp) { ... mutex_enter(&dtrace_provider_lock); <------------ mutex_enter(&dtrace_lock); ... int sdt_provider_listall(sdt_provider_listall_func_t callback_func, void *arg) { int error; sx_xlock(&sdt_sx); <----------- ... So it seems that thread 101190 has sdt_sx and wants to take dtrace_provider_lock in dtrace_register. At the same time thread 100433 has dtrace_provider_lock (taken in dtrace_open right before dtrace_probe_provide) and wants to take sdt_sx in sdt_provider_listall. -- Andriy Gapon From owner-freebsd-dtrace@FreeBSD.ORG Thu Aug 29 22:20:38 2013 Return-Path: Delivered-To: freebsd-dtrace@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [8.8.178.115]) (using TLSv1 with cipher ADH-AES256-SHA (256/256 bits)) (No client certificate requested) by hub.freebsd.org (Postfix) with ESMTP id 8A304B16; Thu, 29 Aug 2013 22:20:38 +0000 (UTC) (envelope-from markjdb@gmail.com) Received: from mail-ie0-x22d.google.com (mail-ie0-x22d.google.com [IPv6:2607:f8b0:4001:c03::22d]) (using TLSv1 with cipher ECDHE-RSA-RC4-SHA (128/128 bits)) (No client certificate requested) by mx1.freebsd.org (Postfix) with ESMTPS id 51FF12EA5; Thu, 29 Aug 2013 22:20:38 +0000 (UTC) Received: by mail-ie0-f173.google.com with SMTP id qa5so1612197ieb.4 for ; Thu, 29 Aug 2013 15:20:37 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=sender:date:from:to:cc:subject:message-id:references:mime-version :content-type:content-disposition:in-reply-to:user-agent; bh=pk4YOhHV5s/05honH5KCi4ho6USIrPOQoAjn6W1bqN8=; b=B2B0CoR50/iSzjm+Q2EA7FVIA26pdX+NhHYuavwKW2+pd0ueNbfXpfqsghjXWfuBhW MEcJk4Up8J9hxxyZGU2imtr7MkrXq8SiS621C0GexrKT/ygrqE4jNKPqDgtbl3RVvcWa L2oHQqiuXHCxDRsDycb2ulapIv3En6WHE0qbDkLci33liB/jOt/5IxcHHp0nO3Csq9Ay NofQyKjD52jEp6tV7hTwwVD9qiSRP0XJoMBPrRGJK3WHK7wv08OuWlBPYwcYD1GuJQtG RqbG3tg1yeb6Rta/PVxEq4d/Hr7uiDENADVH4OY/ZAz82YGMS9nVSs78kiRCnvLrHBhY LWcw== X-Received: by 10.43.53.144 with SMTP id vq16mr2559655icb.41.1377814837766; Thu, 29 Aug 2013 15:20:37 -0700 (PDT) Received: from raichu (24-212-218-13.cable.teksavvy.com. [24.212.218.13]) by mx.google.com with ESMTPSA id m1sm752919igj.10.1969.12.31.16.00.00 (version=TLSv1 cipher=ECDHE-RSA-RC4-SHA bits=128/128); Thu, 29 Aug 2013 15:20:37 -0700 (PDT) Sender: Mark Johnston Date: Thu, 29 Aug 2013 18:20:29 -0400 From: Mark Johnston To: Andriy Gapon Subject: Re: sdt deadlock Message-ID: <20130829221950.GA47468@raichu> References: <521F29F2.2020208@FreeBSD.org> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <521F29F2.2020208@FreeBSD.org> User-Agent: Mutt/1.5.21 (2010-09-15) Cc: freebsd-dtrace@FreeBSD.org X-BeenThere: freebsd-dtrace@freebsd.org X-Mailman-Version: 2.1.14 Precedence: list List-Id: "A discussion list for developers working on DTrace in FreeBSD." List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 29 Aug 2013 22:20:38 -0000 On Thu, Aug 29, 2013 at 02:01:06PM +0300, Andriy Gapon wrote: > > We've just experienced a deadlock between dtrace_lock and sdt_sx. > > Mark, could you please take a look at the following debugging data if you have > some time? Does it look like something that could be fixed by your recent big > change to the related code? Hi Andriy, It will definitely be fixed by my recent changes - the sdt rewrite removed sdt_sx. :) Now the sdt code relies only on the kld lock and the DTrace locks, and I was careful to avoid LORs. In particular, the kld lock is always taken before any DTrace locks. I also just did a little test where I was loading and unloading a file containing SDT probe definitions in a loop, and running DTrace scripts in another terminal. I didn't have any problems, so I'm fairly confident that this particular interaction works properly now.