Wednesday Sep 25, 2013

Counting how many threads a cv_broadcast wakes up

I had occasion during a call this week to want to observe what was causing a lot of threads to suddenly be made runnable, and thought I should share the DTrace that I wrote to do it. It's using the fbt provider so don't even think about considering the interfaces stable :)

# dtrace -q -x dynvarsize=4m -n '
BEGIN {trace("Monitoring ..\n"); }
fbt::cv_broadcast:entry {self->cv = (condvar_impl_t *)arg0; }
fbt::cv_broadcast:entry /self->cv && self->cv->cv_waiters>500/ {
       printf("%Y [%d] %s %d woken\n", walltimestamp, pid, execname, self->cv->cv_waiters);
       stack();}
fbt::cv_broadcast:entry /self->cv/ {self->cv = 0;}' 

I needed to make the dynvarsize 4m as I was running this on a pretty large machine so we were getting a lot of thread local variables created and destroyed.

I was rewarded with output like

Monitoring ..                                                                                                                       
2013 Sep 23 15:20:49 [0] sched 1024 woken

              vxfs`vx_sched_thread+0x131c
              unix`thread_start+0x4
2013 Sep 23 15:21:28 [0] sched 1024 woken

              vxfs`vx_sched_thread+0x131c
              unix`thread_start+0x4
2013 Sep 23 15:26:47 [0] sched 1024 woken

Posting in case anyone else has found themselves wanting to find out this kind of thing. Happy DTracing all.

Tuesday Nov 18, 2008

Even More DTrace Lab Answers (9 & 10)

OK, let's get the rest out.

Exercise 9

List the processes that are connecting to a specific port.

OK, we'll take that to mean we want to know the name and the process ID of connections to a particular port. This requires just a little network programming knowledge. We can see that the second argument (arg1) to connect(3SOCKET) is a sockaddr. The extra knowledge that we need is that to get a port, we need to cast it to a sockaddr_in and look at the port structure element. This bit of code expects the command line argument 1 to be a port number.

#!/usr/sbin/dtrace -s

#pragma D option quiet

syscall::connect:entry {
	this->sock = (struct sockaddr_in \*)copyin(arg1, arg2);
	self->port = this->sock->sin_port;
}
syscall::connect:entry /self->port == $1/ {
	 printf("%5d %s\\n", pid, execname); }

syscall::connect:entry { self->port = 0; }

Exercise 10

Write a script to show where a specific system call, rename for example, is blocking and how long it is blocked for.

This one was a bit of fun to write, especially since the output format specifier for a stack is not documented and I had to find it in dt_printf.c.

We'll use the sched provider in this. While it would be nice to use the wakeup probe, it's not fired from the thread context so we won't have the thread local variable that we need to check and use. So, we just use on-cpu, which will tell us how long we were off cpu since we were told to block. Note that this also means that we are not tracking normal scheduling where it may have been pre-empted by another thread for whatever reason. This is what we want.

#!/usr/sbin/dtrace -s

#pragma D option quiet

BEGIN { printf("Collecting...  \^C to continue\\n"); }

syscall::rename:entry {self->interest = 1; }
sched:::sleep /self->interest/ { self->blocktime = timestamp; }
sched:::on-cpu /self->blocktime/ {
	this->taken = timestamp - self->blocktime; 
	@[curthread,stack()] = quantize(this->taken);
	self->blocktime = 0;
}
syscall::rename:return { self->interest = 0; }

END { printa("Thread 0x%p %k %@d\\n", @); }

This leaves us with only Exercise 11 to go. I'll try to get that up tomorrow.

Saturday Nov 15, 2008

More DTrace Lab Answers

OK, I promised more answers so here we go, ... (sorry, where files have copyright notices, I have to leave them there).

Exercise 2

Restrict the iosnoop.d to trace a specific process.

This solution will allow you to either specify a pid by appending '-p {pid}' or to run a command by appending '-c "command args ..." to the command line. eg dtrace -s iosnoop.d -p 1234

