[AHCI] XFS (sda3): metadata I/O error: block 0x941ce20 ("xlog_iodone") error 5 numblks 64

[Fengguang Wu]

Hi Tejun,

FYI, we noticed the below changes on

git://git.kernel.org/pub/scm/linux/kernel/git/tj/libata for-3.18-fixes
commit 61e268068c92ed000f078dc1ab71d1228439fecd ("Revert "AHCI: Optimize single IRQ interrupt processing"")

+-----------------------------------------------------------+------------+------------+
|                                                           | aa1cf25887 | 61e268068c |
+-----------------------------------------------------------+------------+------------+
| boot_successes                                            | 35         | 4          |
| early-boot-hang                                           | 1          |            |
| boot_failures                                             | 0          | 8          |
| metadata_I/O_error:block#("xlog_iodone")error#numblks     | 0          | 8          |
| XFS(sda3):Log_I/O_Error_Detected.Shutting_down_filesystem | 0          | 8          |
| Please_umount_the_filesystem_and_rectify_the_problem(s)   | 0          | 8          |
+-----------------------------------------------------------+------------+------------+


[   24.322655] sd 2:0:0:0: [sda] CDB: 
[   24.322657] Write(10): 2a 00 27 b5 22 10 00 00 10 00
[   24.322659] ata2: EH complete
[   24.322672] XFS (sda3): metadata I/O error: block 0x941ce20 ("xlog_iodone") error 5 numblks 64
[   24.322674] XFS (sda3): xfs_do_force_shutdown(0x2) called from line 1181 of file fs/xfs/xfs_log.c.  Return address = 0xffffffff81356796
[   24.322710] XFS (sda3): Log I/O Error Detected.  Shutting down filesystem
[   24.322710] XFS (sda3): Please umount the filesystem and rectify the problem(s)
[   24.322716] Buffer I/O error on device sda3, logical block 19432150
[   24.322716] lost page write due to I/O error on sda3
[   24.322720] Buffer I/O error on device sda3, logical block 19432151

To reproduce:

        apt-get install ruby ruby-oj
        git clone git://git.kernel.org/pub/scm/linux/kernel/git/wfg/lkp-tests.git
        cd lkp-tests
        bin/setup-local job.yaml # the job file attached in this email
        bin/run-local   job.yaml

testbox/testcase/testparams: lkp-ne04/fsmark/performance-1x-32t-1HDD-xfs-5K-400M-fsyncBeforeClose-16d-256fpd

aa1cf25887099bba  61e268068c92ed000f078dc1ab
----------------  --------------------------
           :15          20%           1:5     last_state.is_incomplete_run
           :15          20%           1:5     last_state.booting
           :15          80%           4:5     dmesg.Please_umount_the_filesystem_and_rectify_the_problem(s)
           :15          80%           4:5     dmesg.XFS(sda3):Log_I/O_Error_Detected.Shutting_down_filesystem
           :15          80%           4:5     dmesg.metadata_I/O_error:block#("xlog_iodone")error#numblks

testbox/testcase/testparams: lkp-ne04/fsmark/performance-1x-32t-1HDD-xfs-8K-400M-fsyncBeforeClose-16d-256fpd

aa1cf25887099bba  61e268068c92ed000f078dc1ab
----------------  --------------------------
       fail:runs  %reproduction    fail:runs
           |             |             |
           :10          80%           4:5     dmesg.Please_umount_the_filesystem_and_rectify_the_problem(s)
           :10          80%           4:5     dmesg.XFS(sda3):Log_I/O_Error_Detected.Shutting_down_filesystem
           :10          80%           4:5     dmesg.metadata_I/O_error:block#("xlog_iodone")error#numblks
           :10          80%           4:5     stderr.fopen_failed_to_open:fs_log.txt
           :10          80%           4:5     stderr.fs_mark:fsync_failed_Input/output_error

Thanks,
Fengguang

Attachment: .dmesg
Description: Binary data

---
testcase: fsmark
default_monitors:
  wait: pre-test
  uptime: 
  iostat: 
  vmstat: 
  numa-numastat: 
  numa-vmstat: 
  numa-meminfo: 
  proc-vmstat: 
  proc-stat: 
  meminfo: 
  slabinfo: 
  interrupts: 
  lock_stat: 
  latency_stats: 
  softirqs: 
  bdi_dev_mapping: 
  diskstats: 
  cpuidle: 
  cpufreq: 
  turbostat: 
  sched_debug:
    interval: 10
  pmeter: 
default_watchdogs:
  watch-oom: 
  watchdog: 
cpufreq_governor:
- performance
model: Nehalem-EP
memory: 12G
hdd_partitions: "/dev/disk/by-id/ata-ST3500514NS_9WJ03EBA-part3"
swap_partitions: "/dev/disk/by-id/ata-ST3120026AS_5MS07HA2-part2"
rootfs_partition: "/dev/disk/by-id/ata-ST3500514NS_9WJ03EBA-part1"
commit: 61e268068c92ed000f078dc1ab71d1228439fecd
iterations: 1x
nr_threads: 32t
disk: 1HDD
fs:
- xfs
fs2:
- 
fsmark:
  filesize:
  - 5K
  test_size: 400M
  sync_method: fsyncBeforeClose
  nr_directories: 16d
  nr_files_per_directory: 256fpd
enqueue_time: 2014-10-31 18:16:31.406733520 +08:00
testbox: lkp-ne04
tbox_group: lkp-ne04
kconfig: x86_64-rhel
head_commit: 7d33fe9ab9eace2403adefea3c6dc2c92a0a5185
base_commit: cac7f2429872d3733dc3f9915857b1691da2eb2f
branch: linux-devel/devel-hourly-2014102723
user: lkp
queue: validate
rootfs: debian-x86_64.cgz
result_root: "/result/lkp-ne04/fsmark/performance-1x-32t-1HDD-xfs-5K-400M-fsyncBeforeClose-16d-256fpd/debian-x86_64.cgz/x86_64-rhel/61e268068c92ed000f078dc1ab71d1228439fecd/3"
job_file: "/lkp/scheduled/lkp-ne04/validate_fsmark-performance-1x-32t-1HDD-xfs-5K-400M-fsyncBeforeClose-16d-256fpd-debian-x86_64.cgz-x86_64-rhel-61e268068c92ed000f078dc1ab71d1228439fecd-2.yaml"
repeat_to: 5
kernel: "/kernel/x86_64-rhel/61e268068c92ed000f078dc1ab71d1228439fecd/vmlinuz-3.18.0-rc2-g61e2680"
dequeue_time: 2014-10-31 18:25:36.586355107 +08:00
job_state: failed
loadavg: 2.80 0.63 0.21 1/209 3265
start_time: '1414751176'
end_time: '1414751180'
version: "/lkp/lkp/.src-20141030-221304"