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 mo...@rodents-montreal.org / \ Email! 7D C8 61 52 5D E7 2D 39 4E F1 31 3E E8 B3 27 4B