[9fans] system call trace version of 9vx available.

[9fans] system call trace version of 9vx available.

[ron minnich]

http://bitbucket.org/rminnich/vx32

this is my hack of vx32.

It includes a ram block device, but more importantly, it supports the
system call trace code.

In the 'root' of the repo is the syscalltrace directory; cd in there
to make the syscalltrace binary.

Comments and improvements welcome. Noah wrote the first version of
syscalltrace.c. Thanks to Russ for suggestions that led to substantial
improvements in the code; it's still not good enough (Jim McKie made a
really great improvement which you can see in the 9k kernel) and I
don't think it yet belongs in the main vx32 tree. That said, you can
get a *lot* of work done with this version, and we've found
syscalltrace very helpful on the bg/p effort, so I wanted to make sure
people could see it. I've seen questions go by on this list lately
that use of syscalltrace might have answered. I use syscalltrace all
the time now when I hit a problem I don't understand. It would be
helpful for those debugging cpu and auth problems, I think.

Thanks to Russ, Jim, and Noah for their help and improvements. Any
errors are mine.

ron

Re: [9fans] system call trace version of 9vx available.

[David Leimbach]

[-- Attachment #1: Type: text/plain, Size: 1365 bytes --]

On Tue, May 18, 2010 at 5:22 PM, ron minnich <rminnich@gmail.com> wrote:

> http://bitbucket.org/rminnich/vx32
>
> this is my hack of vx32.
>

Were all of the binaries within recompiled against this code?  Running 9vx
on my iMac is pretty smooth!

Dave


>
> It includes a ram block device, but more importantly, it supports the
> system call trace code.
>
> In the 'root' of the repo is the syscalltrace directory; cd in there
> to make the syscalltrace binary.
>
> Comments and improvements welcome. Noah wrote the first version of
> syscalltrace.c. Thanks to Russ for suggestions that led to substantial
> improvements in the code; it's still not good enough (Jim McKie made a
> really great improvement which you can see in the 9k kernel) and I
> don't think it yet belongs in the main vx32 tree. That said, you can
> get a *lot* of work done with this version, and we've found
> syscalltrace very helpful on the bg/p effort, so I wanted to make sure
> people could see it. I've seen questions go by on this list lately
> that use of syscalltrace might have answered. I use syscalltrace all
> the time now when I hit a problem I don't understand. It would be
> helpful for those debugging cpu and auth problems, I think.
>
> Thanks to Russ, Jim, and Noah for their help and improvements. Any
> errors are mine.
>
> ron
>
>

