Alan Hargreaves' Weblog

PSARC 2008/008 DTrace Provider for Bourne Shell

I finally got to submit the fast track for the shell provider. I've already had one comment (from Darren Reed) that I have incorporated as it made very good sense. He suggested that if we are tracking variable assignments, we should also track unset. At this point I realised that a better name for the probes would be variable-set and variable-unset. I have a working copy for SPARC with these changes now.

Below is the prefix text and the revised specification.

I am sponsoring the following fast track for myself. I am doing the
bourne shell first for two primary reasons.

1. It is the "simplest" of the shells and thus should provide the
   minimum set of probes to implement for future work in other shells,
2. Providing probes into /bin/sh gives us observability of
   approximately 60% of all of the scripts on ON.

Additionally, as it has been around for a very long time there are
quite a lot of user written scripts for it, many very badly written.

I would expect future fast tracks for other shells (eg ksh88, ksh93,
zsh, bash, ...) to reference this fast track for the minimum set of
probes.

Note the probes are currently listed as Uncommitted. As the probes
gain use I would hope to log a future fast track to increase this
stability.

A Minor release binding is initially requested. Again, once things
settle down and the interfaces stabilise it is expected that a future
case may request a patch binding.

The sh provider makes available probes that can be used to observe the
behaviour of bourne shell scripts.

Probes
------

The sh provider makes available the following probes as exports:

builtin-entry   Fires on entry to a shell builtin command.
builtin-return  Fires on return from a shell builtin command.
command-entry   Fires when the shell execs an external command.
command-return  Fires on return from an external command.
function-entry  Fires on entry into a shell function.
function-return Pires on return from a shell function.
line            Fires before commands on a particular line of code are
		executed.
subshell-entry  Fires when the shell forks a subshell.
subshell-return Fires on return from a forked subshell.
script-start    Fires before any commands in a script are executed.
script-done     Fires on script exit.
variable-set	Fires on assignment to a variable.
variable-unset	Fires when a variable is unset.

The use of non-empty module or function names in a sh* probe is
undefined at this time.

Arguments
---------

builtin-entry,
command-entry,
function-entry

	char *	args[0]	Script Name
	char *	args[1]	Builtin/Command/Function Name
	int	args[2]	Line Number
	int	args[3]	# Arguments
	char **	args[4]	Pointer to argument list

builtin-return,
command-return,
function-return

	char *	args[0]	Script Name
	char *	args[1]	Builtin/Command/Function Name
	int	args[2]	Return Value

subshell-entry

	char *	args[0]	Script Name
	pid_t	args[1]	Forked Process ID

subshell-return

	char *	args[0]	Script Name
	int	args[1]	Return Value

line

	char *	args[0]	Script Name
	int	args[1]	Line Number

script-start

	char *	args[0]	Script Name

script-done

	char *	args[0]	Script Name
	int	args[1]	Exit Value

variable-set

	char *	args[0]	Script Name
	char *	args[1]	Variable Name
	char *	args[2]	Value

variable-unset

	char *	args[0] Script Name
	char *	args[1]	Variable Name

Examples
--------

1. Catching a variable assignment

	Say we want to determine which line in the following script has
	an assignment to WatchedVar:

	#!/bin/sh

	# starting script
	WatchedVar=Value
	unset WatchedVar
	# ending script

	We could use the following script

	#!/usr/sbin/dtrace -s

	#pragma D option quiet

	sh$target:::line { self->line = arg1; }
	sh$target:::variable-set /copyinstr(arg1) == "WatchedVar"/ {
	        printf("%d: %s=%s\n", self->line, copyinstr(arg1),
		    copyinstr(arg2))
	}
	sh$target:::variable-unset /copyinstr(arg1) == "WatchedVar"/ {
	        printf("%d: unset %s\n", self->line, copyinstr(arg1)); }


	$ ./watch.d -c ./var.sh
	4: WatchedVar=Value
	5: unset WatchedVar

