From: Denis V. <vd...@il...> - 2005-10-23 10:29:09
|
On Saturday 22 October 2005 20:07, Carlos Martin wrote: > Here you go. Logs with your changes. I would have sent it earlier, but > "my Internet broke". Thanks! Looks like your logging system (klogd+syslogd or whatever) is losing large pieces of kernel log. But anyway: # grep 'tx:' usb-autorate2.log | grep -v 'wake ' | grep -v 'stat: mac_cnt_rcvd:' | $PAGER Oct 22 15:21:07 localhost kernel: tx: falling back to ratemask 0003 Oct 22 15:21:07 localhost kernel: tx: [IGN] client=d0fe04b4/00:80:5A:29:08:4B used=0004 cur=0003 cfg=0027 __=0/3 ^^=0/10 Oct 22 15:21:07 localhost kernel: tx: [IGN] client=d0fe04b4/00:80:5A:29:08:4B used=0004 cur=0003 cfg=0027 __=0/3 ^^=0/10 Oct 22 15:21:07 localhost kernel: tx: [IGN] client=d0fe04b4/00:80:5A:29:08:4B used=0004 cur=0003 cfg=0027 __=0/3 ^^=0/10 Oct 22 15:21:07 localhost kernel: tx: [IGN] client=d0fe04b4/00:80:5A:29:08:4B used=0004 cur=0003 cfg=0027 __=0/3 ^^=0/10 Oct 22 15:21:07 localhost kernel: tx: [IGN] client=d0fe04b4/00:80:5A:29:08:4B used=0004 cur=0003 cfg=0027 __=0/3 ^^=0/10 Oct 22 15:21:07 localhost kernel: tx: client=d0fe04b4/00:80:5A:29:08:4B used=0004 cur=0003 cfg=0027 __=0/3 ^^=1/10 ^^^^^^^^^ With ratemask cur=3 (000011) PCI driver uses 2Mbit rate. USB apparently used 5.5Mbit! You must be right about USB doing it's own rate management. Oct 22 15:21:07 localhost kernel: tx: client=d0fe04b4/00:80:5A:29:08:4B used=0004 cur=0003 cfg=0027 __=0/3 ^^=2/10 Here we lose a large piece of log (stepup counter "jumps" from 2/10 to 8/10)... Oct 22 15:21:07 localhost kernel: tx: client=d0fe04b4/00:80:5A:29:08:4B used=0002 cur=0003 cfg=0027 __=0/3 ^^=8/10 Oct 22 15:21:07 localhost kernel: tx: client=d0fe04b4/00:80:5A:29:08:4B used=0002 cur=0003 cfg=0027 __=0/3 ^^=9/10 Oct 22 15:21:07 localhost kernel: tx: client=d0fe04b4/00:80:5A:29:08:4B used=0002 cur=0003 cfg=0027 __=0/3 ^^=10/10 Oct 22 15:21:07 localhost kernel: tx: stepping up to ratemask 0007 Basically this means that this piece of code seems to be not needed: if (priv->rate_auto && stat->hostdata < VEC_SIZE(priv->sta_list)) { client_t *clt = &priv->sta_list[stat->hostdata]; acx_l_handle_txrate_auto(priv, clt, stat->rate, 0 /*rate111*/, stat->mac_status /*error*/, ACX_URB_CNT - priv->tx_free); } Consider testing throughput with and without it (with logging off of course). Loss of logging produces a number of puzzling fragments: Oct 22 15:21:07 localhost kernel: tx: falling back to ratemask 0003 Oct 22 15:21:07 localhost kernel: tx: [IGN] client=d0fe04b4/00:80:5A:29:08:4B used=0004 cur=0003 cfg=0027 __=0/3 ^^=0/10 Oct 22 15:21:07 localhost kernel: tx: [IGN] client=d0fe04b4/00:80:5A:29:08:4B used=0004 cur=0003 cfg=0027 __=0/3 ^^=0/10 Oct 22 15:21:07 localhost kernel: tx: [IGN] client=d0fe04b4/00:80:5A:29:08:4B used=0004 cur=0003 cfg=0027 __=0/3 ^^=0/10 Oct 22 15:21:07 localhost kernel: tx: [IGN] client=d0fe04b4/00:80:5A:29:08:4B used=0004 cur=0003 cfg=0027 __=0/3 ^^=0/10 Oct 22 15:21:07 localhost kernel: tx: [IGN] client=d0fe04b4/00:80:5A:29:08:RN RX (2) status=0 size=430 Oct 22 15:21:07 localhost kernel: tx: client=d0fe04b4/00:80:5A:29:08:4B used=0004 cur=0003 cfg=0027 __=0/3 ^^=1/10 Oct 22 15:21:07 localhost kernel: tx: client=d0fe04b4/00:80:5A:29:08:4B used=0004 cur=0003 cfg=0027 __=0/3 ^^=2/10 Oct 22 15:21:07 localhost kernel: tx: client=d0fe04b4/00:80:5A:29:08:4B used=0004 cur=0003 cfg=0027 __=0/3 ^^=3/10 [LOST] Oct 22 15:21:07 localhost kernel: tx: client=d0fe04b4/00:80:5A:29:08:4B used=0002 cur=0003 cfg=0027 __=0/3 ^^=7/10 Oct 22 15:21:07 localhost kernel: tx: client=d0fe04b4/00:80:5A:29:08:4B used=0002 cur=0003 cfg=0027 __=0/3 ^^=8/10 Oct 22 15:21:07 localhost kernel: tx: client=d0fe04b4/00:80:5A:29:08:4B used=0002 cur=0003 cfg=0027 __=0/3 ^^=9/10 [LOST] Oct 22 15:21:07 localhost kernel: tx: [IGN] client=d0fe04b4/00:80:5A:29:08:4B used=0002 cur=0007 cfg=0027 __=0/3 ^^=0/10 Oct 22 15:21:07 localhost kernel: tx: [IGN] client=d0fe04b4/00:80:5A:29:08:4B used=0002 cur=0007 cfg=0027 __=0/3 ^^=0/10 Oct 22 15:21:07 localhost kernel: tx: client=d0fe04b4/00:80:5A:29:08:4B used=0002 cur=0007 cfg=0027 __=0/3 ^^=0/10 Oct 22 15:21:07 localhost kernel: tx: client=d0fe04b4/00:80:5A:29:08:4B used=0002 cur=0007 cfg=0027 __=1/3 ^^=0/10 Oct 22 15:21:07 localhost kernel: tx: client=d0fe04b4/00:80:5A:29:08:4B used=0002 cur=0007 cfg=0027 __=2/3 ^^=0/10 Oct 22 15:21:07 localhost kernel: tx: client=d0fe04b4/00:80:5A:29:08:4B used=0002 cur=0007 cfg=0027 __=3/3 ^^=0/10 Oct 22 15:21:07 localhost kernel: tx: falling back to ratemask 0003 stepup event was lost in between of two fallback ones! :( I am using a socklog tool from http://smarden.org/socklog/ Can be run standalone but I use it in combination with daemontools from http://cr.yp.to/daemontools.html Attached is the tarball of directory with necessary scripts. If you will fail to convince your klogd to work properly, try socklog instead. -- vda |