[Prism54-devel] 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