I've been experiencing delays access data off my file server since I
upgraded to 5.3... either I hosed something, have bad hardware or very
unlikely, found a bug.
When reading or writing data, the stream to the hdd's stops every 5-10
min and %iowait goes through the roof. I checked the logs and they
are filled with this diagnostic data that I can't readily decipher.
my setup involves two md raid5 devices, 9+1 sata drives total, five of
them are on the internal intel sata (i5000) controller, five of them
on an external super micro (marvell) controller. I need to do some
more testing to see which of (or is it both?) of the md devices is
generating these errors.
system is running centos 5.3 64bit:
# uname -a
Linux xenmaster.dimension-x.local 2.6.18-128.1.6.el5xen #1 SMP Wed Apr
1 09:53:14 EDT 2009 x86_64 x86_64 x86_64 GNU/Linux
# cat /proc/mdstat
Personalities : [raid6] [raid5] [raid4]
md1 : active raid5 sdk1[2] sdj1[4] sdi1[3] sdh1[0] sdg1[1]
976783616 blocks level 5, 64k chunk, algorithm 2 [5/5] [UUUUU]
md0 : active raid5 sdf1[3] sde1[1] sdd1[4](S) sdc1[0] sdb1[2]
2197715712 blocks level 5, 64k chunk, algorithm 2 [4/4] [UUUU]
unused devices: <none>
here is what dmesg has to say: (some of it looks like repeats but some
of it is very slightly different too)
BUG: warning at drivers/ata/libata-core.c:4923/ata_qc_issue() (Tainted: G )
Call Trace:
[<ffffffff880b6625>] :libata:ata_qc_issue+0x61/0x4a9
[<ffffffff880bacf3>] :libata:ata_scsi_rw_xlat+0x119/0x188
[<ffffffff880735a6>] :scsi_mod:scsi_done+0x0/0x18
[<ffffffff880babda>] :libata:ata_scsi_rw_xlat+0x0/0x188
[<ffffffff880baea2>] :libata:ata_scsi_translate+0x140/0x16d
[<ffffffff880735a6>] :scsi_mod:scsi_done+0x0/0x18
[<ffffffff80299dd4>] keventd_create_kthread+0x0/0xc4
[<ffffffff880bda72>] :libata:ata_scsi_queuecmd+0x1b4/0x1d4
[<ffffffff88073c83>] :scsi_mod:scsi_dispatch_cmd+0x290/0x322
[<ffffffff880790e2>] :scsi_mod:scsi_request_fn+0x2c5/0x39c
[<ffffffff8025c62a>] generic_unplug_device+0x22/0x37
[<ffffffff8835c060>] :raid456:unplug_slaves+0x60/0x9b
[<ffffffff8836122f>] :raid456:raid5d+0x17c/0x187
[<ffffffff802639f9>] _spin_lock_irqsave+0x9/0x14
[<ffffffff803fed01>] md_thread+0xf8/0x10e
[<ffffffff80299fec>] autoremove_wake_function+0x0/0x2e
[<ffffffff803fec09>] md_thread+0x0/0x10e
[<ffffffff80233483>] kthread+0xfe/0x132
[<ffffffff8025fb2c>] child_rip+0xa/0x12
[<ffffffff80299dd4>] keventd_create_kthread+0x0/0xc4
[<ffffffff80233385>] kthread+0x0/0x132
[<ffffffff8025fb22>] child_rip+0x0/0x12
BUG: warning at drivers/ata/libata-core.c:4923/ata_qc_issue() (Tainted: G )
Call Trace:
[<ffffffff880b6625>] :libata:ata_qc_issue+0x61/0x4a9
[<ffffffff880bacf3>] :libata:ata_scsi_rw_xlat+0x119/0x188
[<ffffffff880735a6>] :scsi_mod:scsi_done+0x0/0x18
[<ffffffff880babda>] :libata:ata_scsi_rw_xlat+0x0/0x188
[<ffffffff880baea2>] :libata:ata_scsi_translate+0x140/0x16d
[<ffffffff880735a6>] :scsi_mod:scsi_done+0x0/0x18
[<ffffffff80299dd4>] keventd_create_kthread+0x0/0xc4
[<ffffffff880bda72>] :libata:ata_scsi_queuecmd+0x1b4/0x1d4
[<ffffffff88073c83>] :scsi_mod:scsi_dispatch_cmd+0x290/0x322
[<ffffffff880790e2>] :scsi_mod:scsi_request_fn+0x2c5/0x39c
[<ffffffff8025c62a>] generic_unplug_device+0x22/0x37
[<ffffffff8835c060>] :raid456:unplug_slaves+0x60/0x9b
[<ffffffff8836122f>] :raid456:raid5d+0x17c/0x187
[<ffffffff802639f9>] _spin_lock_irqsave+0x9/0x14
[<ffffffff803fed01>] md_thread+0xf8/0x10e
[<ffffffff80299fec>] autoremove_wake_function+0x0/0x2e
[<ffffffff803fec09>] md_thread+0x0/0x10e
[<ffffffff80233483>] kthread+0xfe/0x132
[<ffffffff8025fb2c>] child_rip+0xa/0x12
[<ffffffff80299dd4>] keventd_create_kthread+0x0/0xc4
[<ffffffff80233385>] kthread+0x0/0x132
[<ffffffff8025fb22>] child_rip+0x0/0x12
BUG: warning at drivers/ata/libata-core.c:4923/ata_qc_issue() (Tainted: G )
Call Trace:
[<ffffffff880b6625>] :libata:ata_qc_issue+0x61/0x4a9
[<ffffffff880bacf3>] :libata:ata_scsi_rw_xlat+0x119/0x188
[<ffffffff880735a6>] :scsi_mod:scsi_done+0x0/0x18
[<ffffffff880babda>] :libata:ata_scsi_rw_xlat+0x0/0x188
[<ffffffff880baea2>] :libata:ata_scsi_translate+0x140/0x16d
[<ffffffff880735a6>] :scsi_mod:scsi_done+0x0/0x18
[<ffffffff8033949e>] cfq_kick_queue+0x0/0x89
[<ffffffff880bda72>] :libata:ata_scsi_queuecmd+0x1b4/0x1d4
[<ffffffff88073c83>] :scsi_mod:scsi_dispatch_cmd+0x290/0x322
[<ffffffff880790e2>] :scsi_mod:scsi_request_fn+0x2c5/0x39c
[<ffffffff80339514>] cfq_kick_queue+0x76/0x89
[<ffffffff8024ee1e>] run_workqueue+0x94/0xe4
[<ffffffff8024b727>] worker_thread+0x0/0x122
[<ffffffff80299dd4>] keventd_create_kthread+0x0/0xc4
[<ffffffff8024b817>] worker_thread+0xf0/0x122
[<ffffffff80286daf>] default_wake_function+0x0/0xe
[<ffffffff80299dd4>] keventd_create_kthread+0x0/0xc4
[<ffffffff80299dd4>] keventd_create_kthread+0x0/0xc4
[<ffffffff80233483>] kthread+0xfe/0x132
[<ffffffff8025fb2c>] child_rip+0xa/0x12
[<ffffffff80299dd4>] keventd_create_kthread+0x0/0xc4
[<ffffffff8026df02>] monotonic_clock+0x35/0x7b
[<ffffffff80233385>] kthread+0x0/0x132
[<ffffffff8025fb22>] child_rip+0x0/0x12
BUG: warning at drivers/ata/libata-core.c:4923/ata_qc_issue() (Tainted: G )
Call Trace:
[<ffffffff880b6625>] :libata:ata_qc_issue+0x61/0x4a9
[<ffffffff880bacf3>] :libata:ata_scsi_rw_xlat+0x119/0x188
[<ffffffff880735a6>] :scsi_mod:scsi_done+0x0/0x18
[<ffffffff880babda>] :libata:ata_scsi_rw_xlat+0x0/0x188
[<ffffffff880baea2>] :libata:ata_scsi_translate+0x140/0x16d
[<ffffffff880735a6>] :scsi_mod:scsi_done+0x0/0x18
[<ffffffff80299dd4>] keventd_create_kthread+0x0/0xc4
[<ffffffff880bda72>] :libata:ata_scsi_queuecmd+0x1b4/0x1d4
[<ffffffff88073c83>] :scsi_mod:scsi_dispatch_cmd+0x290/0x322
[<ffffffff880790e2>] :scsi_mod:scsi_request_fn+0x2c5/0x39c
[<ffffffff8025c62a>] generic_unplug_device+0x22/0x37
[<ffffffff8835c060>] :raid456:unplug_slaves+0x60/0x9b
[<ffffffff8836122f>] :raid456:raid5d+0x17c/0x187
[<ffffffff802639f9>] _spin_lock_irqsave+0x9/0x14
[<ffffffff803fed01>] md_thread+0xf8/0x10e
[<ffffffff80299fec>] autoremove_wake_function+0x0/0x2e
[<ffffffff803fec09>] md_thread+0x0/0x10e
[<ffffffff80233483>] kthread+0xfe/0x132
[<ffffffff8025fb2c>] child_rip+0xa/0x12
[<ffffffff80299dd4>] keventd_create_kthread+0x0/0xc4
[<ffffffff80233385>] kthread+0x0/0x132
[<ffffffff8025fb22>] child_rip+0x0/0x12
BUG: warning at drivers/ata/libata-core.c:4923/ata_qc_issue() (Tainted: G )
Call Trace:
<IRQ> [<ffffffff880b6625>] :libata:ata_qc_issue+0x61/0x4a9
[<ffffffff880bacf3>] :libata:ata_scsi_rw_xlat+0x119/0x188
[<ffffffff880735a6>] :scsi_mod:scsi_done+0x0/0x18
[<ffffffff880babda>] :libata:ata_scsi_rw_xlat+0x0/0x188
[<ffffffff880baea2>] :libata:ata_scsi_translate+0x140/0x16d
[<ffffffff880735a6>] :scsi_mod:scsi_done+0x0/0x18
[<ffffffff880bda72>] :libata:ata_scsi_queuecmd+0x1b4/0x1d4
[<ffffffff88073c83>] :scsi_mod:scsi_dispatch_cmd+0x290/0x322
[<ffffffff880790e2>] :scsi_mod:scsi_request_fn+0x2c5/0x39c
[<ffffffff8025e2f2>] blk_run_queue+0x41/0x72
[<ffffffff88078016>] :scsi_mod:scsi_next_command+0x2d/0x39
[<ffffffff88078174>] :scsi_mod:scsi_end_request+0xbf/0xcd
[<ffffffff880782d0>] :scsi_mod:scsi_io_completion+0x14e/0x324
[<ffffffff880a57cd>] :sd_mod:sd_rw_intr+0x21d/0x257
[<ffffffff88078565>] :scsi_mod:scsi_device_unbusy+0x67/0x81
[<ffffffff802389b8>] blk_done_softirq+0x67/0x75
[<ffffffff80212880>] __do_softirq+0x8d/0x13b
[<ffffffff8025fda4>] call_softirq+0x1c/0x278
[<ffffffff8026d08e>] do_softirq+0x31/0x98
[<ffffffff8026cf09>] do_IRQ+0xec/0xf5
[<ffffffff803a6cca>] evtchn_do_upcall+0x13b/0x1fb
[<ffffffff8025f8d6>] do_hypervisor_callback+0x1e/0x2c
<EOI> [<ffffffff8026df02>] monotonic_clock+0x35/0x7b
[<ffffffff802063aa>] hypercall_page+0x3aa/0x1000
[<ffffffff802063aa>] hypercall_page+0x3aa/0x1000
[<ffffffff8026e4e5>] raw_safe_halt+0x84/0xa8
[<ffffffff8026ba22>] xen_idle+0x38/0x4a
[<ffffffff8024a803>] cpu_idle+0x97/0xba
var/log/messages has the same info, with timestamps - this error
repeats itself several times a second for several minutes at a time
all suggestions are appreciated!
-Gordon