Subject: Re: syscall tracing
To: None <tech-kern@NetBSD.ORG>
From: der Mouse <mouse@Collatz.McRCIM.McGill.EDU>
List: tech-kern
Date: 03/21/1995 14:08:18
Adam Glass writes:

> Compare this proposed mechanism with that provided by
> ktrace(1)/kdump(1) and the underlying ktrace(2) system call.

That's right, I'd forgotten about ktrace, so I didn't mention it or
discuss why I think PT_SYSCALL is worthwhile even though ktrace exists.
But PT_SYSCALL provides significant additional functionality beyond
ktrace().  Specifically,

- PT_SYSCALL lets you take arbitrary actions when a syscall is made,
  such as, for example, a forced sleep for a short time when a read()
  is done from certain file descriptors.  (This unlikely-sounding
  example is one I actually had occasion to hack my tracer to
  implement, which is why I picked it.)

- PT_SYSCALL lets you dump out arguments far more verbosely than
  ktrace() allows, since by the time kdump gets hold of things, all it
  has is what was recorded in the file.

- PT_SYSCALL lets you short-circuit the syscall and/or replace it with
  another, so that you can (for example) build a tracing program that
  prevents the traced program from accessing certain paths, or prevents
  it from making certain network calls, or "redirects" certain
  pathnames to certain others, or whatever your fevered brain can
  imagine.  (SunOS PTRACE_SYSCALL lets you do only some of this.)

Of course, PT_SYSCALL also puts more of a crimp in the traced
processes' performance.  This is the inevitable price for the extra
functionality.

As an example of the second point, here is a side-by-side comparison.
First, I ran "ktrace date" and "kdump":

  7298 ktrace   RET   ktrace 0
[lots more "ktrace" lines omitted]
  7298 ktrace   CALL  execve(0xf7fff200,0xf7fff6d0,0xf7fff6d8)
  7298 ktrace   NAMI  "/bin/date"
  7298 date     RET   execve 0
  7298 date     CALL  gettimeofday(0xf7fff1f8,0)
  7298 date     RET   gettimeofday 0
  7298 date     CALL  open(0x58d8,0,0)
  7298 date     NAMI  "/etc/localtime"
  7298 date     RET   open 3
  7298 date     CALL  read(0x3,0xf7ffe270,0x9dc)
  7298 date     GIO   fd 3 read 756 bytes
       "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\^B\0\0\0\0\0\0\
	\0\M^J\0\0\0\^B\0\0\0\b\M-~\M-8\^\\M-p\M^?\M-'\M^?\M-`\0\M^W\M-~\M-p\
	\^A\M^G\M-a\M-`\^Bw\M-`\M-p\^Cp\M-~`\^D`\M-}p\^EP\M-``\^F@\M-_p\a0\M-B\
	`\b \M-Ap	\^P\M-$`
[22 lines, 1443 bytes, of expanded data omitted]
	\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\
	\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\
	\M^?\M^?\M-G\M-@\^A\0\M^?\M^?\M-9\M-0\0\^DEDT\0EST\0\0\0"
  7298 date     RET   read 756/0x2f4
  7298 date     CALL  close(0x3)
  7298 date     RET   close 0
  7298 date     CALL  open(0x58d8,0,0x2)
  7298 date     NAMI  "/etc/localtime"
  7298 date     RET   open 3
  7298 date     CALL  read(0x3,0xf7ffe2e0,0x9dc)
  7298 date     GIO   fd 3 read 756 bytes
       "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\^B\0\0\0\0\0\0\
	\0\M^J\0\0\0\^B\0\0\0\b\M-~\M-8\^\\M-p\M^?\M-'\M^?\M-`\0\M^W\M-~\M-p\
	\^A\M^G\M-a\M-`\^Bw\M-`\M-p\^Cp\M-~`\^D`\M-}p\^EP\M-``\^F@\M-_p\a0\M-B\
	`\b \M-Ap	\^P\M-$`
[same stuff omitted as above]
	\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\
	\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\0\^A\
	\M^?\M^?\M-G\M-@\^A\0\M^?\M^?\M-9\M-0\0\^DEDT\0EST\0\0\0"
  7298 date     RET   read 756/0x2f4
  7298 date     CALL  close(0x3)
  7298 date     RET   close 0
  7298 date     CALL  fstat(0x1,0xf7ffed30)
  7298 date     RET   fstat 0
  7298 date     CALL  __sysctl(0xf7ffed20,0x2,0xf7ffed1c,0xf7ffed18,0,0)
  7298 date     RET   __sysctl 4
  7298 date     CALL  break(0x14978)
  7298 date     RET   break 0
  7298 date     CALL  break(0x14ffc)
  7298 date     RET   break 0
  7298 date     CALL  break(0x19ffc)
  7298 date     RET   break 0
  7298 date     CALL  ioctl(0x1,0x402c7413 ,0xf7ffed60)
  7298 date     RET   ioctl 0
  7298 date     CALL  write(0x1,0x15000,0x1d)
  7298 date     GIO   fd 1 wrote 29 bytes
       "Tue Mar 21 12:16:16 EST 1995
       "
  7298 date     RET   write 29/0x1d
  7298 date     CALL  exit(0)