2. Watching the time spent in functions

	#!/usr/sbin/dtrace -s

	#pragma D option quiet

	sh$target:::function-entry { self->start = vtimestamp }
	sh$target:::function-return {
		@[copyinstr(arg1)] = quantize(vtimestamp - self->start)
	}

	Similar for the other entry/return probes, with the exception
	of subshell as the probe name is unavailable.

3. Wasted time using external functions instead of builtins

	This script is copied from the DTrace toolkit. It's function
	and how it works should be relatively self explanatory.

#!/usr/sbin/dtrace -Zs
/*
 * sh_wasted.d - measure Bourne shell elapsed times for "wasted" commands.
 *               Written for the sh DTrace provider.
 *
 * $Id: sh_wasted.d 25 2007-09-12 09:51:58Z brendan $
 *
 * USAGE: sh_wasted.d { -p PID | -c cmd }       # hit Ctrl-C to end
 *
 * This script measures "wasted" commands - those which are called externally
 * but are in fact builtins to the shell. Ever seen a script which calls
 * /usr/bin/echo needlessly? This script measures that cost.
 *
 * FIELDS:
 *              FILE            Filename of the shell or shellscript
 *              NAME            Name of call
 *              TIME            Total elapsed time for calls (us)
 *
 * IDEA: Mike Shapiro
 *
 * Filename and call names are printed if available.
 *
 * COPYRIGHT: Copyright (c) 2007 Brendan Gregg.
 *
 * CDDL HEADER START
 *
 *  The contents of this file are subject to the terms of the
 *  Common Development and Distribution License, Version 1.0 only
 *  (the "License").  You may not use this file except in compliance
 *  with the License.
 *
 *  You can obtain a copy of the license at Docs/cddl1.txt
 *  or http://www.opensolaris.org/os/licensing.
 *  See the License for the specific language governing permissions
 *  and limitations under the License.
 *
 * CDDL HEADER END
 *
 * 09-Sep-2007  Brendan Gregg   Created this.
 */

#pragma D option quiet

dtrace:::BEGIN
{
        isbuiltin["echo"] = 1;
        isbuiltin["test"] = 1;
        /* add builtins here */

        printf("Tracing... Hit Ctrl-C to end.\n");
        self->start = timestamp;
}

sh$target:::command-entry
{
        self->command = timestamp;
}

sh$target:::command-return
{
        this->elapsed = timestamp - self->command;
        this->path = copyinstr(arg1);
        this->cmd = basename(this->path);
}

sh$target:::command-return
/self->command && !isbuiltin[this->cmd]/
{
        @types_cmd[basename(copyinstr(arg0)), this->path] = sum(this->elapsed);
        self->command = 0;
}

sh$target:::command-return
/self->command/
{
        @types_wasted[basename(copyinstr(arg0)), this->path] =
            sum(this->elapsed);
        self->command = 0;
}

proc:::exit
/pid == $target/
{
        exit(0);
}

dtrace:::END
{
        this->elapsed = (timestamp - self->start) / 1000;
        printf("Script duration: %d us\n", this->elapsed);

        normalize(@types_cmd, 1000);
        printf("\nExternal command elapsed times,\n");
        printf("   %-30s %-22s %8s\n", "FILE", "NAME", "TIME(us)");
        printa("   %-30s %-22s %@8d\n", @types_cmd);

        normalize(@types_wasted, 1000);
        printf("\nWasted command elapsed times,\n");
        printf("   %-30s %-22s %8s\n", "FILE", "NAME", "TIME(us)");
        printa("   %-30s %-22s %@8d\n", @types_wasted);
}


Stability
---------

Element Name    Class           Data Class
------------------------------------------
Provider        Uncommited      Uncommited
Module          Private         Private
Function        Private         Private
Name            Uncommited      Uncommited
Arguments       Uncommited      Uncommited
------------------------------------------

Technorati Tags: Solaris, OpenSolaris, DTrace

Posted at 09:27AM Jan 09, 2008 by Alan Hargreaves in OpenSolaris  |