Flushing systemtap output without restarting (was: Re: Rapidly running systemtap causing hangs or oops)

["Richard W.M. Jones" <rjones at redhat dot com>]

On Thu, Jun 23, 2011 at 08:51:26AM +0100, Richard W.M. Jones wrote:
> Unfortunately for the real program I'm writing, I really do need a way
> to box stap around each test.  The problem I was having before was
> that there was quite a long delay between my test running and stap
> probes firing (or at least, seeing stap output).  I need the stap
> output from one test to be clearly distinct from the stap output from
> the next test.  If there was a way to run the test and then say to
> stap "now flush all your output" before running the next test, then
> that would be acceptable.
> 
> I thought about using the process ID, but ideally my tests will all
> run as the same pid.

My first idea for "flushing" stap output involves putting a timestamp
at the start of each stap line, then matching up those timestamps with
when the tests were run.

In my test I have:

  for pass in `seq 1 1000`; do
    d=$(date +'%s.%N')
    echo $d: mount
    mount -o loop /tmp/fs /tmp/mnt
    umount /tmp/mnt
    sync
  done

In my probe I have:

  probe module("ext2").statement ("*@*.c:*")
  {
    us = gettimeofday_us();
    printf ("%d.%d: %s\n", us/1000000, us%1000000, pp());
  }

My aggregated output is supposed to look like this:

  1308822712.884907138: mount
  1308822712.920008: module("ext2").statement("ext2_mount@fs/ext2/super.c:1378")
  1308822712.920015: module("ext2").statement("ext2_mount@fs/ext2/super.c:1379")
  [etc]

Unfortunately this doesn't work.  It seems like the probes don't run
synchronously.  Are they running asynchronously in a bottom half /
softirq / {whatever Linux is calling them this week}?

It certainly looks like they run asynch, because my actual output
(sometimes) looks like:

1308822714.015994546: mount
1308822714.424888519: mount
1308822714.43626: module("ext2").statement("ext2_mount@fs/ext2/super.c:1378")
1308822714.43634: module("ext2").statement("ext2_mount@fs/ext2/super.c:1379")
1308822714.442957: module("ext2").statement("ext2_mount@fs/ext2/super.c:1378")
1308822714.442965: module("ext2").statement("ext2_mount@fs/ext2/super.c:1379")

The output from two tests is mixed together, and the timestamps aren't
accurate.  That's no good for the testing I had in mind.

So is there a way to flush systemtap output without restarting it?

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
virt-top is 'top' for virtual machines.  Tiny program with many
powerful monitoring features, net stats, disk stats, logging, etc.
http://et.redhat.com/~rjones/virt-top