Re: Kernel crash on high load

Raffaello Cassetta wrote to linux1394-user:
> I've experienced a severe kernel crash and a command fail
> under very high filesystem load on an external firewire HD.
>  
> Kernel crash:
>  
> Environment:
> Linux Fedora Core 4
> kernel 2.6.16-1.2115
> 512 MB memory
> 80 GB internal IDE HD for system
> 1TB external Firewire RAID (4 HDs) enclosure for data
> sbp2 serialize off
>  
> Process that caused crash:
> 2 cp commands running for copying huge
> amount of data from two folder on the external enclosure.
>  
> Kernel log:
> 
> ieee1394: sbp2: aborting sbp2 command
> sd 0:0:0:0:
> command: Read (10): 28 00 0b 31 67 1f 00 00 a8 00
> ieee1394: sbp2: aborting sbp2 command
> sd 0:0:0:0:
> command: Write (10): 2a 00 28 6b ae 37 00 00 60 00
[...similar messages repeated multiple times...]
> invalid opcode: 0000 [#1]
> last sysfs file: /class/vc/vcs6/dev
> Modules linked in: ipv6 autofs4 sg sd_mod sbp2 scsi_mod dm_mod video button 
> battery ac ohci1394 ieee1394 ohci_hcd ehci_hcd sis900 mii r8169 floppy ext3 jbd
> CPU: 0
> EIP: 0060:[<de87a007>] Not tainted VLI
> EFLAGS: 00010202 (2.6.16-1.2115_FC4 #1)
> EIP is at ext3_has_free_blocks+0x7/0x56 [ext3]
> eax: dca66400 ebx: dcd1dd80 ecx: c78e1348 edx: dca66400
> esi: 00000008 edi: dd0b4400 ebp: c23b7cb4 esp: c23b7bc4
> ds: 007b es: 007b ss: 0068
> Process as (pid: 10275, threadinfo=c23b7000 task=caa08aa0)
> Stack: <0>dd0b4400 de87b10e 21ac0e60 4497bd7f 00000000 c012114d 00000246 dd56c400
> c23b7c04 00000246 00139800 c78e1348 d98e93c4 00000246 00000010 dd4fcc00
> dd0b4400 dca66400 dcd1dd80 dc67f700 00080292 00000000 c78e1294 c23b7cb4
> Call Trace:
> [<de87b10e>] ext3_new_block+0xd3/0x59b [ext3] [<c012114d>] current_fs_time+0x4e/0x71
> [<de87fa59>] ext3_get_block_handle+0x244/0x843 [ext3] [<c031aa65>] 
> _read_unlock_irq+0x5/0x7
> [<de8800aa>] ext3_get_block+0x52/0x90 [ext3] [<c015f444>] 
> __block_prepare_write+0x235/0x46f
> [<de845675>] journal_start+0xc2/0xef [jbd] [<c015f6a0>] 
> block_prepare_write+0x22/0x30
> [<de880058>] ext3_get_block+0x0/0x90 [ext3] [<de87f09a>] 
> ext3_prepare_write+0x11e/0x132 [ext3]
> [<de880058>] ext3_get_block+0x0/0x90 [ext3] [<de87ef7c>] 
> ext3_prepare_write+0x0/0x132 [ext3]
> [<c013e867>] generic_file_buffered_write+0x29f/0x655 [<c012114d>] 
> current_fs_time+0x4e/0x71
> [<c013fe81>] __generic_file_aio_write_nolock+0x255/0x462 [<c01402e8>] 
> generic_file_aio_write+0x5b/0xd0
> [<de87c0ec>] ext3_file_write+0x24/0x96 [ext3] [<c015bbdb>] do_sync_write+0xc3/0x11e
> [<c014c857>] arch_get_unmapped_area_topdown+0x135/0x14f [<c012e858>] 
> autoremove_wake_function+0x0/0x37
> [<c013c2bc>] audit_syscall_entry+0x11a/0x13b [<c015bb18>] do_sync_write+0x0/0x11e
> [<c015c02d>] vfs_write+0xa4/0x15a [<c015c97a>] sys_write+0x41/0x6a
> [<c0102d35>] syscall_call+0x7/0xb <0>Code: Bad EIP value.
> Continuing in 120 seconds.
> Continuing in 119 seconds.
> ..........omissis.........
> Continuing in 1 seconds.
> <3>ieee1394: sbp2: aborting sbp2 command
> sd 0:0:0:0:
> command: Write (10): 2a 00 57 c2 70 2f 00 00 f8 00
[...etc...]
[from 2nd log:]
> ieee1394: sbp2: sbp2util_node_write_no_wait failed.
> ieee1394: sbp2: aborting sbp2 command
> sd 0:0:0:0:
> command: Write (10): 2a 00 8b 99 2b cf 00 00 f8 00
> ieee1394: sbp2: sbp2util_node_write_no_wait failed.
> ieee1394: sbp2: aborting sbp2 command
> sd 0:0:0:0:
> command: Write (10): 2a 00 8b 99 4d 4f 00 00 f8 00

Thanks for the report. I suspect this are three bugs:

1. many "aborting sbp2 command", without other error notices from
   the 1394 subsystem or sense data logged by the SCSI subsystem:
   could be the same old issue as filed in
   http://bugzilla.kernel.org/show_bug.cgi?id=1872
   "data corruption on ipod using sbp2 module"
   I currently believe it may be caused by the same underlying
   problem as the next bug (sbp2 not waiting for transactions to
   finish).

2. "sbp2util_node_write_no_wait failed", most likely because of
   temporary unavailability of transaction labels
   sbp2 should wait until transaction labels are freed, but it
   can't do so yet because it initiates transactions from atomic
   context. (Sorry for the techno babble, just ignore it.) I plan
   to move this part in sbp2 into process context but I am
   embarassingly slow putting my plans into practice.
   http://marc.theaimsgroup.com/?l=linux1394-devel&m=113119559513711
   (a discussion from November 2005)

3. The crash ("invalid opcode") may be a problem in ext3 after it
   got invalid data due to sbp2's failures. I am therefore
   crossposting to ext2-devel.
   Or underlying code like sbp2 or scsi overwrote memory where it
   had no business to write, after that code did something stupid
   based on invalid data.

If you want to be notified when I or somebody else did something
against those "aborting sbp2 command"s, you could stay subscribed to
linux1394-user or add your address to above linked bugzilla entry.

BTW, what brand and model is the enclosure? And do you know which
SBP-2 bridge chip is used in it?
-- 
Stefan Richter
-=====-=-==- -==- =-=--
http://arcgraph.de/sr/