Rapidly running systemtap causing hangs or oops

Rapidly running systemtap causing hangs or oops

[Richard W.M. Jones]

Me again.  I can get something involving systemtap, ext2, the loop
device, Linux 3.0 to oops very easily.  I'm not quite sure exactly
what factor causes it, but here's an easy reproducer:

$ mkdir /tmp/mnt

$ truncate -s 1G /tmp/fs
$ mkfs.ext2 -F /tmp/fs

$ cat > /tmp/test.sh 
#!/bin/sh -
echo mount
mount -o loop /tmp/fs /tmp/mnt
echo unmount
umount /tmp/mnt

$ chmod +x /tmp/test.sh

$ while sudo stap -e 'probe module("ext2").statement ("*@*.c:*") { printf ("%s\n", pp()); }' -c /tmp/test.sh ; do : ; done

The final command usually either hangs the machine, or produces a long
oops like the one attached, after just a few iterations.  It takes
just a few seconds on my VM to get a hang or oops.

Just doing repeated stap without running the shell script seems OK.

Using a dummy 'never' probe seems OK.

Just repeatedly mounting and unmounting the filesystem (no systemtap)
seems OK.

So it's probably something to do with having so many probes, and/or
adding and removing the probes, while at the same time having ext2
code potentially running, or something like that ...

systemtap-20110618, patched so STP_DEFAULT_BUFFERS == 1000
Linux 3.0-0.rc4.git0.2.fc16.x86_64
host with 2 cores x 2 threads

Rich.

----------------------------------------------------------------------

