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