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

[Nick Alcock]

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 :)

> ---
>  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 :)

> 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.

> +# 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

(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