/\*
 \* 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 usr/src/OPENSOLARIS.LICENSE
 \* or http://www.opensolaris.org/os/licensing.
 \* See the License for the specific language governing permissions
 \* and limitations under the License.
 \*
 \* When distributing Covered Code, include this CDDL HEADER in each
 \* file and include the License file at usr/src/OPENSOLARIS.LICENSE.
 \* If applicable, add the following below this CDDL HEADER, with the
 \* fields enclosed by brackets "[]" replaced with your own identifying
 \* information: Portions Copyright [yyyy] [name of copyright owner]
 \*
 \* CDDL HEADER END
 \*/
/\*
 \* Copyright 2005 Sun Microsystems, Inc.  All rights reserved.
 \* Use is subject to license terms.
 \*
 \* This D script is used as an example in the Solaris Dynamic Tracing Guide
 \* wiki in the "io Provider" Chapter.
 \*
 \* The full text of the this chapter may be found here:
 \*
 \*   http://wikis.sun.com/display/DTrace/io+Provider
 \*
 \* On machines that have DTrace installed, this script is available as
 \* iosnoop.d in /usr/demo/dtrace, a directory that contains all D scripts
 \* used in the Solaris Dynamic Tracing Guide.  A table of the scripts and their
 \* corresponding chapters may be found here:
 \*
 \*   file:///usr/demo/dtrace/index.html
 \*/

#pragma D option quiet

BEGIN
{
	printf("%10s %58s %2s\\n", "DEVICE", "FILE", "RW");
}

io:::start
/pid == $target/
{
	printf("%10s %58s %2s\\n", args[1]->dev_statname,
	    args[2]->fi_pathname, args[0]->b_flags & B_READ ? "R" : "W");
}

Exercise 3

Display the arguments for the rename(2) system call along with its return code.

This is longer than it needs to be as I like the idea of a single line of output for each time the we have a rename() system call. I save the two arguments in thread local variables (self->source and self->destination). Note that the two arguments are strings and they are in user space when this probe fires, so we use copyinstr() to both get them into kernel context and make them printable strings. Note also that we clean up after ourselves in the return probe.

#!/usr/sbin/dtrace -s

#pragma D option quiet

syscall::rename:entry {
	self->source = copyinstr(arg0);
	self->destination = copyinstr(arg1);
}
syscall::rename:return {
	printf("%s: %s -> %s returned %d\\n", probefunc, self->source,
	    self->destination, arg1);
	self->source = self->destination = 0;
}

Exercise 4

Display the real and sys times (see timex(1)) for the syscall

I'm not completely happy with this as I saw some anomalous real time values running this on my notebook, but it should be about right. Note that we record a walltimestamp (seconds since epoch) and the vtimestamp (time on cpu in nanoseconds) and simply compare them in the return probe.

#!/usr/sbin/dtrace -s

#pragma D option quiet

syscall:::entry {
	self->seconds = walltimestamp;
	self->sys = vtimestamp;
}
syscall:::return /self->sys/ {
	printf("%s: %d real seconds, %dns system\\n",
            probefunc,
            walltimestamp - self->seconds,
            vtimestamp - self->sys);
	self->seconds = self->sys = 0;
}

Exercise 5

Show the kernel function name that triggers the io:::start probe.

Many folks did this using stack(). There is a better way. This makes use of the fact that in the io provider, the probe\* values are defined.

$ pfexec dtrace -qn 'io:::start {printf("iostart:::probefunc called from %s\\n",probefunc);}'
iostart:::probefunc called from bdev_strategy
...

You could also simply use the default action without -q as that will print the probe specification each time it fires, which will include the probefunc.

Exercise 6

Show the flow of kernel functions for a write system call.

Most folks put a -F in the arguments on line 1. The clearer (and more correct) way to do this in a script is to use the pragma (highlighted).

#!/usr/sbin/dtrace -s

#pragma D option flowindent

syscall::write:entry { self->interest = 1; }
fbt::: /self->interest/ {}
syscall::write:return { self->interest = 0; }

Exercise 7

Show all lock events for mutexes that occur during two second.

The question hints that we may want to use an aggregation and summary rather than printing them as they happen.

#!/usr/sbin/dtrace -s3

#pragma D option quiet

lockstat:::adaptive\* {@[probename] = count();}
tick-2s {exit(0);}

Exercise 8

Find file to which most IO is being done.

