dtrace discuss - Jan 2008 - DTrace Provider for Bourne Shell [PSARC/2008/008 FastTrack timeout 01/16/2008]

Given that you''re tracing setting a variable, isn''t it also
worthwhile generating an event for "unset"?

e.g. if a dtrace script is following variable assignments
and my shell script does this:

FOO=bar
unset FOO
echo ${FOO}

the dtrace script''s idea of the state of affairs when echo
is executed is going to be quite different to the shell''s.

Darren

As promised based on Darren''s suggestion, I have updated the spec and 
included it below.

Changes
-------
1. The variable-assign probe has been renamed to variable-set.
2. Added the variable-unset probe
3. Corrected a typo in the probe list.

In the light of adding variable-unset, it seems to m e that the name 
variable set is more consistent than variable-assign.

Regards,
Alan.

========================
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-assign Fires on assignment to a variable.

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

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



-- 
Alan Hargreaves - http://blogs.sun.com/tpenta
Staff Engineer (Kernel/VOSJEC/Performance)
Systems Technical Support Centre
Sun Microsystems

Reposting as I just had another problem pointed out to me, in that I 
left variable-assign in the initial list of probes and forgot to add in 
the new variable-set. Thanks Michael.

alan.

Alan Hargreaves wrote:
> As promised based on Darren''s suggestion, I have updated the spec
and
> included it below.
> 
> Changes
> -------
> 1. The variable-assign probe has been renamed to variable-set.
> 2. Added the variable-unset probe
> 3. Corrected a typo in the probe list.
> 
> In the light of adding variable-unset, it seems to m e that the name 
> variable set is more consistent than variable-assign.
> 
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

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


-- 
Alan Hargreaves - http://blogs.sun.com/tpenta
Staff Engineer (Kernel/VOSJEC/Performance)
Systems Technical Support Centre
Sun Microsystems

And of course I now see that I missed a line out cutting and pasting the 
first example. Rather than repost the whole thing it is included below.
> 1. Catching a variable assignment
  ...
>     $ ./watch.d -c ./var.sh
>     4: WatchedVar=Value
> 
	5: unset WatchedVar

Alan
-- 
Alan Hargreaves - http://blogs.sun.com/tpenta
Staff Engineer (Kernel/VOSJEC/Performance)
Systems Technical Support Centre
Sun Microsystems

Joseph Kowalski wrote:
> Alan Hargreaves wrote:
>> I am sponsoring the following fast track for myself.
> How will this be documented?  Some of the materials look like
> EXAMPLES, but I''m not sure where...
> 
> - jek3
> 
I am currently taking the spec and turning it into documentation for the 
  Reference Manual Wiki.

alan.

-- 
Alan Hargreaves - http://blogs.sun.com/tpenta
Staff Engineer (Kernel/VOSJEC/Performance)
Systems Technical Support Centre
Sun Microsystems

Alan Hargreaves wrote:
> Joseph Kowalski wrote:
>> Alan Hargreaves wrote:
>>> I am sponsoring the following fast track for myself.
>> How will this be documented?  Some of the materials look like
>> EXAMPLES, but I''m not sure where...
>>
>> - jek3
>>
> 
> I am currently taking the spec and turning it into documentation for the 
>  Reference Manual Wiki.
> 
> alan.
> 
There is documentation up (amazingly similar to the case funnily enough) 
under the proposed providers section at http://wikis.sun.com at 
http://wikis.sun.com/display/DTrace/sh+Provider

alan.
-- 
Alan Hargreaves - http://blogs.sun.com/tpenta
Staff Engineer (Kernel/VOSJEC/Performance)
Systems Technical Support Centre
Sun Microsystems

This case was approved in the meeting today.

alan.
-- 
Alan Hargreaves - http://blogs.sun.com/tpenta
Staff Engineer (Kernel/VOSJEC/Performance)
Systems Technical Support Centre
Sun Microsystems

Hello Alan,

Wednesday, January 9, 2008, 6:19:19 PM, you wrote:

AH> This case was approved in the meeting today.

AH> alan.


good.

btw: have you measured for severa scripts what''s the performance
impact of sh with and without usdt provider probes?
Shouldn''t by much but still...

-- 
Best regards,
 Robert Milkowski                           mailto:rmilkowski at task.gda.pl
                                       http://milek.blogspot.com

Robert Milkowski wrote:
> Hello Alan,
> 
> Wednesday, January 9, 2008, 6:19:19 PM, you wrote:
> 
> AH> This case was approved in the meeting today.
> 
> AH> alan.
> 
> 
> good.
> 
> btw: have you measured for severa scripts what''s the performance
> impact of sh with and without usdt provider probes?
> Shouldn''t by much but still...
> 
I have not measured, but the probes really are miniscule.

alan.
-- 
Alan Hargreaves - http://blogs.sun.com/tpenta
Staff Engineer (Kernel/VOSJEC/Performance)
Systems Technical Support Centre
Sun Microsystems