From dillon@best.net Wed Jun 10 10:53:06 PDT 1998 news1 is my diablo machine. 206.86.0.12 is one of my NNTP machines. The data below indicates that my diablo machine is able to keep the TCP queue to the nntp machine relatively full. news1:/news> netstat -tn | fgrep 206.86.0.12 | fgrep ESTAB tcp 0 0 209.24.149.21.4414 206.86.0.12.434 ESTABLISHED tcp 345 1216 209.24.149.21.4374 206.86.0.12.434 ESTABLISHED news1:/news> netstat -tn | fgrep 206.86.0.12 | fgrep ESTAB tcp 0 0 209.24.149.21.4414 206.86.0.12.434 ESTABLISHED tcp 0 2752 209.24.149.21.4374 206.86.0.12.434 ESTABLISHED news1:/news> netstat -tn | fgrep 206.86.0.12 | fgrep ESTAB tcp 0 0 209.24.149.21.4414 206.86.0.12.434 ESTABLISHED tcp 107 1216 209.24.149.21.4374 206.86.0.12.434 ESTABLISHED news1:/news> netstat -tn | fgrep 206.86.0.12 | fgrep ESTAB tcp 0 0 209.24.149.21.4414 206.86.0.12.434 ESTABLISHED tcp 107 608 209.24.149.21.4374 206.86.0.12.434 ESTABLISHED news1:/news> netstat -tn | fgrep 206.86.0.12 | fgrep ESTAB tcp 0 0 209.24.149.21.4414 206.86.0.12.434 ESTABLISHED tcp 107 992 209.24.149.21.4374 206.86.0.12.434 ESTABLISHED news1:/news> netstat -tn | fgrep 206.86.0.12 | fgrep ESTAB tcp 0 0 209.24.149.21.4414 206.86.0.12.434 ESTABLISHED tcp 107 0 209.24.149.21.4374 206.86.0.12.434 ESTABLISHED news1:/news> netstat -tn | fgrep 206.86.0.12 | fgrep ESTAB tcp 0 0 209.24.149.21.4414 206.86.0.12.434 ESTABLISHED tcp 218 65536 209.24.149.21.4374 206.86.0.12.434 ESTABLISHED p.s. note that I'm using large TCP buffers... 65536, in fact. This may not work properly with earlier FreeBSD releases due to a bug in the tcp stack, so if you aren't sure you should use 49152 byte tcp windows. Ok, on my INN box, the netstat -tn of the same connections indicates that the RECEIVE queue is staying relatively full, meaning that the INN box is not able to drain it quickly enough meaning that INN is loaded. (in my case, this is an old INN which I've tuned up the wazoo. It barely keeps up with a full feed even after diablo's spam filter): nntp2:/news> netstat -tn | fgrep 209.24.149.21 tcp 0 0 206.86.0.12.434 209.24.149.21.4414 ESTABLISHED tcp 81920 0 206.86.0.12.434 209.24.149.21.4374 ESTABLISHED nntp2:/news> netstat -tn | fgrep 209.24.149.21 tcp 0 0 206.86.0.12.434 209.24.149.21.4414 ESTABLISHED tcp 81920 0 206.86.0.12.434 209.24.149.21.4374 ESTABLISHED nntp2:/news> netstat -tn | fgrep 209.24.149.21 tcp 0 0 206.86.0.12.434 209.24.149.21.4414 ESTABLISHED tcp 81920 0 206.86.0.12.434 209.24.149.21.4374 ESTABLISHED nntp2:/news> netstat -tn | fgrep 209.24.149.21 tcp 0 0 206.86.0.12.434 209.24.149.21.4414 ESTABLISHED tcp 81920 0 206.86.0.12.434 209.24.149.21.4374 ESTABLISHED nntp2:/news> netstat -tn | fgrep 209.24.149.21 tcp 0 0 206.86.0.12.434 209.24.149.21.4414 ESTABLISHED tcp 33078 0 206.86.0.12.434 209.24.149.21.4374 ESTABLISHED nntp2:/news> netstat -tn | fgrep 209.24.149.21 tcp 0 0 206.86.0.12.434 209.24.149.21.4414 ESTABLISHED tcp 29686 0 206.86.0.12.434 209.24.149.21.4374 ESTABLISHED nntp2:/news> netstat -tn | fgrep 209.24.149.21 tcp 0 0 206.86.0.12.434 209.24.149.21.4414 ESTABLISHED tcp 0 53 206.86.0.12.434 209.24.149.21.4374 ESTABLISHED nntp2:/news> But the netstat alone may not give you enough information. After all, queues that big mean that I'm probably pushing large articles. So I ktrace the innd process for a while: nntp2:/news> ps x | fgrep innd 254 ?? D ktrace -p 254 nntp2:/news> sleep 60 nntp2:/news> ktrace -C nntp2:/news> kdump -R | less And I observe the kdump output to try to determine where the bottlenecks are (you would want to look at all the select()'s, I'm just printing the first 20 in this posting): Get a feel for the kdump output: nntp2:/news> kdump -R | less Here, the relatively low select() latencies indicate that select() is not blocking, which means that data is built up in the read queue from the socket and select is returning immediately... if most of the select()s are this way, INND is not able to read the data fast enough meaning that it is probably having problems doing history lookups or file writes. nntp2:/news> kdump -R | fgrep select | head -20 254 innd 897462359.252239 RET select 1 254 innd 0.000709 CALL select(0xe,0xefbfdc8c,0xefbfdc6c,0,0xefbfdc64) 254 innd 0.000031 RET select 1 254 innd 0.000095 CALL select(0xe,0xefbfdc8c,0xefbfdc6c,0,0xefbfdc64) 254 innd 0.000027 RET select 1 254 innd 0.000223 CALL select(0xe,0xefbfdc8c,0xefbfdc6c,0,0xefbfdc64) 254 innd 0.089403 RET select 1 254 innd 0.000514 CALL select(0xe,0xefbfdc8c,0xefbfdc6c,0,0xefbfdc64) 254 innd 0.000037 RET select 1 254 innd 0.000132 CALL select(0xe,0xefbfdc8c,0xefbfdc6c,0,0xefbfdc64) 254 innd 0.000198 RET select 1 254 innd 0.000110 CALL select(0xe,0xefbfdc8c,0xefbfdc6c,0,0xefbfdc64) 254 innd 0.099462 RET select 1 254 innd 0.001301 CALL select(0xe,0xefbfdc8c,0xefbfdc6c,0,0xefbfdc64) 254 innd 0.000036 RET select 1 254 innd 0.000249 CALL select(0xe,0xefbfdc8c,0xefbfdc6c,0,0xefbfdc64) 254 innd 0.000031 RET select 1 254 innd 0.000077 CALL select(0xe,0xefbfdc8c,0xefbfdc6c,0,0xefbfdc64) 254 innd 0.000431 RET select 1 254 innd 0.000069 CALL select(0xe,0xefbfdc8c,0xefbfdc6c,0,0xefbfdc64) Look at your open() latencies (or if you are using CNFS, look at open latencies and more importantly, seek/read/write latencies): In my case, open latencies are pretty bad since I'm using a normal filesystem. nntp2:/news> kdump -R | fgrep open 254 innd 0.013167 CALL open(0xefbfd654,0x601,0x1b4) 254 innd 0.001489 RET open 20/0x14 254 innd 0.009874 CALL open(0xefbfd654,0x601,0x1b4) 254 innd 0.203921 RET open 20/0x14 254 innd 0.010379 CALL open(0xefbfd654,0x601,0x1b4) 254 innd 0.060001 RET open 20/0x14 254 innd 0.012349 CALL open(0xefbfd654,0x601,0x1b4) 254 innd 0.040169 RET open 20/0x14 254 innd 0.015078 CALL open(0xefbfd654,0x601,0x1b4) 254 innd 0.181994 RET open 20/0x14 254 innd 0.015770 CALL open(0xefbfd654,0x601,0x1b4) 254 innd 0.183961 RET open 20/0x14 254 innd 0.012271 CALL open(0xefbfd654,0x601,0x1b4) 254 innd 0.367897 RET open 20/0x14 254 innd 0.012106 CALL open(0xefbfd654,0x601,0x1b4) 254 innd 0.106144 RET open 20/0x14 ... My seeks look pretty good (they'd better, the kernel doesn't actually do much for an lseek()): nntp2:/news> kdump -R | fgrep lseek | head -20 254 innd 0.000075 CALL lseek(0xe,0,0,0,0x1) 254 innd 0.000024 RET lseek 205250633/0xc3be049 254 innd 0.000137 CALL lseek(0x11,0,0x52a4f0,0,0) 254 innd 0.000027 RET lseek 5416176/0x52a4f0 254 innd 0.000942 CALL lseek(0x12,0,0x246ae3e,0,0) 254 innd 0.000034 RET lseek 38186558/0x246ae3e 254 innd 0.000058 CALL lseek(0x12,0,0x7e24df5,0,0) 254 innd 0.000024 RET lseek 132271605/0x7e24df5 254 innd 0.000055 CALL lseek(0x12,0,0x60818d3,0,0) 254 innd 0.000023 RET lseek 101193939/0x60818d3 254 innd 0.000090 CALL lseek(0xe,0,0,0,0x1) 254 innd 0.000024 RET lseek 205250713/0xc3be099 254 innd 0.000061 CALL lseek(0x11,0,0xb98008,0,0) 254 innd 0.000104 RET lseek 12156936/0xb98008 254 innd 0.000035 CALL lseek(0x10,0,0,0,0) 254 innd 0.000119 RET lseek 0 254 innd 0.000053 CALL lseek(0xe,0,0,0,0x1) 254 innd 0.000021 RET lseek 205250834/0xc3be112 254 innd 0.000067 CALL lseek(0x11,0,0xd03cc,0,0) 254 innd 0.000021 RET lseek 852940/0xd03cc My reads (mostly network reads and history reads): 254 innd 0.000154 RET read 4928/0x1340 254 innd 0.000029 CALL read(0x7,0x7b165a,0x2000) 254 innd 0.000125 GIO fd 7 read 7200 bytes 254 innd 0.000292 RET read 7200/0x1c20 254 innd 0.000067 CALL read(0x7,0x7b327a,0x2000) 254 innd 0.000094 GIO fd 7 read 4320 bytes 254 innd 0.000377 RET read 4320/0x10e0 254 innd 0.000025 CALL read(0x7,0x7b435a,0x2000) 254 innd 0.000071 GIO fd 7 read 2880 bytes 254 innd 0.000068 RET read 2880/0xb40 254 innd 0.000024 CALL read(0x7,0x7b4e9a,0x2000) 254 innd 0.000039 GIO fd 7 read 1152 bytes 254 innd 0.000470 RET read 1152/0x480 254 innd 0.000075 CALL read(0x7,0x7b531a,0x2000) 254 innd 0.000088 GIO fd 7 read 2880 bytes 254 innd 0.000116 RET read 2880/0xb40 254 innd 0.000072 CALL read(0x7,0x7b5e5a,0x2000) 254 innd 0.000199 GIO fd 7 read 7200 bytes My writes! The INN I use uses writev() to write articles, so it's easy to find it. In my case, they are pretty good: 254 innd 0.016623 RET writev 196212/0x2fe74 254 innd 0.000079 CALL writev(0x14,0xefbfd078,0x6) 254 innd 0.000053 RET writev 1065/0x429 254 innd 0.000124 CALL writev(0x14,0xefbfd078,0x6) 254 innd 0.000229 RET writev 2286/0x8ee 254 innd 0.000124 CALL writev(0x14,0xefbfd078,0x6) 254 innd 0.000074 RET writev 2647/0xa57 254 innd 0.000078 CALL writev(0x14,0xefbfd078,0x6) 254 innd 0.000065 RET writev 1292/0x50c 254 innd 0.000086 CALL writev(0x14,0xefbfd078,0x6) 254 innd 0.000321 RET writev 3411/0xd53 254 innd 0.000061 CALL writev(0x14,0xefbfd078,0x6) 254 innd 0.000071 RET writev 1346/0x542 254 innd 0.000079 CALL writev(0x14,0xefbfd078,0x6) 254 innd 0.000051 RET writev 759/0x2f7 254 innd 0.000095 CALL writev(0x14,0xefbfd078,0x6) 254 innd 0.051205 RET writev 565400/0x8a098 254 innd 0.000092 CALL writev(0x14,0xefbfd078,0x6) 254 innd 0.000061 RET writev 1166/0x48e 254 innd 0.000073 CALL writev(0x14,0xefbfd078,0x6) And so on. So, this analysis of my news system has indicated that my feeder has no problem keeping the pipe full (running diablo), but my INN news box has definite problems open()ing those article files, but once open it's reasonably fast. And, by looking carefully at the read()'s I've determined that my INN news box has no problem with the history file lookups. There, that's the end of my example analysis of a news system using ktrace and netstat. -Matt -- Matthew Dillon Engineering, BEST Internet Communications, Inc. , include original article w/ any response. do not under any circumstances send email to joeblow@bigspender.idiom.com and, for gods sake, don't email bucktram@popserver.idiom.com