Lost interrupt, page allocation failure, and kernel oops

[Kaspar Fischer <fischerk@inf.ethz.ch>]

Hi list,

My machine crashed after /dev/hdb encoutered a "lost interrupt"
and, some hours later (and maybe unrelated) a "page allocation
failure" and a "Oops: kernel access of bad area" occurred.
The details are in the log file below.

What I know is that at 23:00:00 a cronjob started to copy from
the filesystem mounted on /dev/hdb2 to the filesystem mounted
on /dev/hde2, so it seems the crash (at time 23:02:31) was
caused by this cp process (?), or the "rm -fr" before it that
erased the contents of the backup drive /dev/hde2.

The machine then crashed and restarted into read-only mode
(not in the log because of the read-only, I guess) and fsck
found the /dev/hdb2 ext2-filesytem to be severally damaged
(some 10000 duplicate blocks).

Do you have any idea what this could be?

Any help is very much appreciated as I am completely lost
here.

Kaspar

-- System information:
The machine is running Linux 2.6.8 which I compiled with the
config file that comes with debian sarge with the two
exceptions that I patched the kernel with Thibaut Varene's
AEC6280 patch,

  http://marc.theaimsgroup.com/?l=linux-ide&m=113128446708744&q=p3

and that I disable firewire support.

-- /var/log/messages:
Mar 14 06:26:35 bumbum syslogd 1.4.1#17: restart.
Mar 14 06:37:57 bumbum -- MARK --
[snip: several more of these MARK's]
Mar 14 23:18:39 bumbum kernel: hdb: lost interrupt
Mar 14 23:18:39 bumbum kernel: hdb: dma_intr: status=0x58  
{ DriveReady SeekComp\
lete DataRequest }
Mar 14 23:18:39 bumbum kernel:
Mar 14 23:18:39 bumbum kernel: hdb: status timeout: status=0xd0 { Busy }
Mar 14 23:18:39 bumbum kernel:
Mar 14 23:18:39 bumbum kernel: hda: DMA disabled
Mar 14 23:18:39 bumbum kernel: hdb: DMA disabled
Mar 14 23:18:39 bumbum kernel: ide0: reset: success
Mar 14 23:37:59 bumbum -- MARK --
Mar 14 23:58:00 bumbum -- MARK --
Mar 15 00:18:01 bumbum -- MARK --
Mar 15 00:38:02 bumbum -- MARK --
Mar 15 00:58:03 bumbum -- MARK --
Mar 15 01:18:04 bumbum -- MARK --
Mar 15 01:38:06 bumbum -- MARK --
Mar 15 01:58:07 bumbum -- MARK --
Mar 15 02:18:08 bumbum -- MARK --
Mar 15 02:38:09 bumbum -- MARK --
Mar 15 02:58:10 bumbum -- MARK --
Mar 15 03:05:35 bumbum kernel: kblockd/0: page allocation failure.  
order:0, mod\
e:0x20
Mar 15 03:05:36 bumbum kernel: Call trace:
Mar 15 03:05:36 bumbum kernel:  [c000ba7c] dump_stack+0x18/0x28
Mar 15 03:05:36 bumbum kernel:  [c003f1ec] __alloc_pages+0x324/0x388
Mar 15 03:05:36 bumbum kernel:  [c003f27c] __get_free_pages+0x2c/0x5c
Mar 15 03:05:36 bumbum kernel:  [c0042f04] kmem_getpages+0x2c/0x130
Mar 15 03:05:36 bumbum kernel:  [c0043ca4] cache_grow+0x9c/0x16c
Mar 15 03:05:36 bumbum kernel:  [c0043f34] cache_alloc_refill 
+0x1c0/0x25c
Mar 15 03:05:36 bumbum kernel:  [c00444ac] __kmalloc+0xa8/0xb4
Mar 15 03:05:36 bumbum kernel:  [c0148520] alloc_skb+0x4c/0xe0
Mar 15 03:05:36 bumbum kernel:  [ce1181c8] bmac_rxdma_intr 
+0x100/0x228 [bmac]
Mar 15 03:05:36 bumbum kernel:  [c0009ad8] ppc_irq_dispatch_handler 
+0x1b8/0x21c
Mar 15 03:05:36 bumbum kernel:  [c0009b94] do_IRQ+0x58/0xcc
Mar 15 03:05:36 bumbum kernel:  [c0008438] ret_from_except+0x0/0x1c
Mar 15 03:05:36 bumbum kernel:  [ce104234] read_intr+0x174/0x2c0  
[ide_disk]
Mar 15 03:05:36 bumbum kernel:  [c00fc144] ide_intr+0xec/0x174
Mar 15 03:05:36 bumbum kernel:  [c0009ad8] ppc_irq_dispatch_handler 
+0x1b8/0x21c
Mar 15 03:05:36 bumbum kernel: kblockd/0: page allocation failure.  
order:0, mod\
e:0x20
[snip the above lines starting from "Call trace" repeat some six times]
Mar 15 07:18:23 bumbum -- MARK --
[several more of these MARK's]
Mar 15 07:21:12 bumbum syslogd 1.4.1#17: restart.
[several more MARK's]
Mar 15 22:38:37 bumbum -- MARK --
Mar 15 22:58:37 bumbum -- MARK --
[Note: at 23:00:00, my cronjob started...]
Mar 15 23:02:31 bumbum kernel: hde: dma_intr: status=0x51  
{ DriveReady SeekComp\
lete Error }
Mar 15 23:02:31 bumbum kernel: hde: dma_intr: error=0x84  
{ DriveStatusError Bad\
CRC }
Mar 15 23:16:40 bumbum kernel: Oops: kernel access of bad area, sig:  
11 [#1]
Mar 15 23:16:40 bumbum kernel: NIP: C001AC60 LR: C0073B44 SP:  
CBFABE10 REGS: cb\
fabd60 TRAP: 0300    Not tainted
Mar 15 23:16:40 bumbum kernel: MSR: 00001032 EE: 0 PR: 0 FP: 0 ME: 1  
IR/DR: 11
Mar 15 23:16:40 bumbum kernel: DAR: 98540806, DSISR: 42000000
Mar 15 23:16:40 bumbum kernel: TASK = cbfa9980[1] 'init' THREAD:  
cbfaa000Last s\
yscall: 142
Mar 15 23:16:40 bumbum kernel: GPR00: 00100100 CBFABE10 CBFA9980  
00010800 CA894\
00C 00000000 00000000 CA894018
Mar 15 23:16:40 bumbum kernel: GPR08: 00097B8E 00009032 98540806  
00200200 00000\
000 1001F568 00000000 00000400
Mar 15 23:16:40 bumbum kernel: GPR16: 00000000 00000000 CB99D2D0  
CB99D2D4 CB99D\
2D8 CB99D2C4 CB99D2C8 CB99D2CC
Mar 15 23:16:40 bumbum kernel: GPR24: 0000000B 00000000 00000400  
00000104 00000\
00B CA894000 CA894008 CA894008
Mar 15 23:16:40 bumbum kernel: NIP [c001ac60] remove_wait_queue 
+0x28/0x40
Mar 15 23:16:40 bumbum kernel: LR [c0073b44] poll_freewait+0x34/0x70
Mar 15 23:16:40 bumbum kernel: Call trace:
Mar 15 23:16:40 bumbum kernel:  [c0073e94] do_select+0x148/0x280
Mar 15 23:16:40 bumbum kernel:  [c00742ac] sys_select+0x298/0x45c
Mar 15 23:16:40 bumbum kernel:  [c000dc98] ppc_select+0x98/0x9c
Mar 15 23:16:40 bumbum kernel:  [c0007d50] ret_from_syscall+0x0/0x4c
Mar 16 11:42:43 bumbum syslogd 1.4.1#17: restart.

-- dmesg output:
Total memory = 192MB; using 512kB for hash table (at c0300000)
Linux version 2.6.8.20060211 (root@bumbum) (gcc version 3.3.5 (Debian  
1:3.3.5-13
)) #1 Sat Feb 11 00:51:39 CET 2006
Found a Paddington mac-io controller, rev: 0, mapped at 0xfdf35000
PowerMac motherboard: PowerMac G4 PCI Graphics
Found Grackle (MPC106) PCI host bridge at 0x80000000. Firmware bus  
number: 0->1
nvram: OF partition at 0x140
nvram: XP partition at 0xffffffff
nvram: NR partition at 0xffffffff
On node 0 totalpages: 49152
  DMA zone: 49152 pages, LIFO batch:12
  Normal zone: 0 pages, LIFO batch:1
  HighMem zone: 0 pages, LIFO batch:1
Built 1 zonelists
Kernel command line: root=/dev/hdc3 ro
System has 64 possible interrupts
PID hash table entries: 1024 (order 10: 8192 bytes)
GMT Delta read from XPRAM: 0 minutes, DST: on
via_calibrate_decr: ticks per jiffy = 24934 (1496062 ticks)
Console: colour dummy device 80x25
serial8250_console_init: nothing to do on PowerMac
pmac_zilog: serial modem detected
Dentry cache hash table entries: 32768 (order: 5, 131072 bytes)
Inode-cache hash table entries: 16384 (order: 4, 65536 bytes)
Memory: 189408k available (1736k kernel code, 1092k data, 164k init,  
0k highmem)
Calibrating delay loop... 696.32 BogoMIPS
Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
checking if image is initramfs...it isn't (ungzip failed); looks like  
an initrd
Freeing initrd memory: 1584k freed
NET: Registered protocol family 16
PCI: Probing PCI hardware
PCI: Enabling device 0000:01:02.0 (0004 -> 0005)
Registering pmac pic with sysfs...
PCI: Enabling device 0000:00:10.0 (0086 -> 0087)
aty128fb: Found Open Firmware ROM Image
aty128fb: BIOS not located, guessing timings.
aty128fb: Rage128 RE PCI [chip rev 0x2] 16M 128-bit SDR SGRAM (1:1)
fb0: ATY Rage128 frame buffer device on Rage128 RE PCI
Thermal assist unit using timers, shrink_timer: 2000 jiffies
audit: initializing netlink socket (disabled)
audit(1142512332.090:0): initialized
devfs: 2004-01-31 Richard Gooch (rgooch@atnf.csiro.au)
devfs: boot_options: 0x0
Initializing Cryptographic API
Console: switching to colour frame buffer device 128x48
Generic RTC Driver v1.07
Macintosh non-volatile memory driver v1.1
serial8250_init: nothing to do on PowerMac
pmac_zilog: 0.6 (Benjamin Herrenschmidt <benh@kernel.crashing.org>)
ttyS0 at MMIO 0x80813020 (irq = 15) is a Z85c30 ESCC - Internal modem
ttyS1 at MMIO 0x80813000 (irq = 16) is a Z85c30 ESCC - Infrared port
RAMDISK driver initialized: 16 RAM disks of 8192K size 1024 blocksize
divert: not allocating divert_blk for non-ethernet device lo
MacIO PCI driver attached to Paddington chipset
Can't request resource 0 for MacIO device 0.00000000:power-mg
input: Macintosh mouse button emulation
Macintosh CUDA driver v0.5 for Unified ADB.
Uniform Multi-Platform E-IDE driver Revision: 7.00alpha2
ide: Assuming 33MHz system bus speed for PIO modes; override with  
idebus=xx
adb: starting probe task...
adb devices:
adb: finished probe task...
ide0: Found Apple Heathrow ATA controller, bus ID 0, irq 13
Probing IDE interface ide0...
hda: MATSHITA CR-589, ATAPI CD/DVD-ROM drive
hdb: IC35L120AVVA07-0, ATA DISK drive
hda: MDMA, cycleTime: 120, accessTime: 75, recTime: 45
hda: Set MDMA timing for mode 2, reg: 0x00211526
hda: Enabling MultiWord DMA 2
hdb: MDMA, cycleTime: 120, accessTime: 75, recTime: 45
hdb: Set MDMA timing for mode 2, reg: 0x00211526
hdb: Enabling MultiWord DMA 2
Using anticipatory io scheduler
ide0 at 0xce0d4000-0xce0d4007,0xce0d4160 on irq 13
mice: PS/2 mouse device common for all mice
NET: Registered protocol family 2
IP: routing cache hash table of 2048 buckets, 16Kbytes
TCP: Hash tables configured (established 16384 bind 32768)
RAMDISK: cramfs filesystem found at block 0
RAMDISK: Loading 1584 blocks [1 disk] into ram disk... done.
VFS: Mounted root (cramfs filesystem) readonly.
Freeing unused kernel memory: 164k init 4k chrp 32k prep
NET: Registered protocol family 1
AEC6280R: IDE controller at PCI slot 0000:01:02.0
AEC6280R: chipset revision 7
AEC6280R: ROM enabled at 0x80890000
AEC6280R: 100% native mode on irq 23
    ide2: BM-DMA at 0x1400-0x1407, BIOS settings: hde:pio, hdf:pio
    ide3: BM-DMA at 0x1408-0x140f, BIOS settings: hdg:pio, hdh:pio
Probing IDE interface ide2...
hde: Maxtor 6Y120P0, ATA DISK drive
hdf: Maxtor 6Y120P0, ATA DISK drive
ide2 at 0x14b0-0x14b7,0x14a2 on irq 23
Probing IDE interface ide3...
CMD646: IDE controller at PCI slot 0000:01:01.0
CMD646: chipset revision 7
CMD646: chipset revision 0x07, UltraDMA Capable
CMD646: 100% native mode on irq 26
    ide1: BM-DMA at 0x14c0-0x14c7, BIOS settings: hdc:pio, hdd:pio
    ide4: BM-DMA at 0x14c8-0x14cf, BIOS settings: hdi:pio, hdj:pio
Probing IDE interface ide1...
hdc: QUANTUM FIREBALLP AS40.0, ATA DISK drive
hdd: Maxtor 6Y120L0, ATA DISK drive
Unhandled interrupt 1a, disabled
ide1 at 0x1800-0x1807,0x14f2 on irq 26
Probing IDE interface ide4...
ide4: Wait for ready failed before probe !
hdb: max request size: 128KiB
hdb: 241254720 sectors (123522 MB) w/1863KiB Cache, CHS=65535/16/63,  
(U)DMA
/dev/ide/host0/bus0/target1/lun0: [mac] p1 p2
hde: max request size: 128KiB
hde: 240121728 sectors (122942 MB) w/7936KiB Cache, CHS=65535/16/63,  
UDMA(100)
/dev/ide/host2/bus0/target0/lun0: [mac] p1 p2
hdf: max request size: 128KiB
hdf: 240121728 sectors (122942 MB) w/7936KiB Cache, CHS=65535/16/63,  
UDMA(100)
/dev/ide/host2/bus0/target1/lun0: [mac] p1 p2
hdc: max request size: 128KiB
hdc: 78177792 sectors (40027 MB) w/1902KiB Cache, CHS=65535/16/63,  
UDMA(33)
/dev/ide/host1/bus0/target0/lun0: [mac] p1 p2 p3 p4
hdd: max request size: 128KiB
hdd: 240121728 sectors (122942 MB) w/2048KiB Cache, CHS=65535/16/63,  
UDMA(33)
/dev/ide/host1/bus0/target1/lun0: [mac] p1 p2
usbcore: registered new driver usbfs
usbcore: registered new driver hub
ohci_hcd: 2004 Feb 02 USB 1.1 'Open' Host Controller (OHCI) Driver (PCI)
ohci_hcd: block sizes: ed 64 td 64
ohci_hcd 0000:01:06.0: OPTi Inc. 82C861
ohci_hcd 0000:01:06.0: irq 28, pci mem ce0fb000
ohci_hcd 0000:01:06.0: new USB bus registered, assigned bus number 1
ohci_hcd 0000:01:06.0: WARNING: OPTi workarounds unavailable
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 2 ports detected
USB Universal Host Controller Interface driver v2.2
usbcore: registered new driver hiddev
usbcore: registered new driver usbhid
drivers/usb/input/hid-core.c: v2.0:USB HID core driver
kjournald starting.  Commit interval 5 seconds
...