I'm going to assume that the question means real IO, not IOs that hit the cache. In which case, we can use the answer to exercise 2 as a hint. Unfortunately, pretty much all of the IO that this tracks is being done by sched to flush buffers and we don't have any idea of the filename. I'll try to come up with a better solution.

#!/usr/sbin/dtrace -s

#pragma D option quiet

BEGIN { printf("Collecting data ... \^C to finish.\\n"); }
io:::start { @[args[2]->fi_pathname] = count(); }
END { trunc(@,1); printa(@); }

That's it for the moment, I'll finish them off later.

Friday Nov 14, 2008

DTrace Lab in the performance track at CEC

We have just been helping out in the DTrace lab for the performance track at CEC. On having a look at exercise 1, we suggested to the attendees that they attempt the other exercises and come back to this one. The exercise was:

Enhance /usr/demo/dtrace/iosnoop to be able to detect reads that are satisfied by the filesystem cache (UFS: pagecache).

We then went off to write our own versions of an answer to the problem.I started from scratch, and (referring back to a previous blog where I did some digging into this code), came up with the following:

#!/usr/sbin/dtrace -s

#pragma D option quiet

BEGIN { printf("Collecting ...\\n"); }

syscall::read\*:entry {
        self->interest = 1;
        self->file = fds[arg0].fi_name;
        self->phys = 0;
}

/\* we only increment this kstat if we have to go to disk, from a filesystem \*/

sysinfo:::bread /self->interest/ { self->phys = 1;}

syscall::read\*:return /self->interest/ {
        this->str = self->phys
            ? "Physical reads"
            : "Cache Reads";
        @[this->str, self->file] = count();
        self->interest = 0;
}

END { printa("%@6d %s %s\\n", @); }

On running this you get output like:

   ...
   209 Cache Reads jaxrpc-impl.jar
   211 Cache Reads appserv-admin.jar
   311 Cache Reads xalan.jar
   354 Cache Reads ttysrch
   372 Cache Reads jaxr-impl.jar
   373 Cache Reads auxv
   500 Cache Reads appserv-assemblytool.jar
  1216 Cache Reads 
  1324 Cache Reads appserv-rt.jar
  1392 Cache Reads clone@0:ptm
 83181 Cache Reads psinfo

Of course by the time I finished writing this, pretty much everything in the only ufs filesystem on the box had been cached :)

Wednesday Jan 09, 2008

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

Tuesday Oct 23, 2007

Sun Developer Days

OK, I got back from CEC on Saturday a week back and walked into the house at about 9:30 absolutely knackered. About 2pm my pager went off and I discovered that I was on VOSJEC duty that weekend and ended up with a righht horror of a call that lasted the rest of the weekend (that I won't go into detail here with, save to say that I got an action plan out to these ghuys at about 00:30 on Monday morning.

Early Monday morning (ok I did get some sleep, this is real morning about 10-11), I got a call from Laurie Wong. Apparantly the DTrace speaker they had organised for the Developer Days couldn't make it and they really couldn't find anyone else. After some discussion with my boss, we agreed that I would go fly to Melbourne the next day to cover this and also cover Sydney on Wednesday.

Had an awful time actually using the system that we are supposed to use to book the flight, ended up taking me a bit over an hour and by that time the fare had risen 50% !!! Anyway got that all sorted and boy am I glad that I booked to get my self well ahead of when I spoke.

First off, I was using someone else's slides, so of course I had to work out what I was going to say to each one (I use flash cards to remind me of what I want to talk about so I'm not just reading the slides). Going through the slides I noticed that the information on the javascript provider was actually out of date. Indeed, you can actually download a firefox 3.0 alpha that has the new provider in there and looks pretty damned spiffy. So, I updated that stuff, then I discovered that there were actually two sections of the talk not present in the slides. This was the "tie it all together" bit and the summary. Well I didn't have the time to write a "tie it all together bit", so I removed that from the agenda slide and did up an "in conclusion" slide.

The other part of being glad I booked an earlier flight is that even though we boarded close to time, we were about an hour late getting off the runway! I got in to Melbourne at about midday. Fortunately we were able to put another speaker in front of me so I could finish writing the talk which I ended up giving at 4pm.