[  312.120212] stap_94148964062ac48d4f063ebbe5401fc8_192393: systemtap: 1.6/0.152, base: ffffffffa00e1000, memory: 493data/16text/2ctx/273net/31alloc kb, probes: 1241
[  312.467344] SELinux: initialized (dev loop0, type ext2), uses xattr
[  315.002778] stap_94148964062ac48d4f063ebbe5401fc8_192393: systemtap: 1.6/0.152, base: ffffffffa017c000, memory: 493data/16text/2ctx/273net/31alloc kb, probes: 1241
[  315.375095] SELinux: initialized (dev loop0, type ext2), uses xattr
[  317.960558] stap_94148964062ac48d4f063ebbe5401fc8_192393: systemtap: 1.6/0.152, base: ffffffffa01fd000, memory: 493data/16text/2ctx/273net/31alloc kb, probes: 1241
[  318.291151] SELinux: initialized (dev loop0, type ext2), uses xattr
[  320.794384] stap_94148964062ac48d4f063ebbe5401fc8_192393: systemtap: 1.6/0.152, base: ffffffffa017c000, memory: 493data/16text/2ctx/273net/31alloc kb, probes: 1241
[  321.118256] SELinux: initialized (dev loop0, type ext2), uses xattr
[  323.609426] stap_94148964062ac48d4f063ebbe5401fc8_192393: systemtap: 1.6/0.152, base: ffffffffa01fd000, memory: 493data/16text/2ctx/273net/31alloc kb, probes: 1241
[  323.969995] SELinux: initialized (dev loop0, type ext2), uses xattr
[  326.539067] stap_94148964062ac48d4f063ebbe5401fc8_192393: systemtap: 1.6/0.152, base: ffffffffa017c000, memory: 493data/16text/2ctx/273net/31alloc kb, probes: 1241
[  326.897670] SELinux: initialized (dev loop0, type ext2), uses xattr
[  329.636916] stap_94148964062ac48d4f063ebbe5401fc8_192393: systemtap: 1.6/0.152, base: ffffffffa01fd000, memory: 493data/16text/2ctx/273net/31alloc kb, probes: 1241
[  329.958285] SELinux: initialized (dev loop0, type ext2), uses xattr
[  332.749455] stap_94148964062ac48d4f063ebbe5401fc8_192393: systemtap: 1.6/0.152, base: ffffffffa017c000, memory: 493data/16text/2ctx/273net/31alloc kb, probes: 1241
[  333.098627] EXT2-fs (loop0): warning: maximal mount count reached, running e2fsck is recommended
[  333.103118] SELinux: initialized (dev loop0, type ext2), uses xattr
[  335.765820] stap_94148964062ac48d4f063ebbe5401fc8_192393: systemtap: 1.6/0.152, base: ffffffffa01fd000, memory: 493data/16text/2ctx/273net/31alloc kb, probes: 1241
[  336.124337] EXT2-fs (loop0): warning: maximal mount count reached, running e2fsck is recommended
[  336.125338] SELinux: initialized (dev loop0, type ext2), uses xattr
[  338.739976] stap_94148964062ac48d4f063ebbe5401fc8_192393: systemtap: 1.6/0.152, base: ffffffffa017c000, memory: 493data/16text/2ctx/273net/31alloc kb, probes: 1241
[  339.068795] EXT2-fs (loop0): warning: maximal mount count reached, running e2fsck is recommended
[  339.069828] SELinux: initialized (dev loop0, type ext2), uses xattr
[  341.672427] stap_94148964062ac48d4f063ebbe5401fc8_192393: systemtap: 1.6/0.152, base: ffffffffa00da000, memory: 493data/16text/2ctx/273net/31alloc kb, probes: 1241
[  342.036460] double fault: 0000 [#1] SMP 
[  342.037017] CPU 0 
[  342.037017] Modules linked in: stap_94148964062ac48d4f063ebbe5401fc8_192393 ext2 sunrpc ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 nf_conntrack_ipv4 nf_defrag_ipv4 ip6table_filter xt_state ip6_tables nf_conntrack joydev microcode virtio_balloon i2c_piix4 i2c_core virtio_net virtio_blk [last unloaded: stap_94148964062ac48d4f063ebbe5401fc8_192393]
[  342.037017] 
[  342.037017] Pid: 1919, comm: mount Not tainted 3.0-0.rc4.git0.2.fc16.x86_64 #1 Bochs Bochs
[  342.037017] RIP: 0010:[<ffffffffa00ca6a6>]  [<ffffffffa00ca6a6>] ext2_get_inode+0x6d/0x130 [ext2]
[  342.037017] RSP: 0000:00000000fffffffb  EFLAGS: 00010246
[  342.037017] RAX: 0000000000000000 RBX: ffff88003959a120 RCX: ffff880026e0c8c8
[  342.037017] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff88003959a120
[  342.037017] RBP: ffff8800244adc48 R08: ffff88003959a2d8 R09: 0000000000000000
[  342.037017] R10: ffffffff827ff2a0 R11: ffffffff827ff2a0 R12: 0000000000000002
[  342.037017] R13: 0000000000000002 R14: ffff8800244adc60 R15: 0000000000000001
[  342.037017] FS:  00007f41d60f6820(0000) GS:ffff88003fc00000(0000) knlGS:0000000000000000
[  342.037017] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[  342.037017] CR2: 00000000ffffffe8 CR3: 0000000024488000 CR4: 00000000000006f0
[  342.037017] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  342.037017] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[  342.037017] Process mount (pid: 1919, threadinfo ffff8800244ac000, task ffff88003daa0000)
[  342.037017] Stack:
[  342.037017] BUG: unable to handle kernel paging request at 00000000fffffffb
[  342.037017] IP: [<ffffffff8100afb8>] show_stack_log_lvl+0xbf/0x118
[  342.037017] PGD 0 
[  342.037017] Oops: 0000 [#2] SMP 
[  342.037017] CPU 0 
[  342.037017] Modules linked in: stap_94148964062ac48d4f063ebbe5401fc8_192393 ext2 sunrpc ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 nf_conntrack_ipv4 nf_defrag_ipv4 ip6table_filter xt_state ip6_tables nf_conntrack joydev microcode virtio_balloon i2c_piix4 i2c_core virtio_net virtio_blk [last unloaded: stap_94148964062ac48d4f063ebbe5401fc8_192393]
[  342.037017] 
[  342.037017] Pid: 1919, comm: mount Not tainted 3.0-0.rc4.git0.2.fc16.x86_64 #1 Bochs Bochs
[  342.037017] RIP: 0010:[<ffffffff8100afb8>]  [<ffffffff8100afb8>] show_stack_log_lvl+0xbf/0x118
[  342.037017] RSP: 0000:ffff88003fc05df8  EFLAGS: 00010046
[  342.037017] RAX: ffff88003fbfffc0 RBX: 0000000000000000 RCX: 0000000000000000
[  342.037017] RDX: ffff88003fc00000 RSI: ffff88003fc05f58 RDI: 0000000000000000
[  342.037017] RBP: ffff88003fc05e48 R08: ffffffff817b1edf R09: 0000000000000000
[  342.037017] R10: 0000ffff00066c0a R11: 0000000000000001 R12: ffff88003fc05f58
[  342.037017] R13: 0000000000000000 R14: 00000000fffffffb R15: 0000000000000000
[  342.037017] FS:  00007f41d60f6820(0000) GS:ffff88003fc00000(0000) knlGS:0000000000000000
[  342.037017] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[  342.037017] CR2: 00000000fffffffb CR3: 0000000024488000 CR4: 00000000000006f0
[  342.037017] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  342.037017] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[  342.037017] Process mount (pid: 1919, threadinfo ffff8800244ac000, task ffff88003daa0000)
[  342.037017] Stack:
[  342.037017]  ffffffff817b1edf ffff88003fbfffc0 ffff88003fc03fc0 00000000fffffffb
[  342.037017]  ffff88003fc05e78 00000000fffffffb ffff88003fc05f58 0000000000000000
[  342.037017]  000000000000002b 0000000000000001 ffff88003fc05eb8 ffffffff8100b0ce
[  342.037017] Call Trace:
[  342.037017]  <#DF> 
[  342.037017]  [<ffffffff8100b0ce>] show_registers+0xbd/0x206
[  342.037017]  [<ffffffff814f6cba>] ? atomic_notifier_call_chain+0x14/0x16
[  342.037017]  [<ffffffff814f4941>] __die+0x97/0xd8
[  342.037017]  [<ffffffff8100be1c>] die+0x47/0x63
[  342.037017]  [<ffffffff81009d79>] do_double_fault+0x65/0x67
[  342.037017]  [<ffffffff814fb1aa>] double_fault+0x2a/0x30
[  342.037017]  [<ffffffffa00ca6a6>] ? ext2_get_inode+0x6d/0x130 [ext2]
[  342.037017]  <<EOE>> 
[  342.037017] Code: 76 f8 e8 1b e1 4d 00 eb 09 41 f7 c6 ff 1f 00 00 74 3f 45 85 ff 74 14 41 f6 c7 03 75 0e 48 c7 c7 1c 1f 7b 81 31 c0 e8 f7 e0 4d 00 
[  342.037017]  8b 36 48 c7 c7 e4 24 7b 81 31 c0 49 83 c6 08 41 ff c7 e8 df 
[  342.037017] RIP  [<ffffffff8100afb8>] show_stack_log_lvl+0xbf/0x118
[  342.037017]  RSP <ffff88003fc05df8>
[  342.037017] CR2: 00000000fffffffb
[  342.037017] ---[ end trace 8b91f4a818d18433 ]---


