On Wed, 2012-02-15 at 15:27 +0800, Jim Barber wrote: > On 14/02/2012 8:45 AM, Jim Barber wrote: > > Thanks Nicholas. > > > > I'm building the new kernel as I type this and will install it the first chance I get. > > > > I'm not sure why my system might be taking a long time to return outstanding I/O. > > It is using a 3ware 9650SE RAID controller with the StorSave policy set to 'performance' with read cache off and write cache on. > > It uses a RAID-1 array for the operating system. > > It has a RAID-10 array made up of 8x 750GB 7200rpm SATA disks that are used exclusively by LIO. > > It's not enterprise class disk, but I wouldn't expect it to be too slow... > > > > Regards, > > Hi Nicholas. > > I've had the problem again on the new kernel. > It starts out like so: > Hi Jim, Thanks for the quick turn-around.. > Feb 15 13:49:31 san kernel: [70231.165867] ABORT_TASK: Found referenced qla2xxx task_tag: 1160872 > Feb 15 13:49:31 san kernel: [70231.182553] qla2xxx 0000:0b:00.0: qla2x00_error_entry: error entry, type 0x12 status 0x8 > Feb 15 13:49:31 san kernel: [70231.436017] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 1160872 > Feb 15 13:49:35 san kernel: [70234.529340] qla2xxx 0000:0b:00.0: qla2x00_error_entry: error entry, type 0x12 status 0x8 Strange.. So the ABORT_TASK is received, and immediately (in less than 1 sec) locates ref_tag: 1160872, and sends a TMR_FUNCITON_COMPLETION. Which would lead me to believe that ref_tag: 1160872 is *not* actually outstanding in the backend device, but is actually in the qla HW completion queue waiting to be pushed back onto the wire.. What I'm still not able to reproduce on my side with qla2xxx Linux clients is the bit: qla2xxx 0000:0b:00.0: qla2x00_error_entry: error entry, type 0x12 status 0x8 Which indicated an error entry for type CTIO_TYPE7 (likely the timed out completion I/O with ref_tag: 1160872). Just to make sure, can you verify which firmware that you're using with qla2xxx on the target side..? This value will appear in dmesg during 'modprobe qla2xxx' time like so: [ 3253.670910] scsi20 : qla2xxx [ 3253.674503] qla2xxx 0000:03:00.0: skipping scsi_scan_host() for non-initiator port [ 3253.682974] qla2xxx [0000:03:00.0]-00fa:20: QLogic Fibre Channed HBA Driver: 8.03.07.12-k. [ 3253.692186] qla2xxx [0000:03:00.0]-00fb:20: QLogic QLE2562 - PCI-Express Dual Channel 8Gb Fibre Channel HBA. [ 3253.703150] qla2xxx [0000:03:00.0]-00fc:20: ISP2532: PCIe (5.0GT/s x4) @ 0000:03:00.0 hdma+ host#=20 fw=5.06.01 (90d5). Thanks, --nab > Feb 15 13:50:26 san kernel: [70285.969579] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:50:26 san kernel: [70285.969637] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:50:26 san kernel: [70285.971662] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:50:26 san kernel: [70285.971722] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:50:26 san kernel: [70285.971870] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:50:26 san kernel: [70285.971926] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:51:08 san kernel: [70328.192114] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:51:08 san kernel: [70328.192170] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:51:08 san kernel: [70328.194047] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:51:08 san kernel: [70328.194105] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:51:08 san kernel: [70328.194251] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:51:08 san kernel: [70328.194306] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:52:09 san kernel: [70388.651916] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:52:09 san kernel: [70388.651972] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:52:09 san kernel: [70388.653923] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:52:09 san kernel: [70388.653982] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:52:09 san kernel: [70388.654133] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:52:09 san kernel: [70388.654189] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:53:08 san kernel: [70448.205196] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:53:08 san kernel: [70448.205250] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:53:08 san kernel: [70448.207244] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:53:08 san kernel: [70448.207301] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:53:08 san kernel: [70448.207448] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:53:08 san kernel: [70448.207503] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:53:10 san kernel: [70450.367519] TARGET_CORE[qla2xxx]: Detected NON_EXISTENT_LUN Access for 0x00000001 > Feb 15 13:53:10 san kernel: [70450.367737] TARGET_CORE[qla2xxx]: Detected NON_EXISTENT_LUN Access for 0x00000002 > Feb 15 13:53:10 san kernel: [70450.367822] TARGET_CORE[qla2xxx]: Detected NON_EXISTENT_LUN Access for 0x00000001 > Feb 15 13:53:10 san kernel: [70450.367944] TARGET_CORE[qla2xxx]: Detected NON_EXISTENT_LUN Access for 0x00000003 > Feb 15 13:53:10 san kernel: [70450.367996] TARGET_CORE[qla2xxx]: Detected NON_EXISTENT_LUN Access for 0x00000002 > Feb 15 13:53:10 san kernel: [70450.368177] TARGET_CORE[qla2xxx]: Detected NON_EXISTENT_LUN Access for 0x00000004 > Feb 15 13:53:10 san kernel: [70450.368208] TARGET_CORE[qla2xxx]: Detected NON_EXISTENT_LUN Access for 0x00000003 > Feb 15 13:53:10 san kernel: [70450.368472] TARGET_CORE[qla2xxx]: Detected NON_EXISTENT_LUN Access for 0x00000005 > Feb 15 13:53:10 san kernel: [70450.368491] TARGET_CORE[qla2xxx]: Detected NON_EXISTENT_LUN Access for 0x00000004 > Feb 15 13:53:10 san kernel: [70450.368624] TARGET_CORE[qla2xxx]: Detected NON_EXISTENT_LUN Access for 0x00000005 > Feb 15 13:53:10 san kernel: [70450.368726] TARGET_CORE[qla2xxx]: Detected NON_EXISTENT_LUN Access for 0x00000006 > Feb 15 13:53:10 san kernel: [70450.368826] TARGET_CORE[qla2xxx]: Detected NON_EXISTENT_LUN Access for 0x00000006 > > > Then has a whole lot of "Detected NON_EXISTENT_LUN Access" messages ranging from LUNs 0x00000001 to 0x000000ff > These seem to occur multiple times. > Then at some point it got a few more messages that weren't the NON_EXISTENT_LUN errors again: > > > Feb 15 13:53:46 san kernel: [70486.230938] TARGET_CORE[qla2xxx]: Detected NON_EXISTENT_LUN Access for 0x000000fe > Feb 15 13:53:46 san kernel: [70486.231103] TARGET_CORE[qla2xxx]: Detected NON_EXISTENT_LUN Access for 0x000000ff > Feb 15 13:54:09 san kernel: [70508.665020] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:54:09 san kernel: [70508.665075] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:54:09 san kernel: [70508.667039] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:54:09 san kernel: [70508.667095] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:54:09 san kernel: [70508.667236] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:54:09 san kernel: [70508.667288] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:55:08 san kernel: [70568.218536] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:55:08 san kernel: [70568.218593] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:55:08 san kernel: [70568.220629] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:55:08 san kernel: [70568.220691] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:55:08 san kernel: [70568.220843] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:55:08 san kernel: [70568.220899] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:56:09 san kernel: [70628.677543] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:56:09 san kernel: [70628.677600] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:56:09 san kernel: [70628.679594] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:56:09 san kernel: [70628.679654] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:56:09 san kernel: [70628.679805] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:56:09 san kernel: [70628.679862] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:57:08 san kernel: [70688.230564] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:57:08 san kernel: [70688.230620] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:57:08 san kernel: [70688.232573] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:57:08 san kernel: [70688.232629] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:57:08 san kernel: [70688.232781] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:57:08 san kernel: [70688.232837] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:58:09 san kernel: [70748.690792] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:58:09 san kernel: [70748.690846] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:58:09 san kernel: [70748.692831] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:58:09 san kernel: [70748.692889] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:58:09 san kernel: [70748.693039] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:58:09 san kernel: [70748.693095] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:58:10 san kernel: [70750.377109] TARGET_CORE[qla2xxx]: Detected NON_EXISTENT_LUN Access for 0x00000001 > Feb 15 13:58:10 san kernel: [70750.377178] TARGET_CORE[qla2xxx]: Detected NON_EXISTENT_LUN Access for 0x00000001 > Feb 15 13:58:10 san kernel: [70750.377374] TARGET_CORE[qla2xxx]: Detected NON_EXISTENT_LUN Access for 0x00000002 > Feb 15 13:58:10 san kernel: [70750.377405] TARGET_CORE[qla2xxx]: Detected NON_EXISTENT_LUN Access for 0x00000002 > > > Then back to the NON_EXISTENT_LUN errors before yet another dump of info: > > > Feb 15 13:59:08 san kernel: [70808.445378] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:59:08 san kernel: [70808.445433] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:59:08 san kernel: [70808.447417] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:59:08 san kernel: [70808.447474] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 13:59:08 san kernel: [70808.447620] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 13:59:08 san kernel: [70808.447675] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 14:00:09 san kernel: [70868.904789] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 14:00:09 san kernel: [70868.904848] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 14:00:09 san kernel: [70868.906837] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 14:00:09 san kernel: [70868.906897] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 14:00:09 san kernel: [70868.907044] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 14:00:09 san kernel: [70868.907100] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 14:01:08 san kernel: [70928.458780] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 14:01:08 san kernel: [70928.458837] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 14:01:08 san kernel: [70928.460846] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 14:01:08 san kernel: [70928.460904] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 14:01:08 san kernel: [70928.461060] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 14:01:08 san kernel: [70928.461116] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 14:02:09 san kernel: [70988.918201] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 14:02:09 san kernel: [70988.918259] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 14:02:09 san kernel: [70988.920222] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 14:02:09 san kernel: [70988.920283] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 14:02:09 san kernel: [70988.920432] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 14:02:09 san kernel: [70988.920488] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 14:03:08 san kernel: [71048.471585] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 14:03:08 san kernel: [71048.471642] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 14:03:08 san kernel: [71048.473670] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 14:03:08 san kernel: [71048.473731] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 14:03:08 san kernel: [71048.473879] scsi(5): resetting (session ffff8801279b48c0 from port 21:00:00:1b:32:83:f3:c6, mcmd > fffd, loop_id 130) > Feb 15 14:03:08 san kernel: [71048.473935] qla_target(0): Unknown task mgmt fn 0xfffd > Feb 15 14:03:10 san kernel: [71050.386572] TARGET_CORE[qla2xxx]: Detected NON_EXISTENT_LUN Access for 0x00000001 > > > Then I rebooted the system again. > > The most recent 'git log' entry for the currently running kernel is: > > commit c851cb5a4043e11ae7844dc8a01d4787a4cc9573 > Author: Nicholas Bellinger <nab@xxxxxxxxxxxxxxx> > Date: Mon Feb 13 01:26:48 2012 -0800 > > qla_target/tcm_qla2xxx: Fix TMR_ABORT_TASK with target mode usage > > Regards, > > ---------- > Jim Barber > DDI Health -- To unsubscribe from this list: send the line "unsubscribe target-devel" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
