[DTrace-devel] [PATCH] test: clean up orphaned tracing events between tests

[Kris Van Hees]

On Wed, Jun 07, 2023 at 11:09:45AM +0100, Nick Alcock wrote:
> On 7 Jun 2023, Kris Van Hees via DTrace-devel outgrape:
> 
> > Signed-off-by: Kris Van Hees <kris.van.hees at oracle.com>
> 
> Significant changes suggested below: equally significant reduction in
> runtime expected :)

The reduction in runtime is actually minimal, but improvements are welcome
either way.  But... not really significant in the overall cost of the
testsuite by any means.

I'll send a v2.

> > ---
> >  runtest.sh                 |   2 +
> >  test/utils/Build           |   2 +-
> >  test/utils/clean_probes.sh | 102 +++++++++++++++++++++++++++++++++++++
> >  3 files changed, 105 insertions(+), 1 deletion(-)
> >  create mode 100755 test/utils/clean_probes.sh
> >
> > diff --git a/runtest.sh b/runtest.sh
> > index a39a1c91..17589d85 100755
> > --- a/runtest.sh
> > +++ b/runtest.sh
> > @@ -1500,6 +1500,8 @@ for dt in $dtrace; do
> >              cp -f $tmpdir/test.out $base.r
> >          fi
> >  
> > +	test/utils/clean_probes.sh >> $LOGFILE
> > +
> 
> Total pedantry: runtest.sh uses spaces, not tabs :)

OK - why?

> > diff --git a/test/utils/clean_probes.sh b/test/utils/clean_probes.sh
> > new file mode 100755
> > index 00000000..5e931232
> > --- /dev/null
> > +++ b/test/utils/clean_probes.sh
> > @@ -0,0 +1,102 @@
> > +#!/usr/bin/bash
> > +
> > +TRACEFS=/sys/kernel/debug/tracing
> > +EVENTS=${TRACEFS}/available_events
> > +KPROBES=${TRACEFS}/kprobe_events
> > +UPROBES=${TRACEFS}/uprobe_events
> > +
> > +# Check permissions
> > +if [ ! -r ${EVENTS} ]; then
> 
> Throughout: [ is (much) slower than [[ in bash and has awful semantics.
> [[ ... ]] is almost always preferable.

OK.

> > +# Scan the list of events for any orphaned DTrace probes
> > +(
> > +	ps -e
> 
> Rather than using a ps -e and then parsing the heck out of it, why not
> do something like

Um... "parsing the heck out of it" ??  The AWK script was checking the number
of fields in the input line and then looked for /dtrace/.  That's more like
minimal parsing.

But anyway, I like your suuggestion of using a more specific ps command.

> (ps -C dtrace -o pid=
>  echo ===
>  cat ${EVENTS})
> 
> and then accumulate everything you see into pids, then match on /---/
> and treat everything later as an event? Actually we don't even need (),
> we're not changing anything that uses a subprocess: {} is enough.
> 
> This is really quite a lot faster, too -- ps has to do less work, and
> it doesn't collect things it doesn't have to:
> 
> oranix at loom 3010$ strace ps -e 2>&1 >/dev/null | wc -l
> 19372
> oranix at loom 3011$ strace ps -e -o pid 2>&1 >/dev/null | wc -l
> 11576
> oranix at loom 3012$ ps -C dtrace -o pid 2>&1 >/dev/null | wc -l
> 9830
> 
> So... something like:
> 
> { ps -C dtrace -o pid=; echo ===; cat ${EVENTS}; } |
>     awk -v tracefs=${TRACEFS} \
>         'BEGIN { events = 0; }
>         /^===$/ { events = 1; next; }
>         !events { pids = pids "|" int($1); next; }
> 
> ... and then something else, because I'll admit I have no idea what's
> going on in most of the rest of it, !processing and below: it's
> presumably uprobe_events stuff which is probably pretty much ok as is,
> or at least probably not too expensive and too complex like the
> ps-parsing stuff. (I'm not even sure why the variable 'processing'
> exists.)
> 
> (btw, did you know that the format of ps sans -o depends on an
> environment variable, PS_FORMAT? Always, always use -o when using ps in
> scripts.)
> 
> (original below for comparison)
> 
> > +	cat ${EVENTS}
> > +) | \
> > +	awk -v tracefs=${TRACEFS} \
> > +	    'function getTimestamp(dt) {
> > +#		 cmd = "date --rfc-3339=ns";
> > +		 cmd = "date +\"%s.%N\"";
> > +		 cmd | getline dt;
> > +		 close(cmd);
> > +		 return dt;
> > +	     }
> > +
> > +	     function timeDiff(t0, t1, s0, n0, s1, n1) {
> > +		 tmp = $0;
> > +
> > +		 $0 = t0;
> > +		 sub(/\./, " ");
> > +		 s0 = int($1);
> > +		 n0 = int($2);
> > +		 $0 = t1;
> > +		 sub(/\./, " ");
> > +		 s1 = int($1);
> > +		 n1 = int($2);
> > +
> > +		 if (n1 < n0) {
> > +		     s1--;
> > +		     n1 += 1000000000;
> > +		 }
> > +
> > +		 $0 = tmp;
> > +
> > +		 return sprintf("%d.%09d", s1 - s0, n1 - n0);
> > +	     }
> > +
> > +	     BEGIN { start = getTimestamp(); }
> > +
> > +	     NF > 1 {
> > +		 if (/dtrace/)
> > +		     pids = pids "|" int($1);
> > +		 next;
> > +	     }
> > +
> > +	     !processing {
> > +		 re = "^dt_" substr(pids, 2) "_";
> > +		 processing = 1;
> > +	     }
> > +
> > +	     $1 !~ /^dt_[0-9]/ { next; }
> > +	     $1 ~ re { next; }
> > +	     { sub(/:/, "/"); }
> > +
> > +	     {
> > +		 if (/_fbt_/)
> > +		     kpv[kpc++] = $0;
> > +		 else
> > +		     upv[upc++] = $0;
> > +	     }
> > +
> > +	     END {
> > +		 fn = tracefs"/kprobe_events";
> > +		 for (i = 0; i < kpc; i++) {
> > +		     print "-:"kpv[i] >> fn;
> > +		     if (i % 20 == 19)
> > +			 close(fn);
> > +		 }
> > +		 close(fn);
> > +
> > +		 fn = tracefs"/uprobe_events";
> > +		 for (i = 0; i < upc; i++) {
> > +		     print "-:"upv[i] >> fn;
> > +		     if (i % 20 == 19)
> > +			 close(fn);
> > +		 }
> > +		 close(fn);
> > +
> > +		 diff = timeDiff(start, getTimestamp());
> > +		 txt = sprintf(" (%d kprobes, %d uprobes)", kpc, upc);
> > +		 print "Cleaning took " diff txt;
> > +	     }'
> > +
> > +exit 0