Date: Thu, 4 Dec 2014 12:55:40 -0800 From: <dteske@FreeBSD.org> To: "'Mark Johnston'" <markj@freebsd.org>, <dteske@FreeBSD.org> Cc: 'Julian Elischer' <julian@freebsd.org>, freebsd-dtrace@freebsd.org Subject: RE: DTrace script to trace processes entering vfs::vop_remove Message-ID: <04f001d01004$abaefd30$030cf790$@FreeBSD.org> In-Reply-To: <20141204182232.GB81713@charmander.picturesperfect.net> References: <032e01d00f4f$98a04e20$c9e0ea60$@FreeBSD.org> <20141204004501.GB29167@charmander.picturesperfect.net> <03ed01d00f66$89db0ee0$9d912ca0$@FreeBSD.org> <20141204182232.GB81713@charmander.picturesperfect.net>
next in thread | previous in thread | raw e-mail | index | archive | help
[-- Attachment #1 --] > -----Original Message----- > From: Mark Johnston [mailto:markjdb@gmail.com] On Behalf Of 'Mark > Johnston' > Sent: Thursday, December 4, 2014 10:23 AM > To: dteske@FreeBSD.org > Cc: freebsd-dtrace@freebsd.org; 'Julian Elischer' > Subject: Re: DTrace script to trace processes entering vfs::vop_remove > > On Wed, Dec 03, 2014 at 06:03:45PM -0800, dteske@FreeBSD.org wrote: > > > > > > > -----Original Message----- > > > From: Mark Johnston [mailto:markjdb@gmail.com] On Behalf Of Mark > > > Johnston > > > Sent: Wednesday, December 3, 2014 4:45 PM > > > To: dteske@FreeBSD.org > > > Cc: freebsd-dtrace@freebsd.org; 'Julian Elischer' > > > Subject: Re: DTrace script to trace processes entering vfs::vop_remove > > > > > > On Wed, Dec 03, 2014 at 03:19:31PM -0800, dteske@FreeBSD.org wrote: > > > > Hi markj, list, > > > > > > > > I wrote a script for $work to help me find out "who on Earth > > > > keeps deleting files XYZ?" from a particular storage server. > > > > > > > > Please find attached a copy of watch_vop_remove.d which > > > > has the following sample output: > > > > > > > > 2014 Dec 3 11:58:52 rm[75596]: /tmp/foo > > > > -+= 72846 0.0 -bash > > > > \-+= 75589 0.0 /bin/bash /usr/home/support/bash_script > > > > \-+= 75596 0.0 rm -f /tmp/foo > > > > > > > > The above sample output was displayed when executing the following > shell > > > > script: > > > > > > > > #!/bin/bash > > > > touch /tmp/foo > > > > rm -f /tmp/foo > > > > > > > > The output format displayed for each vop_remove() call is as follows: > > > > > > > > DATE process[PID]: PATH_TO_DELETE > > > > -+= GPID UID.GID grandparent_process [arguments (up to 3)] > > > > \-+= PPID UID.GID parent_process [arguments (up to 3)] > > > > \-+= PID UID.GID process [arguments (up to 3)] > > > > > > This is neat. I just had a few comments: > > > - You can use walltimestamp when printing the date and time, instead of > > > timestamp + blah. > > > > I read that online as well, however: > > walltimestamp appears to _always_ be zero. > > Right, it wasn't working properly on 8.0. :( > > gnn committed a fix for that as r238537. > > > > > > > > - It's possible to get the full argv of the current process with > > > curpsinfo->pr_psargs. It can be done for other processes too; see > > > /usr/lib/dtrace/psinfo.d. (This might not be true depending on the > > > FreeBSD version you're on.) > > > > Thanks! I'll have a look. > > > > > - Running this script with a make -j4 buildkernel causes dtrace to run > > > out of dynamic variable space. > > > > > > > Any recommendation on how to fix that? > > > > #pragma D option dynvarsize=what_exactly? > > (16m causes a warning that it's lowering the dynamic variable memory) > > It looks like a leak - once I start seeing the errors, no file removals > are logged at all. Dynamic variables need to be set to 0 once they're > finished with in order to release the consumed memory. > Thanks! Should be fixed in the latest (attached) version (watch_vop_remove2.d). However, I read here: http://wikis.oracle.com/display/DTrace/Variables Quote: Always assign zero to associative array elements that are no longer in use. And I read some more about the different variable types in DTrace: http://dtrace.org/blogs/brendan/2011/11/25/dtrace-variable-types/ It would appear that I've solved the issue by getting rid of associative arrays. Can you give the latest (attached) a try? -- Devin [-- Attachment #2 --] #!/usr/sbin/dtrace -s /* - * Copyright (c) 2014 Devin Teske <dteske@FreeBSD.org> * All rights reserved. * Redistribution and use in source and binary forms, with or without * modification, are permitted provided that the following conditions * are met: * 1. Redistributions of source code must retain the above copyright * notice, this list of conditions and the following disclaimer. * 2. Redistributions in binary form must reproduce the above copyright * notice, this list of conditions and the following disclaimer in the * documentation and/or other materials provided with the distribution. * * THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE * IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE * ARE DISCLAIMED. IN NO EVENT SHALL THE AUTHOR OR CONTRIBUTORS BE LIABLE * FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL * DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS * OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY * OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF * SUCH DAMAGE. * * $Title: dtrace(1) script to log process(es) entering vfs::vop_remove $ */ #pragma D option quiet #pragma D option dynvarsize=16m #pragma D option switchrate=10hz /*********************************************************/ vfs::vop_remove:entry /* probe ID 1 */ { this->vp = (struct vnode *)arg0; this->ncp = &(this->vp->v_cache_dst) != NULL ? this->vp->v_cache_dst.tqh_first : 0; this->fi_name = args[1] ? ( args[1]->a_cnp != NULL ? stringof(args[1]->a_cnp->cn_nameptr) : "" ) : ""; mount = this->vp->v_mount; /* ptr to vfs we are in */ this->fi_fs = mount != 0 ? stringof(mount->mnt_stat.f_fstypename) : ""; this->fi_mount = mount != 0 ? stringof(mount->mnt_stat.f_mntonname) : ""; this->d_name = args[0]->v_cache_dd != NULL ? stringof(args[0]->v_cache_dd->nc_name) : ""; } vfs::vop_remove:entry /this->vp == 0 || this->fi_fs == 0 || this->fi_fs == "devfs" || this->fi_fs == "" || this->fi_name == ""/ /* probe ID 2 */ { this->ncp = 0; } /*********************************************************/ vfs::vop_remove:entry /this->ncp/ /* probe ID 3 (depth 1) */ { this->dvp = this->ncp->nc_dvp != NULL ? ( &(this->ncp->nc_dvp->v_cache_dst) != NULL ? this->ncp->nc_dvp->v_cache_dst.tqh_first : 0 ) : 0; this->name1 = this->dvp != 0 ? ( this->dvp->nc_name != 0 ? stringof(this->dvp->nc_name) : "" ) : ""; } vfs::vop_remove:entry /this->name1 == 0 || this->fi_fs == 0 || this->fi_fs == "devfs" || this->fi_fs == "" || this->name1 == "/" || this->name1 == ""/ /* probe ID 4 */ { this->dvp = 0; } /*********************************************************/ /* * BEGIN Pathname-depth iterators (copy/paste as many times as-desired) */ vfs::vop_remove:entry /this->dvp/ /* probe ID 5 (depth 2) */ { this->dvp = this->dvp->nc_dvp != NULL ? ( &(this->dvp->nc_dvp->v_cache_dst) != NULL ? this->dvp->nc_dvp->v_cache_dst.tqh_first : 0 ) : 0; this->name2 = this->dvp != 0 ? ( this->dvp->nc_name != 0 ? stringof(this->dvp->nc_name) : "" ) : ""; } vfs::vop_remove:entry /this->dvp/ /* probe ID 6 (depth 3) */ { this->dvp = this->dvp->nc_dvp != NULL ? ( &(this->dvp->nc_dvp->v_cache_dst) != NULL ? this->dvp->nc_dvp->v_cache_dst.tqh_first : 0 ) : 0; this->name3 = this->dvp != 0 ? ( this->dvp->nc_name != 0 ? stringof(this->dvp->nc_name) : "" ) : ""; } vfs::vop_remove:entry /this->dvp/ /* probe ID 7 (depth 4) */ { this->dvp = this->dvp->nc_dvp != NULL ? ( &(this->dvp->nc_dvp->v_cache_dst) != NULL ? this->dvp->nc_dvp->v_cache_dst.tqh_first : 0 ) : 0; this->name4 = this->dvp != 0 ? ( this->dvp->nc_name != 0 ? stringof(this->dvp->nc_name) : "" ) : ""; } vfs::vop_remove:entry /this->dvp/ /* probe ID 8 (depth 5) */ { this->dvp = this->dvp->nc_dvp != NULL ? ( &(this->dvp->nc_dvp->v_cache_dst) != NULL ? this->dvp->nc_dvp->v_cache_dst.tqh_first : 0 ) : 0; this->name5 = this->dvp != 0 ? ( this->dvp->nc_name != 0 ? stringof(this->dvp->nc_name) : "" ) : ""; } vfs::vop_remove:entry /this->dvp/ /* probe ID 9 (depth 6) */ { this->dvp = this->dvp->nc_dvp != NULL ? ( &(this->dvp->nc_dvp->v_cache_dst) != NULL ? this->dvp->nc_dvp->v_cache_dst.tqh_first : 0 ) : 0; this->name6 = this->dvp != 0 ? ( this->dvp->nc_name != 0 ? stringof(this->dvp->nc_name) : "" ) : ""; } vfs::vop_remove:entry /this->dvp/ /* probe ID 10 (depth 7) */ { this->dvp = this->dvp->nc_dvp != NULL ? ( &(this->dvp->nc_dvp->v_cache_dst) != NULL ? this->dvp->nc_dvp->v_cache_dst.tqh_first : 0 ) : 0; this->name7 = this->dvp != 0 ? ( this->dvp->nc_name != 0 ? stringof(this->dvp->nc_name) : "" ) : ""; } vfs::vop_remove:entry /this->dvp/ /* probe ID 11 (depth 8) */ { this->dvp = this->dvp->nc_dvp != NULL ? ( &(this->dvp->nc_dvp->v_cache_dst) != NULL ? this->dvp->nc_dvp->v_cache_dst.tqh_first : 0 ) : 0; this->name8 = this->dvp != 0 ? ( this->dvp->nc_name != 0 ? stringof(this->dvp->nc_name) : "" ) : ""; } vfs::vop_remove:entry /this->dvp/ /* probe ID 12 (depth 9) */ { this->dvp = this->dvp->nc_dvp != NULL ? ( &(this->dvp->nc_dvp->v_cache_dst) != NULL ? this->dvp->nc_dvp->v_cache_dst.tqh_first : 0 ) : 0; this->name9 = this->dvp != 0 ? ( this->dvp->nc_name != 0 ? stringof(this->dvp->nc_name) : "" ) : ""; } vfs::vop_remove:entry /this->dvp/ /* probe ID 13 (depth 10) */ { this->dvp = this->dvp->nc_dvp != NULL ? ( &(this->dvp->nc_dvp->v_cache_dst) != NULL ? this->dvp->nc_dvp->v_cache_dst.tqh_first : 0 ) : 0; this->name10 = this->dvp != 0 ? ( this->dvp->nc_name != 0 ? stringof(this->dvp->nc_name) : "" ) : ""; } vfs::vop_remove:entry /this->dvp/ /* probe ID 14 (depth 11) */ { this->dvp = this->dvp->nc_dvp != NULL ? ( &(this->dvp->nc_dvp->v_cache_dst) != NULL ? this->dvp->nc_dvp->v_cache_dst.tqh_first : 0 ) : 0; this->name11 = this->dvp != 0 ? ( this->dvp->nc_name != 0 ? stringof(this->dvp->nc_name) : "" ) : ""; } vfs::vop_remove:entry /this->dvp/ /* probe ID 15 (depth 12) */ { this->dvp = this->dvp->nc_dvp != NULL ? ( &(this->dvp->nc_dvp->v_cache_dst) != NULL ? this->dvp->nc_dvp->v_cache_dst.tqh_first : 0 ) : 0; this->name12 = this->dvp != 0 ? ( this->dvp->nc_name != 0 ? stringof(this->dvp->nc_name) : "" ) : ""; } vfs::vop_remove:entry /this->dvp/ /* probe ID 16 (depth 13) */ { this->dvp = this->dvp->nc_dvp != NULL ? ( &(this->dvp->nc_dvp->v_cache_dst) != NULL ? this->dvp->nc_dvp->v_cache_dst.tqh_first : 0 ) : 0; this->name13 = this->dvp != 0 ? ( this->dvp->nc_name != 0 ? stringof(this->dvp->nc_name) : "" ) : ""; } vfs::vop_remove:entry /this->dvp/ /* probe ID 17 (depth 14) */ { this->dvp = this->dvp->nc_dvp != NULL ? ( &(this->dvp->nc_dvp->v_cache_dst) != NULL ? this->dvp->nc_dvp->v_cache_dst.tqh_first : 0 ) : 0; this->name14 = this->dvp != 0 ? ( this->dvp->nc_name != 0 ? stringof(this->dvp->nc_name) : "" ) : ""; } vfs::vop_remove:entry /this->dvp/ /* probe ID 18 (depth 15) */ { this->dvp = this->dvp->nc_dvp != NULL ? ( &(this->dvp->nc_dvp->v_cache_dst) != NULL ? this->dvp->nc_dvp->v_cache_dst.tqh_first : 0 ) : 0; this->name15 = this->dvp != 0 ? ( this->dvp->nc_name != 0 ? stringof(this->dvp->nc_name) : "" ) : ""; } vfs::vop_remove:entry /this->dvp/ /* probe ID 19 (depth 16) */ { this->dvp = this->dvp->nc_dvp != NULL ? ( &(this->dvp->nc_dvp->v_cache_dst) != NULL ? this->dvp->nc_dvp->v_cache_dst.tqh_first : 0 ) : 0; this->name16 = this->dvp != 0 ? ( this->dvp->nc_name != 0 ? stringof(this->dvp->nc_name) : "" ) : ""; } vfs::vop_remove:entry /this->dvp/ /* probe ID 20 (depth 17) */ { this->dvp = this->dvp->nc_dvp != NULL ? ( &(this->dvp->nc_dvp->v_cache_dst) != NULL ? this->dvp->nc_dvp->v_cache_dst.tqh_first : 0 ) : 0; this->name17 = this->dvp != 0 ? ( this->dvp->nc_name != 0 ? stringof(this->dvp->nc_name) : "" ) : ""; } vfs::vop_remove:entry /this->dvp/ /* probe ID 21 (depth 18) */ { this->dvp = this->dvp->nc_dvp != NULL ? ( &(this->dvp->nc_dvp->v_cache_dst) != NULL ? this->dvp->nc_dvp->v_cache_dst.tqh_first : 0 ) : 0; this->name18 = this->dvp != 0 ? ( this->dvp->nc_name != 0 ? stringof(this->dvp->nc_name) : "" ) : ""; } vfs::vop_remove:entry /this->dvp/ /* probe ID 22 (depth 19) */ { this->dvp = this->dvp->nc_dvp != NULL ? ( &(this->dvp->nc_dvp->v_cache_dst) != NULL ? this->dvp->nc_dvp->v_cache_dst.tqh_first : 0 ) : 0; this->name19 = this->dvp != 0 ? ( this->dvp->nc_name != 0 ? stringof(this->dvp->nc_name) : "" ) : ""; } vfs::vop_remove:entry /this->dvp/ /* probe ID 23 (depth 20) */ { this->dvp = this->dvp->nc_dvp != NULL ? ( &(this->dvp->nc_dvp->v_cache_dst) != NULL ? this->dvp->nc_dvp->v_cache_dst.tqh_first : 0 ) : 0; this->name20 = this->dvp != 0 ? ( this->dvp->nc_name != 0 ? stringof(this->dvp->nc_name) : "" ) : ""; } /* * END Pathname-depth iterators */ /*********************************************************/ vfs::vop_remove:entry /this->fi_mount != 0/ /* probe ID 24 */ { printf("%Y %s[%d]: ", timestamp + 1406598400000000000, execname, pid); /* * Print full path of file to delete * NB: Up-to but not including the parent directory (printed below) */ printf("%s%s", this->fi_mount, this->fi_mount != 0 ? ( this->fi_mount == "/" ? "" : "/" ) : "/"); printf("%s%s", name = this->name20, name != "" ? "/" : ""); printf("%s%s", name = this->name19, name != "" ? "/" : ""); printf("%s%s", name = this->name18, name != "" ? "/" : ""); printf("%s%s", name = this->name17, name != "" ? "/" : ""); printf("%s%s", name = this->name16, name != "" ? "/" : ""); printf("%s%s", name = this->name15, name != "" ? "/" : ""); printf("%s%s", name = this->name14, name != "" ? "/" : ""); printf("%s%s", name = this->name13, name != "" ? "/" : ""); printf("%s%s", name = this->name12, name != "" ? "/" : ""); printf("%s%s", name = this->name11, name != "" ? "/" : ""); printf("%s%s", name = this->name10, name != "" ? "/" : ""); printf("%s%s", name = this->name9, name != "" ? "/" : ""); printf("%s%s", name = this->name8, name != "" ? "/" : ""); printf("%s%s", name = this->name7, name != "" ? "/" : ""); printf("%s%s", name = this->name6, name != "" ? "/" : ""); printf("%s%s", name = this->name5, name != "" ? "/" : ""); printf("%s%s", name = this->name4, name != "" ? "/" : ""); printf("%s%s", name = this->name3, name != "" ? "/" : ""); printf("%s%s", name = this->name2, name != "" ? "/" : ""); printf("%s%s", name = this->name1, name != "" ? "/" : ""); /* Print the parent directory name */ name = this->d_name != 0 ? this->d_name : ""; printf("%s%s", name, name != "" ? "/" : ""); /* Print the entry name */ name = this->fi_name != 0 ? this->fi_name : ""; printf("%s", name); printf("\n"); /* * Examine process, parent process, and grandparent process details */ /******************* CURPROC *******************/ proc = curthread->td_proc; pid0 = proc->p_pid; uid0 = proc->p_ucred->cr_uid; gid0 = proc->p_ucred->cr_rgid; p_args = proc->p_args; ar_length = p_args ? p_args->ar_length : 0; ar_args = (char *)(p_args ? p_args->ar_args : 0); arg0_0 = ar_length > 0 ? ar_args : stringof(proc->p_comm); len = ar_length > 0 ? strlen(ar_args) + 1 : 0; ar_args += len; ar_length -= len; arg0_1 = ar_length > 0 ? ar_args : ""; len = ar_length > 0 ? strlen(ar_args) + 1 : 0; ar_args += len; ar_length -= len; arg0_2 = ar_length > 0 ? ar_args : ""; len = ar_length > 0 ? strlen(ar_args) + 1 : 0; ar_args += len; ar_length -= len; arg0_3 = ar_length > 0 ? ar_args : ""; len = ar_length > 0 ? strlen(ar_args) + 1 : 0; ar_args += len; ar_length -= len; arg0_4 = ar_length > 0 ? "..." : ""; /******************* PPARENT *******************/ proc = proc->p_pptr; pid1 = proc->p_pid; uid1 = proc->p_ucred->cr_uid; gid1 = proc->p_ucred->cr_rgid; p_args = proc ? proc->p_args : 0; ar_length = p_args ? p_args->ar_length : 0; ar_args = (char *)(p_args ? p_args->ar_args : 0); offset = 0; arg1_0 = ar_length > 0 ? ar_args : stringof(proc->p_comm); len = ar_length > 0 ? strlen(ar_args) + 1 : 0; ar_args += len; ar_length -= len; arg1_1 = ar_length > 0 ? ar_args : ""; len = ar_length > 0 ? strlen(ar_args) + 1 : 0; ar_args += len; ar_length -= len; arg1_2 = ar_length > 0 ? ar_args : ""; len = ar_length > 0 ? strlen(ar_args) + 1 : 0; ar_args += len; ar_length -= len; arg1_3 = ar_length > 0 ? ar_args : ""; len = ar_length > 0 ? strlen(ar_args) + 1 : 0; ar_args += len; ar_length -= len; arg1_4 = ar_length > 0 ? "..." : ""; /******************* GPARENT *******************/ proc = proc->p_pptr; pid2 = proc->p_pid; uid2 = proc->p_ucred->cr_uid; gid2 = proc->p_ucred->cr_rgid; p_args = proc ? proc->p_args : 0; ar_length = p_args ? p_args->ar_length : 0; ar_args = (char *)(p_args ? p_args->ar_args : 0); offset = 0; arg2_0 = ar_length > 0 ? ar_args : stringof(proc->p_comm); len = ar_length > 0 ? strlen(ar_args) + 1 : 0; ar_args += len; ar_length -= len; arg2_1 = ar_length > 0 ? ar_args : ""; len = ar_length > 0 ? strlen(ar_args) + 1 : 0; ar_args += len; ar_length -= len; arg2_2 = ar_length > 0 ? ar_args : ""; len = ar_length > 0 ? strlen(ar_args) + 1 : 0; ar_args += len; ar_length -= len; arg2_3 = ar_length > 0 ? ar_args : ""; len = ar_length > 0 ? strlen(ar_args) + 1 : 0; ar_args += len; ar_length -= len; arg2_4 = ar_length > 0 ? "..." : ""; /***********************************************/ /* * Print process, parent, and grandparent details */ printf(" -+= %05d %d.%d %s", pid2, uid2, gid2, arg2_0); printf("%s%s", arg2_1 != "" ? " " : "", arg2_1); printf("%s%s", arg2_2 != "" ? " " : "", arg2_2); printf("%s%s", arg2_3 != "" ? " " : "", arg2_3); printf("%s%s", arg2_4 != "" ? " " : "", arg2_4); printf("%s", arg2_0 != "" ? "\n" : ""); printf(" \-+= %05d %d.%d %s", pid1, uid1, gid1, arg1_0); printf("%s%s", arg1_1 != "" ? " " : "", arg1_1); printf("%s%s", arg1_2 != "" ? " " : "", arg1_2); printf("%s%s", arg1_3 != "" ? " " : "", arg1_3); printf("%s%s", arg1_4 != "" ? " " : "", arg1_4); printf("%s", arg1_0 != "" ? "\n" : ""); printf(" \-+= %05d %d.%d %s", pid0, uid0, gid0, arg0_0); printf("%s%s", arg0_1 != "" ? " " : "", arg0_1); printf("%s%s", arg0_2 != "" ? " " : "", arg0_2); printf("%s%s", arg0_3 != "" ? " " : "", arg0_3); printf("%s%s", arg0_4 != "" ? " " : "", arg0_4); printf("%s", arg0_0 != "" ? "\n" : ""); }
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?04f001d01004$abaefd30$030cf790$>