Anyway, the talk covered some background on DTrace (and the slide author provided some really nice graphics and animations), and discussion of various providers. In particular I talked about PHP, javascript, and postgresQL. I did demos for some of the basic DTrace, javascript and postgreSQL.

I Also touched on the shell provider I'm working on and encouraged folks to get involved with working on and testing new providers.

Amazingly, without having timed this or even thought about the length, I managed to finish exactly on time.

Laurie took me into the QANTAS lounge where we were able to relax a little before the flight home. With the flight and the train trip I got home about midnight.

The next day was in Sydney, so I only needed to take the train into the city.

After finding the venue (google maps on a treo 750 is really useful!), I sat in on a couple of the other talks and quite enjoyed those. In Sydney my talk was at 3:15 and again went pretty well.

Headed home after being treated to a really nice dinner at Doyle's on the Harbour.

Unfortunately I had a prior commitment on Friday so I couldn't give the talk in Canberra.

These were probably the largest audiences that I have ever presented to (combining both talks I spoke to about 580 people). I actually enjoyed it and I think my audience had a bit of fun as well. It's nice to do this kind of thing every so often.

Technorati Tags: , ,

Monday Aug 20, 2007

sh provider update - command-entry fixed

I've just uploaded the latest diffs and binaries to www.opensolaris.org/os/community/dtrace/shells/.

So what changed?