-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
New in Fedora 11: Fedora Windows cross-compiler. Compile Windows
programs, test, and build Windows installers. Over 70 libraries supprt'd
http://fedoraproject.org/wiki/MinGW http://www.annexia.org/fedora_mingw

Re: Rapidly running systemtap causing hangs or oops

[Josh Stone]

On 06/22/2011 04:00 PM, Richard W.M. Jones wrote:
> Me again.  I can get something involving systemtap, ext2, the loop
> device, Linux 3.0 to oops very easily.  I'm not quite sure exactly
> what factor causes it, but here's an easy reproducer:
> 
> $ mkdir /tmp/mnt
> 
> $ truncate -s 1G /tmp/fs
> $ mkfs.ext2 -F /tmp/fs
> 
> $ cat > /tmp/test.sh 
> #!/bin/sh -
> echo mount
> mount -o loop /tmp/fs /tmp/mnt
> echo unmount
> umount /tmp/mnt
> 
> $ chmod +x /tmp/test.sh
> 
> $ while sudo stap -e 'probe module("ext2").statement ("*@*.c:*") { printf ("%s\n", pp()); }' -c /tmp/test.sh ; do : ; done
> 
> The final command usually either hangs the machine, or produces a long
> oops like the one attached, after just a few iterations.  It takes
> just a few seconds on my VM to get a hang or oops.

Can you try running stap with "-D STP_ALIBI"?  This alibi mode compiles
out most of stap's code, so each probe handler is reduced to just an
atomic increment, then a final hit count is reported on exit.