Presumably anyone can get a similar listing by running similar
commands.  Now, here's the output from my tracer
("trc -o date.trc date"):

gettimeofday (0xf7fff1f8, 0x0) = 0: time=<Tue Mar 21 17:16:38 1995 +.456592s>
open (0x58d8="/etc/localtime", 0x0=O_RDONLY) = 3
read (3, 0xf7ffe270, 2524) = 756: "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\212\0\0\0\2\0\0\0\b\376\270\34\360\377\247\377\340\0\227\376\360\1\207\341\340\2w\340\360\3p\376`\4`\375p\5P\340`\6@\337p\a0\302`\b \301p\t\20\244`\n\0\243p\n\360\206`\v\340\205p\f\331\242\340\r\300gp\16\271\204\340\17\251\203\360\20\231f\340\21\211e\360\22yH\340\23iG\360\24Y*\340\25I)\360\0269\f\340\27)\v\360\30\")`\31\b\355\360\32\2\v`\32\362\np\e\341\355`\34\321\354p\35\301\317`\36\261\316p\37\241\261` v\0\360!\201\223`\"U\342\360#j\257\340$5\304\360%J\221\340&\25\246\360'*s\340'\376\303p)\nU\340)\336\245p*\3527\340+\276\207p,\323T`-\236ip.\2636`/~Kp"...
close (3) = 0
open (0x58d8="/etc/localtime", 0x0=O_RDONLY) = 3
read (3, 0xf7ffe2e0, 2524) = 756: "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\212\0\0\0\2\0\0\0\b\376\270\34\360\377\247\377\340\0\227\376\360\1\207\341\340\2w\340\360\3p\376`\4`\375p\5P\340`\6@\337p\a0\302`\b \301p\t\20\244`\n\0\243p\n\360\206`\v\340\205p\f\331\242\340\r\300gp\16\271\204\340\17\251\203\360\20\231f\340\21\211e\360\22yH\340\23iG\360\24Y*\340\25I)\360\0269\f\340\27)\v\360\30\")`\31\b\355\360\32\2\v`\32\362\np\e\341\355`\34\321\354p\35\301\317`\36\261\316p\37\241\261` v\0\360!\201\223`\"U\342\360#j\257\340$5\304\360%J\221\340&\25\246\360'*s\340'\376\303p)\nU\340)\336\245p*\3527\340+\276\207p,\323T`-\236ip.\2636`/~Kp"...
close (3) = 0
fstat (1, 0xf7ffed30) = 0
__sysctl (0xf7ffed20=<6,7>=<HW,PAGESIZE>, 2, 0xf7ffed1c, 0xf7ffed18=4, 0x0, 0) = 4: value=4096
obreak (0x14978) = 0
obreak (0x14ffc) = 0
obreak (0x19ffc) = 0
#54[ioctl](0x1, 0x402c7413, 0xf7ffed60) = 0x0 0x402c7413
write (1, 0x15000="Tue Mar 21 12:16:38 EST 1995\n", 29) = 29
exit (0) = [exited with status 0]

Notice that it printed the time returned by gettimeofday, the
pointed-to arguments for __sysctl (first and fourth) and the returned
value 4096.  The SunOS version would also unpack the ioctl call to
something like this, which is taken from a real SunOS run:
	ioctl (1, 0x40125401=TCGETA, 0xefffeeac) = 0: tio=<i:0x2526=BRKINT|IGNPAR|ISTRIP|ICRNL|IXON|IMAXBEL,o:0x5=OPOST|ONLCR,c:0x1af=B38400|CS7|CREAD|PARENB,l:0x8a3b=ISIG|ICANON|ECHO|ECHOE|ECHOK|ECHOCTL|ECHOKE|IEXTEN,d:0,cc:<intr=^C,quit=^\,erase=^?,kill=^X,eof=^Z,eol=^@,eol2=^@,swtch=^@>,min=26,time=0>
and the NetBSD one could do the same thing if I had gotten around to
writing the necessary code.

That's why I don't consider ktrace a reason to reject PT_SYSCALL.

					der Mouse

			    mouse@collatz.mcrcim.mcgill.edu