Subject: tcptrace-bugs Time error with large files Date: Tue, 7 Jan 2003 14:17:27 +1000 Message-ID: <231DAA6464F5D311B0A30008C7F90735046C5D68@ntmsg0134.corpmail.telstra.com.au> From: "Desem, Can" <Can.Desem@team.telstra.com>
When processing large dump files (pcap) with several thousand connections, the microsecond portion of the time stamps starts to be in error after about a thousand or several thousand connections. All the subsequent connections are similarly in error. The microsecond portion of the time stamp will always start with three zeros like;
" first packet: Thu Dec 12 00:56:11.000123 2002 "
However, if the packets of the particular connection is extracted into another dump file then there is no error when processed with tcptrace.
More detail:
The original pcap file (DCR14) was about 200MBytes. The tcptrace output after about 10k connections are all in error. One particular connection is extracted to show the error. A smaller file is generated by extracting the packets for this connection. Tcptrace (6.2.0 on Linux 2.4.18 debian)is then used to process the two files.
Attached is the difference of two tcptrace outputs (the ip addresses are randomized for privacy) after the result of the following processes;
tcptrace -nlr -o20201 DCR14 >long
tcpdump -n -r DCR14 -w DCR14_short port 2542 and port 3804
tcptrace -nlr DCR14_short >short
diff long short
1c1
< 1 arg remaining, starting with 'DCR14'
--- > 1 arg remaining, starting with 'tempDCR14' 4,6c4,6 < 4035222 packets seen, 2549793 TCP packets traced < elapsed wallclock time: 0:00:31.147990, 129549 pkts/sec analyzed < trace file elapsed time: 0:20:16.059687 --- > 30 packets seen, 30 TCP packets traced > elapsed wallclock time: 0:00:00.000504, 59523 pkts/sec analyzed > trace file elapsed time: 0:01:26.970124 8,12c8,11 < 87582 TCP connections traced: < ================================ < TCP connection 20201: < host bgsw: 222.26.125.159:2542 < host bgsx: 114.232.11.93:3804 --- > 1 TCP connection traced: > TCP connection 1: > host a: 222.26.125.159:2542 > host b: 114.232.11.93:3804 14,16c13,15 < first packet: Thu Dec 12 00:56:11.000229 2002 < last packet: Thu Dec 12 00:57:38.000199 2002 < elapsed time: 0:01:26.999969 --- > first packet: Thu Dec 12 00:56:11.229380 2002 > last packet: Thu Dec 12 00:57:38.199504 2002 > elapsed time: 0:01:26.970124 18,19c17,18 < filename: DCR14 < bgsw->bgsx: bgsx->bgsw: --- > filename: tempDCR14 > a->b: b->a: 54,55c53,54 < data xmit time: 0.000 secs data xmit time: 75.000 secs < idletime max: 25999.7 ms idletime max: 22000.0 ms --- > data xmit time: 0.000 secs data xmit time: 75.281 secs > idletime max: 25728.1 ms idletime max: 22005.6 ms 59,62c58,61 < RTT min: 0.0 ms RTT min: 2999.7 ms < RTT max: 0.0 ms RTT max: 19000.1 ms < RTT avg: 0.0 ms RTT avg: 7249.6 ms < RTT stdev: 0.0 ms RTT stdev: 7847.7 ms --- > RTT min: 8.8 ms RTT min: 2704.1 ms > RTT max: 13.1 ms RTT max: 19057.3 ms > RTT avg: 11.6 ms RTT avg: 7045.8 ms > RTT stdev: 2.4 ms RTT stdev: 8014.5 ms 64c63 < RTT from 3WHS: 0.0 ms RTT from 3WHS: 0.0 ms --- > RTT from 3WHS: 8.8 ms RTT from 3WHS: 0.0 ms 67,70c66,69 < RTT full_sz min: 0.0 ms RTT full_sz min: 2999.7 ms < RTT full_sz max: 0.0 ms RTT full_sz max: 19000.1 ms < RTT full_sz avg: 0.0 ms RTT full_sz avg: 7249.6 ms < RTT full_sz stdev: 0.0 ms RTT full_sz stdev: 7847.7 ms --- > RTT full_sz min: 13.1 ms RTT full_sz min: 2704.1 ms > RTT full_sz max: 13.1 ms RTT full_sz max: 19057.3 ms > RTT full_sz avg: 13.1 ms RTT full_sz avg: 7045.8 ms > RTT full_sz stdev: 0.0 ms RTT full_sz stdev: 8014.5 ms 78,81c77,80 < RTT min (last): 0.0 ms RTT min (last): 3999.7 ms < RTT max (last): 0.0 ms RTT max (last): 4999.8 ms < RTT avg (last): 0.0 ms RTT avg (last): 4333.0 ms < RTT sdv (last): 0.0 ms RTT sdv (last): 577.3 ms --- > RTT min (last): 0.0 ms RTT min (last): 3705.3 ms > RTT max (last): 0.0 ms RTT max (last): 4833.9 ms > RTT avg (last): 0.0 ms RTT avg (last): 4182.6 ms > RTT sdv (last): 0.0 ms RTT sdv (last): 584.0 ms 86,89c85,88 < min retr time: 0.0 ms min retr time: 3000.0 ms < max retr time: 0.0 ms max retr time: 25999.7 ms < avg retr time: 0.0 ms avg retr time: 15166.5 ms < sdv retr time: 0.0 ms sdv retr time: 8134.2 ms --- > min retr time: 0.0 ms min retr time: 2954.1 ms > max retr time: 0.0 ms max retr time: 25725.5 ms > avg retr time: 0.0 ms avg retr time: 15298.8 ms > sdv retr time: 0.0 ms sdv retr time: 8081.4 msOne can see that the microsecond portion of the time stamp seems to be shifted by three zeros (this behaviour seems consistent when looking at other connections). The same error occurs on shorter files which contain only a few thousand connections.
Regards, Can Desem Telstra Research Laboratories
This archive was generated by hypermail 2b30 : 01/07/03 EST