Another test might be to move the loop inside test.sh, so stap is left
running the whole time, and we might tell if the issue is timed around
stap's probe registration or unregistration.

> [  342.037017]  [<ffffffff8100b0ce>] show_registers+0xbd/0x206
> [  342.037017]  [<ffffffff814f6cba>] ? atomic_notifier_call_chain+0x14/0x16
> [  342.037017]  [<ffffffff814f4941>] __die+0x97/0xd8
> [  342.037017]  [<ffffffff8100be1c>] die+0x47/0x63
> [  342.037017]  [<ffffffff81009d79>] do_double_fault+0x65/0x67
> [  342.037017]  [<ffffffff814fb1aa>] double_fault+0x2a/0x30
> [  342.037017]  [<ffffffffa00ca6a6>] ? ext2_get_inode+0x6d/0x130 [ext2]

Is the Oops always this minimal?  Does it always (questionably) point to
the same ext2_get_inode location?

I'll play with this tomorrow and see if I can reproduce it myself...

Josh

Re: Rapidly running systemtap causing hangs or oops

[Richard W.M. Jones]

On Wed, Jun 22, 2011 at 04:52:08PM -0700, Josh Stone wrote:
> On 06/22/2011 04:00 PM, Richard W.M. Jones wrote:
> > Me again.  I can get something involving systemtap, ext2, the loop
> > device, Linux 3.0 to oops very easily.  I'm not quite sure exactly
> > what factor causes it, but here's an easy reproducer:
> > 
> > $ mkdir /tmp/mnt
> > 
> > $ truncate -s 1G /tmp/fs
> > $ mkfs.ext2 -F /tmp/fs
> > 
> > $ cat > /tmp/test.sh 
> > #!/bin/sh -
> > echo mount
> > mount -o loop /tmp/fs /tmp/mnt
> > echo unmount
> > umount /tmp/mnt
> > 
> > $ chmod +x /tmp/test.sh
> > 
> > $ while sudo stap -e 'probe module("ext2").statement ("*@*.c:*") { printf ("%s\n", pp()); }' -c /tmp/test.sh ; do : ; done
> > 
> > The final command usually either hangs the machine, or produces a long
> > oops like the one attached, after just a few iterations.  It takes
> > just a few seconds on my VM to get a hang or oops.
> 
> Can you try running stap with "-D STP_ALIBI"?  This alibi mode compiles
> out most of stap's code, so each probe handler is reduced to just an
> atomic increment, then a final hit count is reported on exit.

Adding -D STP_ALIBI to the command line changed the stap output
a little bit, so I see lines that look like this:

module("ext2").statement("ext2_xattr_put_super@fs/ext2/xattr.c:817"), (<input>:1:1), hits: 1, from: module("ext2").statement("*@*.c:*")

However it did not change the behaviour.  The mount process crashed
quickly with the oops below:

[  159.454020]  [<ffffffffa00d0a3b>] ext2_fill_super+0x9b5/0xc3b [ext2]
[  159.454020]  [<ffffffff8113a0df>] mount_bdev+0x155/0x1b7
[  159.454020]  [<ffffffffa00d0086>] ? ext2_error+0x112/0x112 [ext2]
[  159.454020]  [<ffffffffa00cedb5>] ext2_mount+0x15/0x17 [ext2]
[  159.454020]  [<ffffffff8113a844>] mount_fs+0x69/0x155
[  159.454020]  [<ffffffff81103f94>] ? __alloc_percpu+0x10/0x12
[  159.454020]  [<ffffffff8114f902>] vfs_kern_mount+0x63/0xa0
[  159.454020]  [<ffffffff811505d6>] do_kern_mount+0x4d/0xdf
[  159.454020]  [<ffffffff81151c6c>] do_mount+0x63c/0x69f
[  159.454020]  [<ffffffff810ffbd9>] ? memdup_user+0x42/0x6a
[  159.454020]  [<ffffffff810ffc3c>] ? strndup_user+0x3b/0x51
[  159.454020]  [<ffffffff81151f50>] sys_mount+0x88/0xc2
[  159.454020]  [<ffffffff814fa142>] system_call_fastpath+0x16/0x1b

> Another test might be to move the loop inside test.sh, so stap is left
> running the whole time, and we might tell if the issue is timed around
> stap's probe registration or unregistration.

