weird ktrace timestamps?

[der Mouse <mouse%Rodents-Montreal.ORG@localhost>]

Is there known to be something weird with ktrace record timestamps
under 4.0.1 (i386, in case it matters)?

I just did some ktracing (using ktrace -i -p ..., in case it matters)
on an i386 machine.  The first two lines of kdump -R output on the
resulting file were

   693      1 xshowppm 0.000000000 EMUL  "netbsd"
   693      1 xshowppm -1.999996647 CALL  accept(3,0xbfbfe90c,0xbfbfe908)

The peculiar apparent timewarp made me look deeper.  Here's (the
beginning of) hexdump -C output on ktrace.out:

00000000  06 00 00 00 07 00 01 00  b5 02 00 00 78 73 68 6f  |............xsho|
00000010  77 70 70 6d 00 00 00 00  00 00 00 00 00 00 00 00  |wppm............|
00000020  8e 89 59 4c 97 15 a1 2a  01 00 00 00 6e 65 74 62  |..YL...*....netb|
00000030  73 64 14 00 00 00 01 00  01 00 b5 02 00 00 78 73  |sd............xs|
00000040  68 6f 77 70 70 6d 00 00  00 00 00 00 00 00 00 00  |howppm..........|
00000050  00 00 8e 89 59 4c 7e 08  a1 2a 01 00 00 00 1e 00  |....YL~..*......|
00000060  00 00 0c 00 00 00 03 00  00 00 0c e9 bf bf 08 e9  |................|
00000070  bf bf 10 00 00 00 02 00  01 00 b5 02 00 00 78 73  |..............xs|

Based on <sys/ktrace.h>, I break down the first two records as

06 00 00 00             ktr_len, 6
07 00                   ktr_type, KTR_EMUL
01 00                   ktr_version, 1
b5 02 00 00             ktr_pid, 0x2b5 = 693
78 73 68 6f 77 70 70 6d ktr_comm, "xshowppm"
00 00 00 00 00 00 00 00
00
00 00 00                (compiler-generated struct padding)
8e 89 59 4c 97 15 a1 2a ktr_time (_ktr_time._ts), 1280936334.715199895
01 00 00 00             ktr_lid (_ktr_id._lid), 1
6e 65 74 62 73 64       record contents, "netbsd"

14 00 00 00             ktr_len, 20
01 00                   ktr_type, KTR_SYSCALL
01 00                   ktr_version, 1
b5 02 00 00             ktr_pid, 0x2b5 = 693
78 73 68 6f 77 70 70 6d ktr_comm, "xshowppm"
00 00 00 00 00 00 00 00
00
00 00 00                (compiler-generated struct padding)
8e 89 59 4c 7e 08 a1 2a ktr_time (_ktr_time._ts), 1280936334.715196542
01 00 00 00             ktr_lid (_ktr_id._lid), 1
1e 00 00 00 0c 00 00 00 record contents
03 00 00 00 0c e9 bf bf
08 e9 bf bf

There are two interesting things here: the timestamps in the file do
not warp backwards by almost two seconds - but they do warp backwards,
by 3353 ns.

So, there are two strange things here: (1) that the timestamps in the
file go backwards and (2) that kdump prints them as going backward much
further than they actually do.

This is not just ntpd happening by bad luck to adjust the clock right
then; I did another run and got the same syndrome (with a very slightly
different time delta) at the same point - the first and second records
of the file. Furthermore, the program forks, and the first two records
generated by the child show a very similar bogon in kdump output:

   693      1 xshowppm 0.000004470 CALL  write(9,0x806c000,0x2800)
   721      1 xshowppm 0.000012292 EMUL  "netbsd"
   721      1 xshowppm -1.999997486 RET   fork 0
   693      1 xshowppm 0.000005866 GIO   fd 9 wrote 4088 bytes

I haven't dug out the underlying records for this case; it's far enough
into the file they would be inconvenient to locate.  But the kdump
output is similar enough that I would expect it to be due to the same
cause, whatever it is.

Any thoughts?  I'll investigate this eventually if I don't hear
anything, but it strikes me as reasonably likely that someone will
recognize the syndrome and be able to point me in a useful direction.

/~\ The ASCII                             Mouse
\ / Ribbon Campaign
 X  Against HTML                mouse%rodents-montreal.org@localhost
/ \ Email!           7D C8 61 52 5D E7 2D 39  4E F1 31 3E E8 B3 27 4B