[Prism54-users] working but Badness in local_bh_enable...
Basile STARYNKEVITCH
basile@starynkevitch.net
Tue, 4 Nov 2003 19:42:53 +0100
Sorry for posting to both devel & users lists - to developers, because
I suppose they can understand what is happenning; and to users for
information.
My SMC2835W Wifi pccard is working, using the latest driver from CVS:
isl_38xx.c:
$Header: /var/lib/cvs/prism54-ng/ksrc/isl_38xx.c,v 1.11 2003/11/04 06:40:10 hvr Exp $
isl_38xx.h:
$Header: /var/lib/cvs/prism54-ng/ksrc/isl_38xx.h,v 1.11 2003/11/04 06:40:10 hvr Exp $
isl_gen.c:
$Header: /var/lib/cvs/prism54-ng/ksrc/isl_gen.c,v 1.4 2003/10/31 08:08:12 hvr Exp $
isl_gen.h:
$Header: /var/lib/cvs/prism54-ng/ksrc/isl_gen.h,v 1.6 2003/11/03 08:25:13 hvr Exp $
isl_ioctl.c:
$Header: /var/lib/cvs/prism54-ng/ksrc/isl_ioctl.c,v 1.18 2003/11/04 06:40:10 hvr Exp $
isl_ioctl.h:
$Header: /var/lib/cvs/prism54-ng/ksrc/isl_ioctl.h,v 1.5 2003/11/03 18:41:22 hvr Exp $
isl_mgt.c:
$Header: /var/lib/cvs/prism54-ng/ksrc/isl_mgt.c,v 1.6 2003/11/01 09:58:24 hvr Exp $
isl_mgt.h:
$Header: /var/lib/cvs/prism54-ng/ksrc/isl_mgt.h,v 1.3 2003/10/31 07:59:27 hvr Exp $
isl_wds.c:
$Header: /var/lib/cvs/prism54-ng/ksrc/isl_wds.c,v 1.4 2003/11/01 09:58:24 hvr Exp $
isl_wds.h:
$Header: /var/lib/cvs/prism54-ng/ksrc/isl_wds.h,v 1.2 2003/10/31 07:59:27 hvr Exp $
islpci_dev.c:
$Header: /var/lib/cvs/prism54-ng/ksrc/islpci_dev.c,v 1.18 2003/11/04 06:40:10 hvr Exp $
islpci_dev.h:
$Header: /var/lib/cvs/prism54-ng/ksrc/islpci_dev.h,v 1.14 2003/11/04 06:35:09 hvr Exp $
islpci_eth.c:
$Header: /var/lib/cvs/prism54-ng/ksrc/islpci_eth.c,v 1.8 2003/11/04 06:40:10 hvr Exp $
islpci_eth.h:
$Header: /var/lib/cvs/prism54-ng/ksrc/islpci_eth.h,v 1.4 2003/11/04 06:35:09 hvr Exp $
islpci_hotplug.c:
$Header: /var/lib/cvs/prism54-ng/ksrc/islpci_hotplug.c,v 1.14 2003/11/04 06:35:09 hvr Exp $
islpci_mgt.c:
$Header: /var/lib/cvs/prism54-ng/ksrc/islpci_mgt.c,v 1.16 2003/11/04 06:40:10 hvr Exp $
islpci_mgt.h:
$Header: /var/lib/cvs/prism54-ng/ksrc/islpci_mgt.h,v 1.9 2003/11/04 06:40:10 hvr Exp $
However, the ping times are quite irregular, for instance pinging my
nearest PC on the local LAN (directly connected to my WRT54G linksys
wifi router) gives (some previous person reported similar behavior).
PING hector.lesours (192.168.0.5): 56 data bytes
64 bytes from 192.168.0.5: icmp_seq=0 ttl=63 time=131.6 ms
64 bytes from 192.168.0.5: icmp_seq=1 ttl=63 time=2.4 ms
64 bytes from 192.168.0.5: icmp_seq=2 ttl=63 time=2.3 ms
64 bytes from 192.168.0.5: icmp_seq=3 ttl=63 time=121.1 ms
64 bytes from 192.168.0.5: icmp_seq=4 ttl=63 time=2.4 ms
64 bytes from 192.168.0.5: icmp_seq=5 ttl=63 time=121.6 ms
64 bytes from 192.168.0.5: icmp_seq=6 ttl=63 time=2.4 ms
64 bytes from 192.168.0.5: icmp_seq=7 ttl=63 time=2.4 ms
64 bytes from 192.168.0.5: icmp_seq=8 ttl=63 time=121.4 ms
64 bytes from 192.168.0.5: icmp_seq=9 ttl=63 time=2.3 ms
64 bytes from 192.168.0.5: icmp_seq=10 ttl=63 time=124.0 ms
64 bytes from 192.168.0.5: icmp_seq=11 ttl=63 time=2.4 ms
I compiled with inside isl_gen.h:
#define VERBOSE 0x3
It seems to me that when the ping last more than 100 milliseconds, I
have the following in my kernel log:
Nov 4 19:10:56 modest kernel: Badness in local_bh_enable at kernel/softirq.c:121
Nov 4 19:10:56 modest kernel: Call Trace:
Nov 4 19:10:56 modest kernel: [<c012cf4c>] local_bh_enable+0x6c/0x70
Nov 4 19:10:56 modest kernel: [<d69f47dd>] ip_ct_find_proto+0x2d/0x40 [ip_conntrack]
Nov 4 19:10:56 modest kernel: [<d69f4b7a>] destroy_conntrack+0x1a/0x110 [ip_conntrack]
Nov 4 19:10:56 modest kernel: [<c0324cbe>] __kfree_skb+0x8e/0x100
Nov 4 19:10:56 modest kernel: [<c025ab54>] __delay+0x14/0x20
Nov 4 19:10:56 modest kernel: [<d6b221de>] islpci_eth_cleanup_transmit+0x5e/0xb0 [prism54]
Nov 4 19:10:56 modest kernel: [<c0324cb0>] __kfree_skb+0x80/0x100
Nov 4 19:10:56 modest kernel: [<d6b225a0>] islpci_eth_transmit+0x370/0x7f0 [prism54]
Nov 4 19:10:56 modest kernel: [<c018fba8>] d_callback+0x28/0x40
Nov 4 19:10:56 modest kernel: [<d6a0752f>] do_bindings+0x6f/0x230 [iptable_nat]
Nov 4 19:10:56 modest kernel: [<d69ee270>] ipt_do_table+0x240/0x310 [ip_tables]
Nov 4 19:10:56 modest kernel: [<c03379c9>] qdisc_restart+0x109/0x4e0
Nov 4 19:10:56 modest kernel: [<c03296bf>] dev_queue_xmit+0x4ef/0x670
Nov 4 19:10:56 modest kernel: [<c0347270>] ip_finish_output2+0x0/0x1d0
Nov 4 19:10:56 modest kernel: [<c0347328>] ip_finish_output2+0xb8/0x1d0
Nov 4 19:10:56 modest kernel: [<c03359b8>] nf_hook_slow+0xc8/0x120
Nov 4 19:10:56 modest kernel: [<c0347270>] ip_finish_output2+0x0/0x1d0
Nov 4 19:10:56 modest kernel: [<c0344f16>] ip_finish_output+0x206/0x210
Nov 4 19:10:56 modest kernel: [<c0347270>] ip_finish_output2+0x0/0x1d0
Nov 4 19:10:56 modest kernel: [<c0347255>] dst_output+0x15/0x30
Nov 4 19:10:56 modest kernel: [<c03359b8>] nf_hook_slow+0xc8/0x120
Nov 4 19:10:56 modest kernel: [<c0347240>] dst_output+0x0/0x30
Nov 4 19:10:56 modest kernel: [<c0345588>] ip_queue_xmit+0x458/0x570
Nov 4 19:10:56 modest kernel: [<c0347240>] dst_output+0x0/0x30
Nov 4 19:10:56 modest kernel: [<c01519de>] __alloc_pages+0x9e/0x320
Nov 4 19:10:56 modest kernel: [<c01206de>] recalc_task_prio+0x8e/0x1b0
Nov 4 19:10:56 modest kernel: [<c0131d66>] update_process_times+0x46/0x50
Nov 4 19:10:56 modest kernel: [<c0121bfa>] default_wake_function+0x2a/0x30
Nov 4 19:10:56 modest kernel: [<c0359194>] tcp_cwnd_restart+0x24/0xb0
Nov 4 19:10:56 modest kernel: [<c03595ae>] tcp_transmit_skb+0x38e/0x590
Nov 4 19:10:56 modest kernel: [<c035a48b>] tcp_write_xmit+0x16b/0x2e0
Nov 4 19:10:56 modest kernel: [<c03249e8>] alloc_skb+0x48/0xf0
Nov 4 19:10:56 modest kernel: [<c034d9cf>] tcp_sendmsg+0x75f/0x16b0
Nov 4 19:10:56 modest kernel: [<c0373d1b>] inet_sendmsg+0x4b/0x60
Nov 4 19:10:56 modest kernel: [<c0320b58>] sock_aio_write+0xe8/0x100
Nov 4 19:10:56 modest kernel: [<c01737a9>] do_sync_write+0x89/0xc0
Nov 4 19:10:56 modest kernel: [<c0248c5f>] inode_has_perm+0x5f/0x90
Nov 4 19:10:56 modest kernel: [<c01738df>] vfs_write+0xff/0x140
Nov 4 19:10:56 modest kernel: [<c01739bf>] sys_write+0x3f/0x60
Nov 4 19:10:56 modest kernel: [<c010bed3>] syscall_call+0x7/0xb
Nov 4 19:10:56 modest kernel:
The wifi connection is still working (using WEP). (Here is the output
of iwconfig - but I changed most of the digits of the encryption key
output).
iwconfig
lo no wireless extensions.
eth0 no wireless extensions.
sit0 no wireless extensions.
eth1 PRISM Duette ESSID:"ours"
Mode:Managed Frequency:2.462GHz Access Point: 00:06:25:E8:5E:49
RTS thr=2347 B Fragment thr=2346 B
Encryption key:C000-B000-6000-9FFF-A777-3333-44 Security mode:restricted
Link Quality:100/0 Signal level:-66 dBm Noise level:-166 dBm
Rx invalid nwid:0 Rx invalid crypt:0 Rx invalid frag:0
Tx excessive retries:0 Invalid misc:0 Missed beacon:0
I'm quite happy, since the radio signal does go thru a concrete floor
(I'm typing downstairs, and the Wifi AP is a WRT54G Linksys router
upstairs, in between there is a floor in armed concrete (in french, my
native tongue, "beton armé").
I'm using an ASUS Laptop (with AMD1600). If this can help developers,
here is the output of my lspci
lspci -v
00:00.0 Host bridge: Silicon Integrated Systems [SiS] 730 Host (rev 02)
Flags: bus master, medium devsel, latency 32
Memory at ec000000 (32-bit, non-prefetchable) [size=64M]
Capabilities: [c0] AGP version 2.0
00:00.1 IDE interface: Silicon Integrated Systems [SiS] 5513 [IDE] (rev d0) (pro g-if 80 [Master])
Subsystem: Asustek Computer, Inc.: Unknown device 1598
Flags: bus master, fast devsel, latency 16
I/O ports at d800 [size=16]
00:01.0 ISA bridge: Silicon Integrated Systems [SiS] 85C503/5513
Flags: bus master, medium devsel, latency 0
00:01.1 Ethernet controller: Silicon Integrated Systems [SiS] SiS900 10/100 Ethe rnet (rev 82)
Subsystem: Asustek Computer, Inc.: Unknown device 1455
Flags: bus master, medium devsel, latency 32, IRQ 9
I/O ports at d400 [size=256]
Memory at eb800000 (32-bit, non-prefetchable) [size=4K]
Expansion ROM at <unassigned> [disabled] [size=128K]
Capabilities: [40] Power Management version 2
00:01.2 USB Controller: Silicon Integrated Systems [SiS] USB 1.0 Controller (rev 07) (prog-if 10 [OHCI])
Subsystem: Silicon Integrated Systems [SiS] USB 1.0 Controller
Flags: bus master, medium devsel, latency 32, IRQ 9
Memory at eb000000 (32-bit, non-prefetchable) [size=4K]
00:01.3 USB Controller: Silicon Integrated Systems [SiS] USB 1.0 Controller (rev 07) (prog-if 10 [OHCI])
Subsystem: Silicon Integrated Systems [SiS] Onboard USB Controller
Flags: bus master, medium devsel, latency 32, IRQ 9
Memory at ea800000 (32-bit, non-prefetchable) [size=4K]
00:01.4 Multimedia audio controller: Silicon Integrated Systems [SiS] SiS PCI Au dio Accelerator (rev 02)
Subsystem: Asustek Computer, Inc.: Unknown device 1453
Flags: bus master, medium devsel, latency 32, IRQ 5
I/O ports at d000 [size=256]
Memory at ea000000 (32-bit, non-prefetchable) [size=4K]
Capabilities: [dc] Power Management version 2
00:01.6 Modem: Silicon Integrated Systems [SiS] Intel 537 [56k Winmodem] (rev a0 ) (prog-if 00 [Generic])
Subsystem: Asustek Computer, Inc.: Unknown device 1457
Flags: bus master, medium devsel, latency 32, IRQ 9
I/O ports at b800 [size=256]
I/O ports at b400 [size=128]
Capabilities: [48] Power Management version 2
00:02.0 PCI bridge: Silicon Integrated Systems [SiS] SiS 530 Virtual PCI-to-PCI bridge (AGP) (prog-if 00 [Normal decode])
Flags: bus master, fast devsel, latency 0
Bus: primary=00, secondary=01, subordinate=01, sec-latency=0
I/O behind bridge: 0000a000-0000afff
Memory behind bridge: e9800000-e9ffffff
Prefetchable memory behind bridge: f0000000-feafffff
00:02.0 PCI bridge: Silicon Integrated Systems [SiS] SiS 530 Virtual PCI-to-PCI bridge (AGP) (prog-if 00 [Normal decode])
Flags: bus master, fast devsel, latency 0
Bus: primary=00, secondary=01, subordinate=01, sec-latency=0
I/O behind bridge: 0000a000-0000afff
Memory behind bridge: e9800000-e9ffffff
Prefetchable memory behind bridge: f0000000-feafffff
00:0a.0 CardBus bridge: Ricoh Co Ltd RL5c476 II (rev 80)
Subsystem: Asustek Computer, Inc.: Unknown device 1594
Flags: bus master, medium devsel, latency 168, IRQ 11
Memory at 16000000 (32-bit, non-prefetchable) [size=4K]
Bus: primary=00, secondary=02, subordinate=05, sec-latency=176
Memory window 0: 16400000-167ff000 (prefetchable)
Memory window 1: 16800000-16bff000
I/O window 0: 00004000-000040ff
I/O window 1: 00004400-000044ff
16-bit legacy interface ports at 0001
00:0a.1 CardBus bridge: Ricoh Co Ltd RL5c476 II (rev 80)
Subsystem: Asustek Computer, Inc.: Unknown device 1594
Flags: bus master, medium devsel, latency 168, IRQ 9
Memory at 16001000 (32-bit, non-prefetchable) [size=4K]
Bus: primary=00, secondary=06, subordinate=09, sec-latency=176
Memory window 0: 16c00000-16fff000 (prefetchable)
Memory window 1: 17000000-173ff000
I/O window 0: 00004800-000048ff
I/O window 1: 00004c00-00004cff
16-bit legacy interface ports at 0001
00:0e.0 FireWire (IEEE 1394): Texas Instruments TSB43AB22/A IEEE-1394a-2000 Cont roller (PHY/Link) (prog-if 10 [OHCI])
Subsystem: Asustek Computer, Inc.: Unknown device 1597
Flags: bus master, medium devsel, latency 32, IRQ 9
Memory at e9000000 (32-bit, non-prefetchable) [size=2K]
Memory at e8800000 (32-bit, non-prefetchable) [size=16K]
Capabilities: [44] Power Management version 2
01:00.0 VGA compatible controller: Silicon Integrated Systems [SiS] SiS630 GUI A ccelerator+3D (rev 31) (prog-if 00 [VGA])
Subsystem: Asustek Computer, Inc.: Unknown device 1452
Flags: 66Mhz, medium devsel
BIST result: 00
Memory at f0000000 (32-bit, prefetchable) [size=128M]
Memory at e9800000 (32-bit, non-prefetchable) [size=128K]
I/O ports at a800 [size=128]
Capabilities: [40] Power Management version 1
Capabilities: [50] AGP version 2.0
02:00.0 Network controller: Harris Semiconductor D-Links DWL-g650 A1 (rev 01)
Subsystem: Standard Microsystems Corp [SMC]: Unknown device 2835
Flags: bus master, medium devsel, latency 80, IRQ 11
Memory at 16800000 (32-bit, non-prefetchable) [size=8K]
Capabilities: [dc] Power Management version 1
I suspect that the kernel backtrace might be related to interrupt
handling;
cat /proc/interrupts
CPU0
0: 2616884 XT-PIC timer
1: 5886 XT-PIC i8042
2: 0 XT-PIC cascade
8: 4 XT-PIC rtc
9: 2942 XT-PIC acpi, yenta
11: 20029 XT-PIC yenta, eth1
12: 37326 XT-PIC i8042
14: 18057 XT-PIC ide0
15: 4 XT-PIC ide1
NMI: 0
ERR: 0
My wired LAN connection is eth0 and is off during this.
I am still using the Wifi connection with all the above symptoms. I'm
not enough a kernel expert to understand what exactly is happenning.
The kernel is a 2.6.0-test9 (on x86) compiled by me: /proc/version
gives
Linux version 2.6.0-test9 (basile@modest) (gcc version 3.3.2 (Debian))
#3 Sat Nov 1 11:18:00 CET 2003
The loaded modules are
#
lsmod
Module Size Used by
prism54 46868 0
ipv6 274432 8
ds 15620 4
yenta_socket 17664 1
pcmcia_core 70368 2 ds,yenta_socket
sis 52992 2
binfmt_misc 11400 1
ipt_LOG 6272 0
iptable_mangle 3200 0
iptable_filter 3200 0
iptable_nat 23720 0
ip_conntrack 31920 1 iptable_nat
ip_tables 17280 4 ipt_LOG,iptable_mangle,iptable_filter,iptable_nat
ehci_hcd 40452 0
usbmouse 6144 0
hid 35904 0
usb_storage 29824 0
sis900 20868 0
sg 37016 0
ide_scsi 17024 0
scsi_mod 129976 3 usb_storage,sg,ide_scsi
evdev 9984 0
ieee1394 88364 0
usbkbd 7808 0
usbcore 132444 5 ehci_hcd,usbmouse,hid,usb_storage,usbkbd
Some essential stuff (IDE driver, screen & keyboard, ext3 & reiser FS,
etc...) are built in the kernel (not loaded as modules).
I hope all the above might help.
A big thanks to the developers for such a rapid update of the prism54
driver and a big thanks to the list for helpful remarks.
I cannot help more on this (probably interrupt related) problem.
Regards.
--
Basile STARYNKEVITCH http://starynkevitch.net/Basile/
email: basile<at>starynkevitch<dot>net
aliases: basile<at>tunes<dot>org = bstarynk<at>nerim<dot>net
8, rue de la Faïencerie, 92340 Bourg La Reine, France