I've left this running for 10 minutes, no crash.

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.

> > [  342.037017]  [<ffffffff8100b0ce>] show_registers+0xbd/0x206
> > [  342.037017]  [<ffffffff814f6cba>] ? atomic_notifier_call_chain+0x14/0x16
> > [  342.037017]  [<ffffffff814f4941>] __die+0x97/0xd8
> > [  342.037017]  [<ffffffff8100be1c>] die+0x47/0x63
> > [  342.037017]  [<ffffffff81009d79>] do_double_fault+0x65/0x67
> > [  342.037017]  [<ffffffff814fb1aa>] double_fault+0x2a/0x30
> > [  342.037017]  [<ffffffffa00ca6a6>] ? ext2_get_inode+0x6d/0x130 [ext2]
> 
> Is the Oops always this minimal?  Does it always (questionably) point to
> the same ext2_get_inode location?

Different places, but all within the ext2 mounting / superblock code.

> I'll play with this tomorrow and see if I can reproduce it myself...

Thanks for looking at this.

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

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

[Richard W.M. Jones]

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

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

[Richard W.M. Jones]

On Thu, Jun 23, 2011 at 11:12:17AM +0100, Richard W.M. Jones wrote:
> 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")

Damn, it's the stupidest mistakes which are the easiest to
overlook.

In fact the ordering (by time) is *correct*.  It just appears wrong
because I didn't format the microsecond field with leading zeroes (%06d) ...

Thanks everyone, I will keep going down the timestamp route.

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

Re: Rapidly running systemtap causing hangs or oops

[Frank Ch. Eigler]

Hi, Richard -

rjones wrote:

> [...]
>> Can you try running stap with "-D STP_ALIBI"?  This alibi mode compiles
>> out most of stap's code, so each probe handler is reduced to just an
>> atomic increment, then a final hit count is reported on exit.

> Adding -D STP_ALIBI [...]  did not change the behaviour.  The mount
> process crashed quickly with the oops below:
> [  159.454020]  [<ffffffffa00d0a3b>] ext2_fill_super+0x9b5/0xc3b [ext2]
> [  159.454020]  [<ffffffff8113a0df>] mount_bdev+0x155/0x1b7
> [  159.454020]  [<ffffffffa00d0086>] ? ext2_error+0x112/0x112 [ext2]
> [...]

OK, that does seem to implicate the kernel or our registration /
unregistration process.  Telling which is a bit tricky because the
kernel's own 'perf probe' widget cannot register/unregister as many
probes as quickly as we can, which means that if the kernel has race
conditions in all that text-segment manipulation, we are more likely
to hit it than e.g. perf.  Such has happened before, and it's tough to
diagnose.

An intermediate option is to extract all the kprobe addresses from the
"stap -p2" processing loop, and modify systemtap source-tree
scripts/kprobes_test/gen_code.py to take a symbol+offset list rather
than just a symbol list, to generate a non-systemtap pure-kprobes
module.  Then one could insmod;test;rmmod in a tight loop to see if
the same problem reappears.  At that point, one punts to the kernel
folks.

Another hacky intermediate possibility is to put some deliberate
time delays here and there, like between your while true; do stap; done 
loop iterations.  Or disable runtime/autoconf-unregister-kprobes.c, so
stap doesn't use the kernel bulk-unregistration functions but rather
goes one by one.

- FChE

Re: Rapidly running systemtap causing hangs or oops

[Josh Stone]

On 06/23/2011 12:51 AM, 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.

How about marking it with some other event that always and only happens
at the beginning or end of your test loop?  e.g. take a mount:

  probe syscall.mount {
    printf("Starting to mount %s on %s\n", source, target)
  }


Josh

Re: Rapidly running systemtap causing hangs or oops

[Richard W.M. Jones]

On Thu, Jun 23, 2011 at 09:15:50AM -0700, Josh Stone wrote:
> On 06/23/2011 12:51 AM, 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.
> 
> How about marking it with some other event that always and only happens
> at the beginning or end of your test loop?  e.g. take a mount:
> 
>   probe syscall.mount {
>     printf("Starting to mount %s on %s\n", source, target)
>   }

Something like this could work, but timestamps seem to be working
rather well now.

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
libguestfs lets you edit virtual machines.  Supports shell scripting,
bindings from many languages.  http://libguestfs.org