Date: Mon, 03 Dec 2012 16:45:18 +0100 From: Andreas Longwitz <longwitz@incore.de> To: Hans Petter Selasky <hselasky@c2i.net> Cc: freebsd-isdn@freebsd.org Subject: Re: ISDN4BSD (HPS version) is going into ports Message-ID: <50BCC90E.7080104@incore.de> In-Reply-To: <201212031226.14851.hselasky@c2i.net> References: <509E87EF.9070607@incore.de> <201212021043.53151.hselasky@c2i.net> <50BBEA16.3060004@incore.de> <201212031226.14851.hselasky@c2i.net>
next in thread | previous in thread | raw e-mail | index | archive | help
Hans Petter Selasky wrote:
> Could you show what code you added?
Yes of course: In i4b_avm_pci.h I have applied your last patch and then
added some IHFC_ERR messages triggered by debug.bootverbose:
--- i4b_avm_pci.h 2012-12-03 15:27:20.000000000 +0100
+++ i4b_avm_pci.h.debug 2012-12-03 00:29:03.000000000 +0100
@@ -111,6 +111,10 @@
{
IPAC_BUS_VAR(sc);
+ if (bootverbose) {
+ IHFC_ERR("reg=0x%04x, len=%d\n", reg, len);
+ }
+
if(reg & 0x80)
{
enum { BUFFER_SIZE = 64 };
@@ -126,6 +130,12 @@
for (x = 0; x != len; x++)
ptr[x] = (u_int8_t)buffer[x];
+ if (bootverbose && len == 4) {
+ IHFC_ERR("got 0x%02x%02x%02x%02x\n",
ptr[0],ptr[1],ptr[2],ptr[3]);
+ }
+ if (bootverbose && len == 5) {
+ IHFC_ERR("got 0x%02x%02x%02x%02x%02x\n",
ptr[0],ptr[1],ptr[2],ptr[3],ptr[4]);
+ }
}
else
{
@@ -139,6 +149,9 @@
{
if(FIFO_NO(f) == d1r)
{
+ if (bootverbose) {
+ IHFC_ERR("len=%d\n", len);
+ }
avm_pci_chip_read(sc,(f->fm.h.Zdata),ptr,len);
}
else
@@ -209,6 +222,9 @@
/* read CIR0 */
avm_pci_chip_read(sc, REG_isacsx_cir0, &temp, 1);
+ if (bootverbose) {
+ IHFC_ERR("cir0=0x%02x\n", temp);
+ }
*ptr = (temp >> 4) & 0xf;
@@ -357,23 +373,33 @@
/* read ISTA (ISAC) */
avm_pci_chip_read(sc, REG_isacsx_ista, &ista, 1);
- IHFC_MSG("ista=0x%02x\n", ista);
+ if (bootverbose) {
+ IHFC_ERR("ista=0x%02x\n", ista);
+ }
if(ista & 0x01 /* ICD */)
{
/* read ISTAD (ISAC) */
avm_pci_chip_read(sc, REG_isacsx_istad, &ista_d, 1);
- IHFC_MSG("ista_d=0x%02x\n", ista_d);
+ if (bootverbose) {
+ IHFC_ERR("ista_d=0x%02x\n", ista_d);
+ }
if(ista_d & 0x80 /* RME */)
{
/* read RBCL (ISAC) */
avm_pci_chip_read(sc, REG_isacsx_rbcld, &temp, 1);
+ if (bootverbose) {
+ IHFC_ERR("rbcld=0x%02x\n", temp);
+ }
sc->sc_fifo[d1r].Z_chip = temp;
/* read RSTA (ISAC) */
avm_pci_chip_read(sc, REG_isacsx_rstad, &temp, 1);
+ if (bootverbose) {
+ IHFC_ERR("rstad=0x%02x\n", temp);
+ }
sc->sc_fifo[d1r].F_chip = temp;
}
> I think we are onto something. The rstad=0xae too, so apparently this byte is
> added to the FIFO.
>
> Could you try to send a dummy frame that is greater than 64 bytes? I want to
> see if len = 0, is used at all.
I am sorry, but I don't know how to generate a frame in D-channel with
more than 64 bytes. If I activate the extra debug messages with sysctl
debug.bootverbose=1 and try a ping to the other side of the isp0
interface, the system crashes after some debugging output:
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00ae, len=1
i4b-L1 ihfc1: avm_pci_fsm_read: cir0=0xc0
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00e0, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: ista=0x01
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00a0, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: ista_d=0x90
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00a6, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: rbcld=0x09
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00a8, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: rstad=0xab
i4b-L1 ihfc1: avm_pci_fifo_read: len=9
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x0080, len=9
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00e0, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: ista=0x01
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00a0, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: ista_d=0x90
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00a6, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: rbcld=0x04
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00a8, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: rstad=0xac
i4b-L1 ihfc1: avm_pci_fifo_read: len=4
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x0080, len=4
i4b-L1 ihfc1: avm_pci_chip_read: got 0x009573ac
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00e0, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: ista=0x01
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00a0, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: ista_d=0x90
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00a6, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: rbcld=0x05
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00a8, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: rstad=0xae
i4b-L1 ihfc1: avm_pci_fifo_read: len=5
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x0080, len=5
i4b-L1 ihfc1: avm_pci_chip_read: got 0x00950102ac
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00e0, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: ista=0x01
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00a0, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: ista_d=0x90
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00a6, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: rbcld=0x0d
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00a8, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: rstad=0xac
i4b-L1 ihfc1: avm_pci_fifo_read: len=13
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x0080, len=13
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00e0, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: ista=0x01
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00a0, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: ista_d=0x80
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00a6, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: rbcld=0x05
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00a8, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: rstad=0xac
i4b-L1 ihfc1: avm_pci_fifo_read: len=5
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x0080, len=5
i4b-L1 ihfc1: avm_pci_chip_read: got 0x00950105ac
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00e0, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: ista=0x01
i4b-L1 ihfc1: avm_pci_chip_read: reg=0x00a0, len=1
i4b-L1 ihfc1: avm_pci_chip_status_read: ista_d=0x14
panic: vm_fault: fault on nofault entry, addr: e5158000
cpuid = 0
KDB: stack backtrace:
db_trace_self_wrapper(c0984233,fb,e514b7a4,c08f2ed3,fb,...) at
db_trace_self_wrapper+0x26
kdb_backtrace(c09a2e37,0,c09992fe,e514b80c,0,...) at kdb_backtrace+0x2a
panic(c09992fe,e5158000,1,e514b948,e514b938,...) at panic+0x15c
vm_fault(c17dc000,e5158000,1,0,4175e6,...) at vm_fault+0x1a4
trap_pfault(c4d332e0,4,c097e974,369,c4d31560,...) at trap_pfault+0x284
trap(e514ba60) at trap+0x3f3
calltrap() at calltrap+0x6
--- trap 0xc, eip = 0xc0bd2338, esp = 0xe514baa0, ebp = 0xe514bbc0 ---
avm_pci_chip_write(c50cd000,80,c6334800,0,c50cd000,...) at
avm_pci_chip_write+0xa8
filter_tx(c50cddd8,20,e514bc2c,c0bcf372,c50cd000,...) at filter_tx+0x57
tx_hdlc(c50cd000,c50cddd8,c0bfeb4e,c50cd000,c0bfa0ca,...) at tx_hdlc+0x5e
i4b_ipac_tx_program(c50cd000,c50cddd8,c4de3b80,e514bc4c,1,...) at
i4b_ipac_tx_program+0x62
__ihfc_chip_interrupt(c50cd000,0,c0bfd197,39b,c4f212c0,...) at
__ihfc_chip_interrupt+0x171
ihfc_chip_interrupt(c50cd000,c4de38a0,0,109,73e3dd24,...) at
ihfc_chip_interrupt+0x38
intr_event_execute_handlers(c4d31560,c4d76b80,c097e974,52c,c4d76bf0,...)
at intr_event_execute_handlers+0x13b
ithread_loop(c525b040,e514bd28,0,c4d31560,0,...) at ithread_loop+0x6b
fork_exit(c06b0290,c525b040,e514bd28) at fork_exit+0x97
fork_trampoline() at fork_trampoline+0x8
--- trap 0, eip = 0, esp = 0xe514bd60, ebp = 0 ---
KDB: enter: panic
[thread pid 12 tid 100028 ]
Stopped at kdb_enter+0x3a: movl $0,kdb_why
db:0:kdb.enter.panic> watchdog
No argument provided, disabling watchdog
db:0:kdb.enter.panic> run ddbinfo
db:1:ddbinfo> capture on
db:1:on> run lockinfo
db:2:lockinfo> show lock Giant
class: sleep mutex
name: Giant
flags: {DEF, RECURSE}
state: {UNOWNED}
db:2:Giant> show lockedvnods
Locked vnodes
0xc5d0cb84: tag ufs, type VREG
usecount 1, writecount 1, refcount 24 mountedhere 0
flags ()
v_object 0xc5f3e908 ref 0 pages 88
lock type ufs: EXCL by thread 0xc5be02e0 (pid 858)
ino 94218, on dev amrd0p4
db:2:lockedvnods> show lockchain
thread 100028 (pid 12, irq23: ihfc1) running on CPU 0
db:2:lockchain> show sleepchain
thread 100028 (pid 12, irq23: ihfc1) running on CPU 0
db:1:sleepchain> show pcpu
cpuid = 0
dynamic pcpu = 0x61ed80
curthread = 0xc4de38a0: pid 12 "irq23: ihfc1"
curpcb = 0xe514bd80
fpcurthread = none
idlethread = 0xc4d335c0: tid 100004 "idle: cpu0"
APIC ID = 3
currentldt = 0x50
db:1:pcpu> show allpcpu
Current CPU: 0
cpuid = 0
dynamic pcpu = 0x61ed80
curthread = 0xc4de38a0: pid 12 "irq23: ihfc1"
curpcb = 0xe514bd80
fpcurthread = none
idlethread = 0xc4d335c0: tid 100004 "idle: cpu0"
APIC ID = 3
currentldt = 0x50
cpuid = 1
dynamic pcpu = 0x3fbcd80
curthread = 0xc5be1b80: pid 1104 "isdndecode"
curpcb = 0xe7463d80
fpcurthread = none
idlethread = 0xc4d338a0: tid 100003 "idle: cpu1"
APIC ID = 0
currentldt = 0x50
db:1:allpcpu> bt
Tracing pid 12 tid 100028 td 0xc4de38a0
kdb_enter(c098203e,c098203e,c09992fe,e514b80c,0,...) at kdb_enter+0x3a
panic(c09992fe,e5158000,1,e514b948,e514b938,...) at panic+0x179
vm_fault(c17dc000,e5158000,1,0,4175e6,...) at vm_fault+0x1a4
trap_pfault(c4d332e0,4,c097e974,369,c4d31560,...) at trap_pfault+0x284
trap(e514ba60) at trap+0x3f3
calltrap() at calltrap+0x6
--- trap 0xc, eip = 0xc0bd2338, esp = 0xe514baa0, ebp = 0xe514bbc0 ---
avm_pci_chip_write(c50cd000,80,c6334800,0,c50cd000,...) at
avm_pci_chip_write+0xa8
filter_tx(c50cddd8,20,e514bc2c,c0bcf372,c50cd000,...) at filter_tx+0x57
tx_hdlc(c50cd000,c50cddd8,c0bfeb4e,c50cd000,c0bfa0ca,...) at tx_hdlc+0x5e
i4b_ipac_tx_program(c50cd000,c50cddd8,c4de3b80,e514bc4c,1,...) at
i4b_ipac_tx_program+0x62
__ihfc_chip_interrupt(c50cd000,0,c0bfd197,39b,c4f212c0,...) at
__ihfc_chip_interrupt+0x171
ihfc_chip_interrupt(c50cd000,c4de38a0,0,109,73e3dd24,...) at
ihfc_chip_interrupt+0x38
intr_event_execute_handlers(c4d31560,c4d76b80,c097e974,52c,c4d76bf0,...)
at intr_event_execute_handlers+0x13b
ithread_loop(c525b040,e514bd28,0,c4d31560,0,...) at ithread_loop+0x6b
fork_exit(c06b0290,c525b040,e514bd28) at fork_exit+0x97
fork_trampoline() at fork_trampoline+0x8
--- trap 0, eip = 0, esp = 0xe514bd60, ebp = 0 ---
db:1:bt> ps
pid ppid pgrp uid state wmesg wchan cmd
11060 10660 11060 0 S+ select 0xc5f621a4 ping
11010 1151 23 0 S nanslp 0xc0a37984 sleep
10660 10659 10660 0 S+ wait 0xc5b47810 sh
......
100028 Run CPU 0 [irq23: ihfc1]
......
db:1:ps> show thread
Thread 100028 at 0xc4de38a0:
proc (pid 12): 0xc4d31560
name: irq23: ihfc1
stack: 0xe514a000-0xe514bfff
flags: 0x4 pflags: 0x200500
state: RUNNING (CPU 0)
priority: 16
container lock: sched lock 0 (0xc0a3b980)
db:1:thread> alltrace
Tracing command ping pid 11060 tid 100157 td 0xc64388a0
sched_switch(c64388a0,0,104,3ceeb53c,316c,...) at sched_switch+0x293
mi_switch(104,0,c5f62180,c6490000,e7553a2c,...) at mi_switch+0x12f
sleepq_switch(c64388a0,0,c0985116,1a5,c64388a0,...) at sleepq_switch+0xcc
sleepq_catch_signals(c5f62180,0,c64388a0,e7553a78,c06910f7,...) at
sleepq_catch_signals+0x52
sleepq_timedwait_sig(c5f621a4,0,c0986a0f,101,0,...) at
sleepq_timedwait_sig+0x1c
_cv_timedwait_sig(c5f621a4,c5f62190,3e9,c8833670,58,...) at
_cv_timedwait_sig+0x1b7
seltdwait(e7553c18,e7553c20,c5ced000,c64388a0,e7553ac8,...) at
seltdwait+0xc1
kern_select(c64388a0,4,bfbee854,0,0,e7553c60,20,0,f4231) at
kern_select+0x571
select(c64388a0,e7553cec,c,c,c,...) at select+0x66
syscall(e7553d28) at syscall+0x342
Xint0x80_syscall() at Xint0x80_syscall+0x21
--- syscall (93, FreeBSD ELF32, select), eip = 0x881a5053, esp =
0xbfbee74c, ebp = 0xbfbfec18 ---
....
db:1:alltrace> capture off
db:0:kdb.enter.panic> call doadump
Physical memory: 1011 MB
Dumping 168 MB:
I get this debug information via a ddb configuration in ddb.conf.
Unfortunately the write of the dump hangs, but that is another story.
If it is relevant, I can give more stack traces or any other debug
information.
Andreas Longwitz
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?50BCC90E.7080104>