There was a bug in that the command-entry probe fired in both parent and child shell. This was a simple oversight that I should not have missed. I originally had the probe before sh forked, then moved it such that it fired after we knew we were able to fork (basically I didn't want it firing if we were not able to actually fork and run the command). Unfortunately, I forgot to specify that it was only to fire in the parent shell. Simple fix. My bad.

Also note that the documentation on the Providers for various shells site supercedes what I previously wrote in my blog.

I haven't tested the diffs, but I did the same massaging to them that I did for the last lot, so they should be ok to use with gpatch.

Looks like things are starting to settle down now so I'll be able to think about progressing this one and starting to look at some others, using these probe names as some kind of standardisation.

There have been suggestions for extras in this provider, but the feeling that I'm getting is let's get a basic useful provider done as a v1.0 and look at things like stacks and other probes in a later update.

Technorati Tags: , ,

Wednesday Aug 15, 2007

sh provider update (changes and sparc available)

After discussions with Brendan and Adam, I've made a couple of changes to the provider.

  1. exec has been renamed to command, and

  2. script-begin and script-end have become script-start and script-done respectively.

These changes are reflected in the documentation that is available at www.opensolaris.org/os/community/dtrace/shells/

In addition, I have rebuilt the x86 binary with this changes and provided a SPARC binary.

Technorati Tags: , ,

Tuesday Aug 14, 2007

sh DTrace provider diffs and x86 binary available

The title says it all. I've uploaded the diffs and an x86 sh binary to the "Providers for various shells" page. I'll do up a SPARC binary if there is interest in it.

Note that the arguments for the entry probes for builtin, exec and function have changed. There is a link to the correct documentation on this page too.

Have fun playing folks and let me know if you find any bugs.

I would have had these up about 90 minutes ago, but my previous blog entry needed to be written.

Technorati Tags: , ,

Why did I do a sh provider first?

Since I posted my initial blog on this, I've received a few comments and a surprising amount of mail asking why I did /bin/sh, which is an obviously obsolete shell, and not ksh93; some of it bordering on insulting.

Let me go through a few reasons why I did this one first.

  1. It's the one I was asked to do.

  2. The Bourne shell has been around for a very long time and there are, quite literally, millions of scripts that have been written in it, some of them very poorly so.

  3. Much work in the open source environment is done to scratch an itch. In my day to day work doing performance calls I come across an amazing number of instances where being able to probe /bin/sh the way that this allows me to, would be an incredibly useful thing to have in order to explain to a customer why their thrown together script runs so slowly, most of these are /bin/sh scripts. Coding probes for ksh93 has no immediate impact on my day to day work as ksh93 is not yet integrated into OpenSolaris.

  4. Just doing a quick poll of usr/src in the opensolaris tree gives me the following:

    Scripting LanguageActual scriptsDynamically created scriptsComments
    /bin/sh463538
    /usr/bin/sh3943/bin symlinked to /usr/bin
    /sbin/sh186272symlink to /bin/sh
    /bin/ksh212199
    /usr/bin/ksh5350/bin symlinked to /usr/bin
    /bin/perl139
    /usr/bin/perl241237/bin symlinked to /usr/bin
    ksh9300

  5. sh is a logical first step from which other providers can follow.

  6. ksh93 is currently on a track to get integrated. I really don't want to drop any roadblocks on it now.

  7. Does it really matter which one comes first?

At no point did I say I would not consider doing ksh93 or even helping someone else do it, indeed I have had communication with Roland suggesting ways in which this could be done. Believe it or not, there is a plan to get all the shells done. Keep an eye on http://www.opensolaris.org/os/community/dtrace/shells/.

The last thing I expected when I started on this was to be the target of insults because I didn't do someone's favorite shell. I'm wondering how this kind of behavior encourages anyone to actually do anything that is of any benefit to the community. Come on folks, we can do better than that.

Technorati Tags: , ,

Friday Aug 10, 2007

/bin/sh DTrace Provider

A couple of days ago Brendan was chatting with me on irc and we got to discussing such a beast. Mainly looking at something simple in the way of the python and perl providers that others have worked on.

Well, to make a long story short (ok it will be longer later), I've coded up something that appears to work against the nevada clone tree of a couple of days ago, and logged RFE 6591476 to track it.

I'll be putting the diffs up in the next day or so, but for a teaser, here is the documentation.

sh Provider

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

Overview

The sh provider makes available the following probes:


builtin-entryProbe that fires on entry to a shell builtin command.
builtin-returnProbe that fires on return from a shell builtin command.

exec-entryProbe that fires when the shell execs an external command.
exec-returnProbe that fires on return from an external command.

function-entryProbe that fires on entry into a shell function.
function-returnProbe that fires on return from a shell function.

lineProbe that fires before commands on a particular line of code are executed.

subshell-entryProbe that fires when the shell forks a subshell.
subshell-returnProbe that fires on return from a forked subshell.

script-beginProbe that fires before any commands in a script are executed.
script-endProbe that fires on script exit.

Arguments

The argument types to the sh provider are listed in the below table.


Probeargs[0]args[1]args[2]args[3]

builtin-entry,
exec-entry,
function-entry
char \*char \*intchar \*\*

builtin-return,
exec-return,
function-return
char \*char \*int

line char \*int

script-begin char \*

script-end char \*int

subshell-entry char \*pid_t
subshell-return char \*int

arg0 in all probes is the script name.

In the builtin, exec, and function entry probes, and the builtin, exec, and function return probes, arg1 is the name of the function, builtin or program being called. arg2 and arg3 in these entry probes are the argument count and a pointer to the argument list. In these return probes, arg2 is the return code from the function, builtin or program.

In the subshell-entry, arg1 is the pid of the forked subshell and in subshell-return probes, arg1 is the return code from the subshell.

In the line probe, arg1 is the line number.

In the script-end probe, arg1 is the exit code of the script.

Stability

The sh provider uses DTrace's stability mechanism to describe its stabilities, as shown in the following table. For more information on the stability mechanism see Chapter 39 of the Solaris Dynamic Tracing guide.

ElementName ClassData ClassDependancy Class
ProviderUnstableUnstableCommon
ModulePrivatePrivateUnknown
FunctionPrivatePrivateUnknown
NameUnstableUnstableCommon
ArgumentsUnstableUnstableCommon

The probes that gave me the most trouble were line and subshell-\*.

line was tricky as sh only does line numbers when it parses input. It has no concept of line numbers on execution, which is what we need.

So, I needed to add another structure element (line) to trenod, and every other struct that is cast over the top of it. In the first failed attempt, I set this to standin->flin whenever we allocated a new one of these nodes, I set line to this value. The problem with this is that if the parser hits a newline, this number gets incremented before we actually set it, which means that the last command on every line has the line number of the following line. Not quite what I wanted.

What I ended up going with was the creation of another variable in the fileblk structure (comline) that I set just before standin->flin is incremented. This looks like it works.

The subshell-\* probes were not initially going to be a part of this, but an assumption I made about com in execute() when coding the exec-\* probes ended up causing the shell to coredump on me. It turns out that com is properly defined when we fall through the switch to the TFORK code, but if we go directly into the TFORK case, it's something completely different (would you believe "1"?). So, I made the probe conditional on the node type. If it was a TFORK, then we do a subshell probe, otherwise we do an exec probe. This also appears to work.

In the meanwhile, I've been sending Brendan sh binaries and he's already started coding more tools for the DTrace Toolkit based on this provider, and I have to say that some of his ideas look pretty cool.

Technorati Tags: , ,

Wednesday Aug 08, 2007

Finding undocumented command options

I had a colleague this morning asking about undocumented (ie not listed in usage or man pages) options in a command. The actual command doesn't really matter, but I was feeling a little lazy and couldn't bothered looking up the source code to the command (which actually wasn't in ON). Almost immediately I thought of DTrace.

Let's have a look at ls as an example. I'll give it a dummy directory as I really don't care about the output.

$ dtrace -q -n 'pid$target::getopt:entry {trace(copyinstr(arg2));}' -c 'ls /nosuchfile'                     
/nosuchfile: No such file or directory
aAbcCdeEfFghHilLmnopqrRsStux1@vV

As you can see, the second line of output is printing out the third argument (arg2) to getopt(3c), which will list every option that getopt(3c) will recognise for the command.

Of course I could have prettied it up, but it's a one liner, I know what the output means.

The point being, that DTrace is just another sysadmin tool to be used in day to day operations.

Technorati Tags: , ,


Yes I know I have been lax in my blogging, I'm going to start doing something about that, starting with this one :-)

Wednesday Nov 22, 2006

Some DTrace scripts I found useful last week

Last week I spent some time looking at applications that a customer was using to perform a data migration. It occurs to me that folks might be interested in a couple of the "one liner" type scripts that I found useful after turning them into 'stat' type tools. So, here they are.

funcs.d

#!/usr/sbin/dtrace -s

#pragma D option quiet

/\*
 \* Count all user space function calls
 \*
 \* $1 - time to run (eg 10s)
 \* $2 - pid to monitor
 \*/

pid$2:::entry {
	@[probefunc] = count();}
tick-$1 {
	printa(@);
	clear(@);
	printf("--------\\n");}

syscalls.d

#!/usr/sbin/dtrace -s

#pragma D option quiet

/\*
 \* Count the syscalls a process is making as a stat tool
 \*
 \* $1 time to wait (eg 10s)
 \* $2 target pid
 \*/

syscall:::entry /pid == $2/ {
	@[probefunc] = count();}
tick-$1 {
	printa(@);
	printf("--------\\n");
	clear(@);}

systimes.d

#!/usr/sbin/dtrace -s

#pragma D option quiet

/\*
 \* Count the syscalls a process is making as a stat tool
 \*
 \* $1 time to wait (eg 10s)
 \* $2 target pid
 \*/

syscall:::entry /pid == $2/ {
	self->start = vtimestamp;}
syscall:::return /self->start/ {
	@[probefunc] = quantize((vtimestamp - self->start)/1000);}
tick-$1 {
	printa(@);
	printf("--------\\n");
	clear(@);}

ustk.d

#!/usr/sbin/dtrace -s

#pragma D option quiet
/\*
 \* Aggregate user stacks calling a function in user space
 \*
 \* $1 - time to run (eg 10s)
 \* $2 - pid to monitor
 \* $3 - function to look for
 \*/

pid$2::$3:entry {
	@[ustack(30)] = count();}
tick-$1 {
	printa(@);
	clear(@);
	printf("--------\\n");}

Technorati Tags: ,

About

* - Solaris and Network Domain, Technical Support Centre


Alan is a kernel and performance engineer based in Australia who tends to have the nasty calls gravitate towards him

Search

Archives
« April 2014
SunMonTueWedThuFriSat
  
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
   
       
Today
Links
Blogroll

No bookmarks in folder

Sun Folk

No bookmarks in folder

Non-Sun Folk
Non-Sun Folks

No bookmarks in folder