[-- Attachment #2: Type: text/html, Size: 1943 bytes --]

Re: [9fans] system call trace version of 9vx available.

[erik quanstrom]

> Were all of the binaries within recompiled against this code?  Running 9vx
> on my iMac is pretty smooth!

trace device doesn't require user land support.

- erik

Re: [9fans] system call trace version of 9vx available.

[ron minnich]

On Wed, May 19, 2010 at 1:54 AM, David Leimbach <leimy2k@gmail.com> wrote:

> Were all of the binaries within recompiled against this code?  Running 9vx
> on my iMac is pretty smooth!

Hm, not sure what you mean.

ron

Re: [9fans] system call trace version of 9vx available.

[David Leimbach]

[-- Attachment #1: Type: text/plain, Size: 659 bytes --]

On Tue, May 18, 2010 at 7:13 PM, ron minnich <rminnich@gmail.com> wrote:

> On Wed, May 19, 2010 at 1:54 AM, David Leimbach <leimy2k@gmail.com> wrote:
>
> > Were all of the binaries within recompiled against this code?  Running
> 9vx
> > on my iMac is pretty smooth!
>
> Hm, not sure what you mean.
>
> ron
>
> There were pre-built binaries in this cloned repo, I'm totally unable to
rebuild the Mac OS X binary, due to some "impossible constraint" in some
assembly or something like that per my recollection.  I was merely wondering
if you expected people to ignore those binaries and build their own or if
those were already built.

Dave

[-- Attachment #2: Type: text/html, Size: 1038 bytes --]

Re: [9fans] system call trace version of 9vx available.

[ron minnich]

On Wed, May 19, 2010 at 4:37 AM, David Leimbach <leimy2k@gmail.com> wrote:

> There were pre-built binaries in this cloned repo, I'm totally unable to
> rebuild the Mac OS X binary, due to some "impossible constraint" in some
> assembly or something like that per my recollection.  I was merely wondering
> if you expected people to ignore those binaries and build their own or if
> those were already built.
> Dave

I just cloned rsc/vx32. That said, I wonder if when I pushed my clone
to rminnich/vx32 it pushed some binaries? It should not have.

The only changes I have made are to the 9vx/9vx part of vx32.

ron

Re: [9fans] system call trace version of 9vx available.

[David Leimbach]

[-- Attachment #1: Type: text/plain, Size: 936 bytes --]

On Tue, May 18, 2010 at 9:52 PM, ron minnich <rminnich@gmail.com> wrote:

> On Wed, May 19, 2010 at 4:37 AM, David Leimbach <leimy2k@gmail.com> wrote:
>
> > There were pre-built binaries in this cloned repo, I'm totally unable to
> > rebuild the Mac OS X binary, due to some "impossible constraint" in some
> > assembly or something like that per my recollection.  I was merely
> wondering
> > if you expected people to ignore those binaries and build their own or if
> > those were already built.
> > Dave
>
> I just cloned rsc/vx32. That said, I wonder if when I pushed my clone
> to rminnich/vx32 it pushed some binaries? It should not have.
>
> The only changes I have made are to the 9vx/9vx part of vx32.
>
> ron
>
> I see, well it could just be that I've not run 9vx in a while too :-)
 Things certainly seemed a lot easier to deal with this time around in
certain areas around networking and such.

Dave

[-- Attachment #2: Type: text/html, Size: 1348 bytes --]

Re: [9fans] system call trace version of 9vx available.

[Ethan Grammatikidis]

[-- Attachment #1: Type: text/plain, Size: 994 bytes --]


On 19 May 2010, at 05:37, David Leimbach wrote:

>
>
> On Tue, May 18, 2010 at 7:13 PM, ron minnich <rminnich@gmail.com>  
> wrote:
> On Wed, May 19, 2010 at 1:54 AM, David Leimbach <leimy2k@gmail.com>  
> wrote:
>
> > Were all of the binaries within recompiled against this code?   
> Running 9vx
> > on my iMac is pretty smooth!
>
> Hm, not sure what you mean.
>
> ron
>
> There were pre-built binaries in this cloned repo, I'm totally  
> unable to rebuild the Mac OS X binary, due to some "impossible  
> constraint" in some assembly or something like that per my  
> recollection.

This error?
libvxc/syscall.h:8: error: can't find a register in class ‘BREG’ while  
reloading ‘asm’

What works for me on 10.5 is this:
cd vx32/src
make 9vx/9vx

It runs; not extensively tested but appears to run fine.

On 10.6 you may have to define _XOPEN_SOURCE as Bakul Shah described.

-- 
Simplicity does not precede complexity, but follows it. -- Alan Perlis


[-- Attachment #2: Type: text/html, Size: 4278 bytes --]

Re: [9fans] system call trace version of 9vx available.

[Bakul Shah]

On Tue, 18 May 2010 18:54:21 PDT David Leimbach <leimy2k@gmail.com>  wrote:
>
> Were all of the binaries within recompiled against this code?  Running 9vx
> on my iMac is pretty smooth!

vx32/src/9vx.*.gz are the same as before (in case you are running those).

Compiling 9vx on a MAC OS 10.6.3 required changing HOST_CC line
in src/Makefrag to

HOST_CC	:= $(CC) -fno-inline -m32 -D_XOPEN_SOURCE

Undoubtedly there is a cleaner way.

I copied vx32/src/9vx/syscalltrace/ to $home in 9vx and compiled
syscalltrace there.

term% 8.out -c /bin/echo Boo!
511 echo Brk 0x3233 0000b450 00000000 00000000 = 0 "" 0x11af077310cde470 0x11af077310d0da40
511 echo Pwrite 0x31d6 1 0000a458/"Boo!." 5 -0x1Boo!
 = 5 "" 0x11af07731e11e758 0x11af077326aed448
511 echo Open 0x32c0 00009ec0/"#c/pid" 00000000 = 3 "" 0x11af0773315f14c0 0x11af0773316790a0
511 echo Pread 0x3287 3 0fffff00/"........511." 20 -0x1 = 12 "" 0x11af07733f047958 0x11af07733f09cca0
511 echo Close 0x32ee 3 = 0 "" 0x11af07734a6dad78 0x11af07734a707c38
511 echo Exits 0x1bd5 0/""cwrite: /proc/511/syscall: failed 12 bytes: process exited
tterm%

Very nice!

Is the the syscall trace data format easy to parse?  If so it
can be massaged in various ways.

Re: [9fans] system call trace version of 9vx available.

[erik quanstrom]

> term% 8.out -c /bin/echo Boo!
> 511 echo Brk 0x3233 0000b450 00000000 00000000 = 0 "" 0x11af077310cde470 0x11af077310d0da40
> 511 echo Pwrite 0x31d6 1 0000a458/"Boo!." 5 -0x1Boo!
>  = 5 "" 0x11af07731e11e758 0x11af077326aed448
> 511 echo Open 0x32c0 00009ec0/"#c/pid" 00000000 = 3 "" 0x11af0773315f14c0 0x11af0773316790a0
> 511 echo Pread 0x3287 3 0fffff00/"........511." 20 -0x1 = 12 "" 0x11af07733f047958 0x11af07733f09cca0
> 511 echo Close 0x32ee 3 = 0 "" 0x11af07734a6dad78 0x11af07734a707c38
> 511 echo Exits 0x1bd5 0/""cwrite: /proc/511/syscall: failed 12 bytes: process exited
> tterm%

ron, please enlighten the ignorant.  could you constrast this with
truss?  or maybe there's a man page?

- erik

Re: [9fans] system call trace version of 9vx available.

[ron minnich]

On Tue, May 18, 2010 at 10:45 PM, erik quanstrom <quanstro@quanstro.net> wrote:

> ron, please enlighten the ignorant.  could you constrast this with
> truss?  or maybe there's a man page?

I need to write one.

The biggest diff from truss is that the program itself is dead simple,
since most of the work is done by the kernel and the data relayed to
the program as text. The program is really a fancier, fork-following
version of this script:
while (echo startsyscall > /proc/$1/ctl) cat /proc/$1/syscalltrace

All the formatting etc. is in the kernel.

ron

Re: [9fans] system call trace version of 9vx available.

[ron minnich]

On Tue, May 18, 2010 at 10:40 PM, Bakul Shah <bakul+plan9@bitblocks.com> wrote:

> term% 8.out -c /bin/echo Boo!
> 511 echo Brk 0x3233 0000b450 00000000 00000000 = 0 "" 0x11af077310cde470 0x11af077310d0da40
> 511 echo Pwrite 0x31d6 1 0000a458/"Boo!." 5 -0x1Boo!
>  = 5 "" 0x11af07731e11e758 0x11af077326aed448
> 511 echo Open 0x32c0 00009ec0/"#c/pid" 00000000 = 3 "" 0x11af0773315f14c0 0x11af0773316790a0
> 511 echo Pread 0x3287 3 0fffff00/"........511." 20 -0x1 = 12 "" 0x11af07733f047958 0x11af07733f09cca0
> 511 echo Close 0x32ee 3 = 0 "" 0x11af07734a6dad78 0x11af07734a707c38
> 511 echo Exits 0x1bd5 0/""cwrite: /proc/511/syscall: failed 12 bytes: process exited
> tterm%

The format arose out of discussions with nemo and others.

It is a straight text layout of system call params and return. The =
separates the params and return. The format is:
pid textname syscall-name pc [params] = retval errstr
start-nanoseconds end-nanoseconds

Anything that is a pointer to memory gets printed this way:
pointervalue/"string"

The string has a '.' printed if isgraph(char) is 0.

So, example:
511 echo Open 0x32c0 00009ec0/"#c/pid" 00000000 = 3 ""
0x11af0773315f14c0 0x11af0773316790a0

pid 511, echo, did an Open, at pc 0x32c0, file name was at 9ec0 and
the value was "#c/pid", mode 0, and the result was 3, no error as the
errstr was empty: "", and it took 0x11af0773316790a0 -
0x11af0773315f14c0 nanoseconds or 556000 nanoseconds.

I need to fix syscalltrace to get rid of this annoying non-error:
cwrite: /proc/511/syscall: failed 12 bytes: process exited

Just have not done it yet, I'll take a patch.

ron

Re: [9fans] system call trace version of 9vx available.

[Bakul Shah]

On Wed, 19 May 2010 08:09:50 PDT ron minnich <rminnich@gmail.com>  wrote:
>
> The format arose out of discussions with nemo and others.
>
> It is a straight text layout of system call params and return. The =
> separates the params and return. The format is:
> pid textname syscall-name pc [params] = retval errstr
> start-nanoseconds end-nanoseconds
>
> Anything that is a pointer to memory gets printed this way:
> pointervalue/"string"
>
> The string has a '.' printed if isgraph(char) is 0.

One can grok most of this by staring at the syscalltrace
output. The small hex value after syscall name -- is it the
return pc?

Very nice but now some gripes!

0. Name syscalltrace is too long :-)
1. Curiously, an actual errstr is not enclosed in "..".
2. Seems long long values are printed as two numbers
   (but I haven't checked carefully enough to be sure).
3. Printing . for isgraph(char) loses information.
4. Perhaps buffersize should be settable to deal with
   args pointing to large areas.
5. Occasional hangs. Not sure what the cause is.

What happens if the passed in ptr points to invalid memory?

Given 3., in the kernel I would've just copied a binary
structure and let the userland worry about any formatting.

I "fixed" a few things in syscalltrace (diff below):

- strace -c echo boo		# extra look up in /bin if needed
- strace -c rc -c 'ls /'	# allow - args to command
- strace -c strace -c echo foo	# allow recursive use
  strace -c rc </dev/null |[2] wc
  # send trace output to stderr, not stdout.

There is still some bug that makes syscalltrace hang,
particularly if its output is piped to another process.

Trivia: rc makes 192 syscalls, on freebsd $PLAN9/bin/rc makes
157, /bin/sh makes 87, and zsh makes 11259 calls!

I can imagine showing syscalls of each traced process on a
separate scrolling time line. This will allow one to see
timing relationships and call patterns.  Zoom to see
appropriate scale, click on a call (or select a range) to see
call details.  Can also show who forks whom, with a
connecting line to the new timeline that just popped up for
the new process.  Color can be used for procs or syscalls.
etc. Not sure when/if I will get around to implementing
something like this though.

-- bakul

diff ../syscalltrace/syscalltrace.c ./syscalltrace.c
4a5
> #include <stdio.h>
121c122
< 		print("%s", s->buf);
---
> 		fprint(2, "%s", s->buf);
151c152
< 		break;
---
> 		goto done;
155c156
<
---
> done:
164a166,170
> 			if (cmd[0] != '/') {
> 				char* pcmd = malloc(strlen(cmd) + 5);
> 				sprintf(pcmd, "/bin/%s", cmd);
> 				exec(pcmd, args);
> 			}

Re: [9fans] system call trace version of 9vx available.

[ron minnich]

On Wed, May 19, 2010 at 10:18 AM, Bakul Shah <bakul+plan9@bitblocks.com> wrote:

> 0. Name syscalltrace is too long :-)

pick a name and I'll change it.

> 1. Curiously, an actual errstr is not enclosed in "..".

that goes on the bug list. If you want, use the bugtracker at
bitbucket.org, on my rminnich/vx32 project, and add these bugs. Also
add your changes below as an enhancement and I'll apply it.

> 2. Seems long long values are printed as two numbers
>   (but I haven't checked carefully enough to be sure).

that's an error, but I have not seen it.

> 3. Printing . for isgraph(char) loses information.

that's life. I'm happy to consider a \hex as an alternate print
scheme, but that complicates parsing? Not sure. Advice welcome. nemo?

> 4. Perhaps buffersize should be settable to deal with
>   args pointing to large areas.

yes. It's on the list of "things I want"

> 5. Occasional hangs. Not sure what the cause is.

weird. Have not seen this. If you can reproduce it let me know.


>
> What happens if the passed in ptr points to invalid memory?

I used uvalidaddr and you'll get the same error as you would in the
system call: suicide.

>
> Given 3., in the kernel I would've just copied a binary
> structure and let the userland worry about any formatting.

no. No, no, no, no, no. no.

If there is any consistent thing in Plan 9, it's that ctl and other
files use text. It's great.

This binary idea is a cancer.
1. with text, I can mount /proc from an ARM, and do system call
tracing on my 386 laptop: text is architecture-independent
2. with kernel formatting, I can use awk and rc and perl and whatever
I want to implement tracing
3. textual formats don't need versioning of binary structures.

So, no. It stays as text :-)


> I can imagine showing syscalls of each traced process on a
> separate scrolling time line. This will allow one to see
> timing relationships and call patterns.  Zoom to see
> appropriate scale, click on a call (or select a range) to see
> call details.  Can also show who forks whom, with a
> connecting line to the new timeline that just popped up for
> the new process.  Color can be used for procs or syscalls.
> etc. Not sure when/if I will get around to implementing
> something like this though.

That's a very fine idea. Will our draw libraries support an interface
with this degree of capability?

Note that it's very easy, on Plan 9, with a shell script, to put every
traced proc into a different window.

Thanks for the corrections!

ron

Re: [9fans] system call trace version of 9vx available.

[Bakul Shah]

On Wed, 19 May 2010 10:41:26 PDT ron minnich <rminnich@gmail.com>  wrote:
> On Wed, May 19, 2010 at 10:18 AM, Bakul Shah <bakul+plan9@bitblocks.com> wrote
>
> > 0. Name syscalltrace is too long :-)
>
> pick a name and I'll change it.

I used strace but don't really care what you call it as long
as it is short!  How about ratrace (Ron's ascii trace)?

> > 3. Printing . for isgraph(char) loses information.
>
> that's life. I'm happy to consider a \hex as an alternate print
> scheme, but that complicates parsing? Not sure. Advice welcome. nemo?

A middle ground is to use counted bytestrings. For example
	120:<120 bytes of random goop>

> This binary idea is a cancer.
> 1. with text, I can mount /proc from an ARM, and do system call
> tracing on my 386 laptop: text is architecture-independent
> 2. with kernel formatting, I can use awk and rc and perl and whatever
> I want to implement tracing
> 3. textual formats don't need versioning of binary structures.
>
> So, no. It stays as text :-)

Ok! I don't feel strongly either way.  But I hope you do
consider counted bytestrings to represent random memory.
It is cheap to parse and produce and doesn't lose info.

Re: [9fans] system call trace version of 9vx available.

[erik quanstrom]

> Ok! I don't feel strongly either way.  But I hope you do
> consider counted bytestrings to represent random memory.
> It is cheap to parse and produce and doesn't lose info.

no keep it text.  plan 9 wins this way.  "bytestrings"
(it seems to me that byte strings are neither) would require
knowledge of the producing kernel.  that's just problematic
with plan 9.

- erik

Re: [9fans] system call trace version of 9vx available.

[ron minnich]

On Wed, May 19, 2010 at 11:23 AM, Bakul Shah <bakul+plan9@bitblocks.com> wrote:

> Ok! I don't feel strongly either way.  But I hope you do
> consider counted bytestrings to represent random memory.
> It is cheap to parse and produce and doesn't lose info.

bear in mind that 99.9999999% of the time (well, that's an
exaggeration!) people do a quick one-off run of this type of tool to
see something. Thus, it should be biased to human readability. Counted
bytestrings doesn't quite do that. But I can escape the characters
that are not printable if you want.
\@through \whatever

ron

Re: [9fans] system call trace version of 9vx available.

[Bakul Shah]

On Wed, 19 May 2010 11:33:24 PDT ron minnich <rminnich@gmail.com>  wrote:
> On Wed, May 19, 2010 at 11:23 AM, Bakul Shah <bakul+plan9@bitblocks.com> wrote:
>
> > Ok! I don't feel strongly either way. =A0But I hope you do
> > consider counted bytestrings to represent random memory.
> > It is cheap to parse and produce and doesn't lose info.
>
> bear in mind that 99.9999999% of the time (well, that's an
> exaggeration!) people do a quick one-off run of this type of tool to
> see something. Thus, it should be biased to human readability. Counted
> bytestrings doesn't quite do that. But I can escape the characters
> that are not printable if you want.
> \@through \whatever

Thanks.  For a quick one-off it may not matter but can be
valuable when you are looking for a needle in the haystack.
kdump for example shows all the data (and uses a sidebyside
addr,hex,ascii format when there are unprintable chars).

Note that most people are likely to use a frontend tool than
directly cat /proc/<pid>/syscall.

Which reminds me... Is there a reason why just doing

    cat /proc/<pid>/syscall

shouldn't start tracing?  Seems to me, opening the device
should be enough to start tracing and closing it enough to
stop tracing.

You write "startsyscall" to <pid>/syscall for every trace
buffer read  -- don't quite understand why that is needed.

-- bakul

truss excerpt:

read(3,"libpthread.so.1 libthr.so.1\nlib"...,4096) = 81 (0x51)
read(3,0x800535000,4096)                         = 0 (0x0)
close(3)                                         = 0 (0x0)
open("/var/run/ld-elf.so.hints",O_RDONLY,0160)   = 3 (0x3)
read(3,"Ehnt\^A\0\0\0\M^@\0\0\0\M-,\^B\0"...,128) = 128 (0x80)

Corresponding ktrace/kdump excerpt:

 61555 cat      CALL  read(0x3,0x800535000,0x1000)
 61555 cat      GIO   fd 3 read 81 bytes
       "libpthread.so.1 libthr.so.1
        libpthread.so.2 libthr.so.2
        libkse.so.3 libthr.so.3

       "
 61555 cat      RET   read 81/0x51
 61555 cat      CALL  read(0x3,0x800535000,0x1000)
 61555 cat      GIO   fd 3 read 0 bytes
       ""
 61555 cat      RET   read 0
 61555 cat      CALL  close(0x3)
 61555 cat      RET   close 0
 61555 cat      CALL  open(0x80052d74b,O_RDONLY,<unused>0x70)
 61555 cat      NAMI  "/var/run/ld-elf.so.hints"
 61555 cat      RET   open 3
 61555 cat      CALL  read(0x3,0x7fffffffdc00,0x80)
 61555 cat      GIO   fd 3 read 128 bytes
       0x0000 4568 6e74 0100 0000 8000 0000 ac02 0000  |Ehnt............|
       0x0010 0000 0000 ab02 0000 0000 0000 0000 0000  |................|
       0x0020 0000 0000 0000 0000 0000 0000 0000 0000  |................|
       0x0030 0000 0000 0000 0000 0000 0000 0000 0000  |................|
       0x0040 0000 0000 0000 0000 0000 0000 0000 0000  |................|
       0x0050 0000 0000 0000 0000 0000 0000 0000 0000  |................|
       0x0060 0000 0000 0000 0000 0000 0000 0000 0000  |................|
       0x0070 0000 0000 0000 0000 0000 0000 0000 0000  |................|
 61555 cat      RET   read 128/0x80

More verbose but more informative and more useful.

Re: [9fans] system call trace version of 9vx available.

[ron minnich]

On Wed, May 19, 2010 at 1:30 PM, Bakul Shah <bakul+plan9@bitblocks.com> wrote:

> You write "startsyscall" to <pid>/syscall for every trace
> buffer read  -- don't quite understand why that is needed.

It gives you the option of not restarting the system call until later.
There could be more complex usage scenarios.

But it's a very good point. We've talked about dumping this data via
the trace facility instead. Trace facility is well designed for this
type of output -- I've got a proposal in which Sape says is ok for
changing the format of the trace records.

So, things can still change. One question though -- once you get to
the point of really complex examination of system calls, would acid be
better? Or do you see a use for ratrace (that name is kind of funny
and has the virtue of being typable on my keyboard with one hand) just
to dump more data and make all data visible? Your point about lost
information is a good one.

ron

Re: [9fans] system call trace version of 9vx available.

[ron minnich]

1.name changed to ratrace
2. output now to stderr

3. phooey. For some reason when a syscall fails the errstr prints an
empty string. 9vx/trap.c: any suggestions?

ron

Re: [9fans] system call trace version of 9vx available.

[ron minnich]

On Wed, May 19, 2010 at 2:48 PM, ron minnich <rminnich@gmail.com> wrote:

> 3. phooey. For some reason when a syscall fails the errstr prints an
> empty string. 9vx/trap.c: any suggestions?

Fixed.

Ron

Re: [9fans] system call trace version of 9vx available.

[Nick LaForge]

You THINK you have lots of control when you're dropping 'into' acid.

Re: [9fans] system call trace version of 9vx available.

[Bakul Shah]

On Wed, 19 May 2010 13:38:36 PDT ron minnich <rminnich@gmail.com>  wrote:
> On Wed, May 19, 2010 at 1:30 PM, Bakul Shah <bakul+plan9@bitblocks.com> wro=
> te:
>
> > You write "startsyscall" to <pid>/syscall for every trace
> > buffer read -- don't quite understand why that is needed.
>
> It gives you the option of not restarting the system call until later.
> There could be more complex usage scenarios.

I don't understand this.

> But it's a very good point. We've talked about dumping this data via
> the trace facility instead. Trace facility is well designed for this
> type of output -- I've got a proposal in which Sape says is ok for
> changing the format of the trace records.

You will go over to the dark side of binary formats? Horrors!

> So, things can still change. One question though -- once you get to
> the point of really complex examination of system calls, would acid be
> better? Or do you see a use for ratrace (that name is kind of funny
> and has the virtue of being typable on my keyboard with one hand) just
> to dump more data and make all data visible? Your point about lost
> information is a good one.

There is value in being able to trace syscalls outside of a
debugger. For instance I have done things like

    strace -f make -j14 |& grep 'open("'
    ktrace -di make -j14 && kdump | grep 'open("'

to look at parallel build problems due to messed up
dependencies. I have used tracing to find all the annoying
hidden config files, dlopened shared libs, pam (pluggable
authentication module) and what not that programs seem to use
these days.

I like the simplicity of cat <pid>/syscall!

Re: [9fans] system call trace version of 9vx available.

[ron minnich]

On Wed, May 19, 2010 at 3:02 PM, Bakul Shah <bakul+plan9@bitblocks.com> wrote:

>> It gives you the option of not restarting the system call until later.
>> There could be more complex usage scenarios.
>
> I don't understand this.

You read the "start of the system call" message. The process is
stopped. It has not run the system call.

You have a lot of options at that point. You could, programatically,
drop the person into acid (the debugger, not the liquid) and, when
they exit, resume the process. You really do have lots of control.


> You will go over to the dark side of binary formats? Horrors!

no, the change might include not being binary. Don't know.



thanks

ron

Re: [9fans] system call trace version of 9vx available.

[Devon H. O'Dell]

2010/5/19 ron minnich <rminnich@gmail.com>:
> On Wed, May 19, 2010 at 3:02 PM, Bakul Shah <bakul+plan9@bitblocks.com> wrote:
>
>>> It gives you the option of not restarting the system call until later.
>>> There could be more complex usage scenarios.
>>
>> I don't understand this.
>
> You read the "start of the system call" message. The process is
> stopped. It has not run the system call.
>
> You have a lot of options at that point. You could, programatically,
> drop the person into acid (the debugger, not the liquid) and, when
> they exit, resume the process. You really do have lots of control.

But there's nothing more fun than watching someone scream in a HCl
bath of high molarity, especially after they've made a dumb
programming error! (Sorry for the noise, I had to.)

--dho

Re: [9fans] system call trace version of 9vx available.

[Bakul Shah]

On Wed, 19 May 2010 15:25:52 PDT ron minnich <rminnich@gmail.com>  wrote:
> On Wed, May 19, 2010 at 3:02 PM, Bakul Shah <bakul+plan9@bitblocks.com> wrote
> :
>
> >> It gives you the option of not restarting the system call until later.
> >> There could be more complex usage scenarios.
> >
> > I don't understand this.
>
> You read the "start of the system call" message. The process is
> stopped. It has not run the system call.
>
> You have a lot of options at that point. You could, programatically,
> drop the person into acid (the debugger, not the liquid) and, when
> they exit, resume the process. You really do have lots of control.

What I don't understand is why do I need these options. I
just want tracing. I don't want to do acid (debugger, low pH
liquid or LSD)! But never mind. I probably won't get it.

Why is the performance so poor?

cd ratrace
mk clean
time ratrace -o /dev/null -c mk	# about 19.67 seconds
mk clean
time mk				# about 0.88 seconds

And here I thought naming it ratrace would make it go faster.
[yes, I added the -o option for precisely this sort of thing)

Re: [9fans] system call trace version of 9vx available.

[ron minnich]

On Wed, May 19, 2010 at 5:26 PM, Bakul Shah <bakul+plan9@bitblocks.com> wrote:

> time ratrace -o /dev/null -c mk # about 19.67 seconds

did you want [2]>/dev/null?

> mk clean
> time mk                         # about 0.88 seconds
>
> And here I thought naming it ratrace would make it go faster.

Speed is left as an exercise for the reader.

But, if you want, you can use ratrace to trace ratrace to see how long
things take. I assume it is the cost of doing the output, but who
knows?

ron

Re: [9fans] system call trace version of 9vx available.

[ron minnich]

I had a question from someone about the syscalltrace. It has not
relationship to the earlier devtrace  work that Floren and I did.

Thanks

ron

Re: [9fans] system call trace version of 9vx available.

[Bakul Shah]

On Wed, 19 May 2010 17:32:19 PDT ron minnich <rminnich@gmail.com>  wrote:
> On Wed, May 19, 2010 at 5:26 PM, Bakul Shah <bakul+plan9@bitblocks.com> wro=
> te:
>
> > time ratrace -o /dev/null -c mk # about 19.67 seconds
>
> did you want [2]>/dev/null?

No, because that eats time output as well. My change uses a
new fd if -o is specified, 2 otherwise.

> > mk clean
> > time mk # about 0.88 seconds
> >
> > And here I thought naming it ratrace would make it go faster.
>
> Speed is left as an exercise for the reader.

On a 5 year old T42 thinkpad running freebsd:

    mk clean
    time ratrace -o /dev/null -c mk	# 2.57 seconds
    mk clean
    time mk				# 0.18 seconds

So may be it is 9vx (and freebsd on i386 vs macos on x86_64)

But there are other issues:

term% cat x.c
#include <u.h>
#include <libc.h>
void main(int c, char**v) {
	fork()? print("parent\n") : print("child\n");
	exits(nil);
}
term% 8c x.c && 8l x.8 && ratrace -c 8.out
178 8.out Rfork 0x1259 00002014child
 = 180 "" 0x11af831799634530 0x11af83179b3a4368
178 8.out Pwrite 0x297d 1 0ffffe0c/"parent." 7 -0x1parent
 = 6 "" 0x11af83179f9d7a60 0x11af8317a93a9d28
 = 7 "" 0x11af8317b1743468 0x11af8317bb73ed78
180 8.out Open 0x120b 0000601c/"#c/pid" 00000000 = 3 "" 0x11af8317c915bc18 0x11af8317c91b5998
178 8.out Open 0x120b 0000601c/"#c/pid" 00000000 = 3 "" 0x11af8317d3cd6700 0x11af8317d3d2fcb0
180 8.out Pread 0x29b0 3 0fffff2c/"........180." 20 -0x1 = 12 "" 0x11af8317dea5ad90 0x11af8317deab08a8
180 8.out Close 0x1239 3 = 0 "" 0x11af8317ebe03a98 0x11af8317ebe39210
180 8.out Exits 0x118b 0/""cwrite: /proc/180/syscall: failed 12 bytes: process exited
178 8.out Pread 0x29b0 3 0fffff2c/"........178." 20 -0x1 = 12 "" 0x11af8317fac10d30 0x11af8317fac65c90
178 8.out Close 0x1239 3 = 0 "" 0x11af83180d0e04c0 0x11af83180d113910
178 8.out Exits 0x118b 0/""cwrite: /proc/178/syscall: failed 12 bytes: process exited
term%

Notice the child's Pwrite is missing but its result shows
up.  After the 2nd line of ratrace output there should be

 = 0 "" 0x11af831799634530 0x11af83179b3XXXXX

to indicate rfork's return in the child but that is missing too.

I need to find time to hack on this!

Re: [9fans] system call trace version of 9vx available.

[John Floren]

On Wed, May 19, 2010 at 2:23 PM, Bakul Shah <bakul+plan9@bitblocks.com> wrote:
> On Wed, 19 May 2010 10:41:26 PDT ron minnich <rminnich@gmail.com>  wrote:
>> On Wed, May 19, 2010 at 10:18 AM, Bakul Shah <bakul+plan9@bitblocks.com> wrote
>>
>> > 0. Name syscalltrace is too long :-)
>>
>> pick a name and I'll change it.
>
> I used strace but don't really care what you call it as long
> as it is short!  How about ratrace (Ron's ascii trace)?
>

I think "ratrace" is a damn fine name, given that it's both "Ron's
ASCII trace" and "rat race"

John
-- 
"With MPI, familiarity breeds contempt. Contempt and nausea. Contempt,
nausea, and fear. Contempt, nausea, fear, and .." -- Ron Minnich

Re: [9fans] system call trace version of 9vx available.

[erik quanstrom]

> > 			if (cmd[0] != '/') {
> > 				char* pcmd = malloc(strlen(cmd) + 5);
> > 				sprintf(pcmd, "/bin/%s", cmd);
> > 				exec(pcmd, args);
> > 			}

shouldn't that be

 			if (cmd[0] != '/')
				exec(smprint("/bin/%s", cmd), args);

with no silly stdio?

- erik

Re: [9fans] system call trace version of 9vx available.

[ron minnich]

On Wed, May 19, 2010 at 10:51 AM, erik quanstrom
<quanstro@labs.coraid.com> wrote:
>> >                     if (cmd[0] != '/') {
>> >                             char* pcmd = malloc(strlen(cmd) + 5);
>> >                             sprintf(pcmd, "/bin/%s", cmd);
>> >                             exec(pcmd, args);
>> >                     }
>
> shouldn't that be
>
>                        if (cmd[0] != '/')
>                                exec(smprint("/bin/%s", cmd), args);
>


indeed.

ron

Re: [9fans] system call trace version of 9vx available.

[ron minnich]

I'll only take that patch if it does NOT include stdio.h.

As for output ... I'm conflicted on output on 1 vs. 2. But it is nice
that you can see normal output of the traced process. But, hmm, if
traced process prints on 2, well ... you'll lose it.

So, my feeling is, if you are *really* concerned about output and
interaction with the process, run rc in another window, and
syscalltrace <pid-of-rc>

ron

Re: [9fans] system call trace version of 9vx available.

[Bakul Shah]

On Wed, 19 May 2010 10:53:59 PDT ron minnich <rminnich@gmail.com>  wrote:
> I'll only take that patch if it does NOT include stdio.h.

Well, you have the trivial diff so do what you want.

> As for output ... I'm conflicted on output on 1 vs. 2. But it is nice
> that you can see normal output of the traced process. But, hmm, if
> traced process prints on 2, well ... you'll lose it.

1 is the working channel -- where most useful thing show up.
The issue is that the output of the traced process is
intermingled with syscalltrace and that just doesn't make
sense.  They are different things. With output to 2 I can
redirect it where I want.

BTW, truss does the same thing (output to stderr).  ktrace on
FreeBSD finesses by just dumping trace output to a file and
then kdump is used to show it.

> So, my feeling is, if you are *really* concerned about output and
> interaction with the process, run rc in another window, and
> syscalltrace <pid-of-rc>

Too much work.

Re: [9fans] system call trace version of 9vx available.

[ron minnich]

On Wed, May 19, 2010 at 11:43 AM, Bakul Shah <bakul+plan9@bitblocks.com> wrote:

> BTW, truss does the same thing (output to stderr).  ktrace on
> FreeBSD finesses by just dumping trace output to a file and
> then kdump is used to show it.
>

strace on linux sends to stderr as well.

OK, you win, I'll change that one. It bothers me to lose error output however.

I should probably open /dev/cons on fd 3 and let people redirect or
something. That way, default behavior is simple and we still have
child process owning 1` and 2.

ron

Re: [9fans] system call trace version of 9vx available.

[erik quanstrom]

> strace on linux sends to stderr as well.
>
> OK, you win, I'll change that one. It bothers me to lose error output however.

if you really need bug-for-bug compatability,
you can always ratrace >[1=2] | ...

- erik