☰

为什么 `ioerr_cnt` 不断上升，但日志中没有显示任何消息？

tag-icon • tag-icon linux-kernel scsi
为什么 `ioerr_cnt` 不断上升，但日志中没有显示任何消息？ 
$ cd /sys/devices/pci0000:00/0000:00:1f.2/ata2/host1/target1:0:0/1:0:0:0
$ ls -l driver subsystem
lrwxrwxrwx. 1 root root 0 Apr  5 10:48 driver -> ../../../../../../../bus/scsi/drivers/sd
lrwxrwxrwx. 1 root root 0 Apr  3 08:48 subsystem -> ../../../../../../../bus/scsi
$ cat ioerr_cnt 
0x38c

:(

大约一分钟后，没有真正做任何事情：

$ cat ioerr_cnt
0x391

:((

根据 IBM 文章，ioerr_cnt意思是“完成但有错误的 SCSI 命令数”。

我当前的内核日志 ( dmesg) 显示没有 I/O 错误，也没有来自 SCSI、ATA 或 AHCI 的错误。

为什么像上面这样失败的 SCSI 命令不会出现在内核日志中？通常，如果您有一张有问题的 DVD 或 USB 记忆棒，您会收到很多关于错误和重试等的好消息。

我可以看到失败的 SCSI 命令，或者以某种方式跟踪相关代码吗？

需要明确的是，如果有什么区别的话，这是一个 SATA 设备（像 Linux 一样使用 SCSI ATA 转换）。而且它是我的笔记本电脑内部硬盘驱动器，所以如果有任何“真正的”IO 错误我想知道:)。首先查看这个计数器的别有用心：我正在尝试调试一些相当安静的 IO 错误，导致从挂起恢复时崩溃。

内核版本：4.15.12-301.fc27.x86_64

编辑：blktrace

blktrace应该能够监视 SCSI 命令并显示错误。我在一段时间内运行了它，出现了 0x3a5 - 0x3a0 = 5 个错误。然后运行blkparse并%e添加到默认格式字符串的末尾，以显示错误代码：

blkparse -f "%D %2c %8s %5T.%9t %5p %2a %3d %e\n"

但是，使用搜索输出中的错误grep -vE "( 0)|( )$没有显示任何结果。

编辑：scsi_logging_level

# scsi_logging_level -s --error=7 --ioctl=7  # from sg3-utils package
# dmesg -w
...
[112831.843993] sd 1:0:0:0: scsi_block_when_processing_errors: rtn: 1
[112831.844004] sd 1:0:0:0: [sda] sd_ioctl: disk=sda, cmd=0x2285
[112831.844007] sd 1:0:0:0: scsi_block_when_processing_errors: rtn: 1
[112831.844012] sd 1:0:0:0: [sda] sd_ioctl: disk=sda, cmd=0x2285
[112831.844015] sd 1:0:0:0: scsi_block_when_processing_errors: rtn: 1
[112831.900267] sd 1:0:0:0: scsi_block_when_processing_errors: rtn: 1
[112831.901394] sd 1:0:0:0: [sda] sd_ioctl: disk=sda, cmd=0x2285
[112831.901397] sd 1:0:0:0: scsi_block_when_processing_errors: rtn: 1
[112831.987030] sd 1:0:0:0: [sda] sd_ioctl: disk=sda, cmd=0x2285
[112831.987034] sd 1:0:0:0: scsi_block_when_processing_errors: rtn: 1
[112832.016745] sd 1:0:0:0: [sda] sd_ioctl: disk=sda, cmd=0x2285
[112832.016749] sd 1:0:0:0: scsi_block_when_processing_errors: rtn: 1
[112832.060156] sd 1:0:0:0: [sda] sd_ioctl: disk=sda, cmd=0x2285
[112832.060160] sd 1:0:0:0: scsi_block_when_processing_errors: rtn: 1
[112832.224840] sd 1:0:0:0: scsi_block_when_processing_errors: rtn: 1

ioerr_cnt似乎与上述消息同时上涨。

SCSI ioctl() 0x2285 是SG_IO，即用户空间提交特定的SCSI命令。

我正在努力弄清楚什么过程是这样做的。 sudo lsof +D /dev/似乎没有显示当前打开的 SCSI 设备的任何进程，但在发生错误时我也没有看到任何相关的 open() 调用 ( cd /dev && sudo fatrace -c)。

通常，这些事件之间的间隔（6 个 ioctl 和 5 个 ioerr，如上所述）正好是 10 分钟。

答案1

udisks 每十分钟轮询一次驾驶，例如聪明的数据。

我希望不同的驱动器有不同的可以轮询的东西。这是有道理的，udisk 可能无法提前猜测特定设备上哪些 SCSI 命令会成功或失败。

因此，运行 udisk 时，预计ioerr_cnt每十分钟就会上升一次。

我不会想每当我使用程序检查 SMART 数据或类似数据时，查看内核日志中的错误。 （尽管我不知道内核使用什么机制来确定这些失败不够有趣）。我预计 udisks 等不会希望进行长时间的重试或重置（这可能会导致日志中出现某些内容），因为它可以判断故障是由不受支持的功能引起的。

（似乎fatrace没有显示此设备被 udisks 打开，因为它没有显示任何设备打开。请参阅：为什么“fatrace”无法检测到某些打开事件（udisks /dev/sda）？）。

$ ps -ax|grep udisksd
  810 ?        Ssl    0:13 /usr/libexec/udisks2/udisksd
$ sudo strace -t -f -p 810
[pid   810] 14:11:09 clone(strace: Process 26543 attached
child_stack=0x7f8fc551ddf0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7f8fc551e9d0, tls=0x7f8fc551e700, child_tidptr=0x7f8fc551e9d0) = 26543
[pid 26543] 14:11:09 set_robust_list(0x7f8fc551e9e0, 24 <unfinished ...>
[pid   810] 14:11:09 poll([{fd=4, events=POLLIN}, {fd=8, events=0}, {fd=9, events=0}, {fd=11, events=POLLIN}, {fd=13, events=POLLIN}], 5, 599968 <unfinished ...>
[pid 26543] 14:11:09 <... set_robust_list resumed> ) = 0
[pid 26543] 14:11:09 prctl(PR_SET_NAME, "pool") = 0
[pid 26543] 14:11:09 openat(AT_FDCWD, "/dev/sda", O_RDONLY|O_NONBLOCK) = 14
[pid 26543] 14:11:09 ioctl(14, SG_IO, {guard='Q', protocol=BSG_PROTOCOL_SCSI, subprotocol=BSG_SUB_PROTOCOL_SCSI_CMD, request_len=16, request="\x85\x06\x20\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xe5\x00", request_tag=0, request_attr=0, request_priority=0, request_extra=0, max_response_len=32, dout_iovec_count=0, dout_xfer_len=0, din_iovec_count=0, din_xfer_len=0, dout_xferp=NULL, timeout=5000, flags=0, usr_ptr=0, response_len=0, response="", din_xferp=NULL, driver_status=0, transport_status=0, device_status=0, retry_delay=0, info=0, duration=0, response_len=0, din_resid=0, dout_resid=0, generated_tag=0}) = -1 EINVAL (Invalid argument)
[pid 26543] 14:11:09 ioctl(14, SG_IO, {interface_id='S', dxfer_direction=SG_DXFER_NONE, cmd_len=16, cmdp="\x85\x06\x20\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xe5\x00", mx_sb_len=32, iovec_count=0, dxfer_len=0, timeout=5000, flags=0, status=0x2, masked_status=0x1, msg_status=0, sb_len_wr=22, sbp="\x72\x01\x00\x1d\x00\x00\x00\x0e\x09\x0c\x00\x00\x00\xff\x00\x00\x00\x00\x00\x00\x00\x50", host_status=0, driver_status=0x8, resid=0, duration=11, info=SG_INFO_CHECK}) = 0
[pid 26543] 14:11:09 close(14)          = 0
[pid 26543] 14:11:09 openat(AT_FDCWD, "/dev/sda", O_RDONLY|O_NOCTTY|O_NONBLOCK|O_CLOEXEC) = 14
[pid 26543] 14:11:09 fstat(14, {st_mode=S_IFBLK|0660, st_rdev=makedev(8, 0), ...}) = 0
[pid 26543] 14:11:09 ioctl(14, BLKGETSIZE64, [500107862016]) = 0
[pid 26543] 14:11:09 readlinkat(AT_FDCWD, "/sys/dev/block/8:0", "../../devices/pci0000:00/0000:00"..., 99) = 78
[pid 26543] 14:11:09 openat(AT_FDCWD, "/", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 16
[pid 26543] 14:11:09 openat(16, "sys", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 17
[pid 26543] 14:11:09 fstat(17, {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
[pid 26543] 14:11:09 close(16)          = 0
...
[pid 26543] 14:11:09 ioctl(14, SG_IO, {interface_id='S', dxfer_direction=SG_DXFER_FROM_DEV, cmd_len=16, cmdp="\x85\x08\x2e\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\xec\x00", mx_sb_len=32, iovec_count=0, dxfer_len=512, timeout=2000, flags=0, dxferp="\x7a\x42\xff\x3f\x37\xc8\x10\x00\x00\x00\x00\x00\x3f\x00\x00\x00\x00\x00\x00\x00\x20\x20\x20\x20\x20\x20\x20\x20\x58\x57\x31\x37"..., status=0x2, masked_status=0x1, msg_status=0, sb_len_wr=22, sbp="\x72\x01\x00\x1d\x00\x00\x00\x0e\x09\x0c\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x50", host_status=0, driver_status=0x8, resid=0, duration=7, info=SG_INFO_CHECK}) = 0
[pid 26543] 14:11:09 ioctl(14, SG_IO, {interface_id='S', dxfer_direction=SG_DXFER_FROM_DEV, cmd_len=16, cmdp="\x85\x08\x2e\x00\xd1\x00\x01\x00\x00\x00\x4f\x00\xc2\x00\xb0\x00", mx_sb_len=32, iovec_count=0, dxfer_len=512, timeout=2000, flags=0, dxferp="\x10\x00\x01\x33\xc8\xc8\x00\x00\x00\x00\x00\x00\x00\x00\x03\x15\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x04\x00\x00\x00\x00\x00"..., status=0x2, masked_status=0x1, msg_status=0, sb_len_wr=22, sbp="\x72\x01\x00\x1d\x00\x00\x00\x0e\x09\x0c\x00\x00\x00\x00\x00\x00\x00\x4f\x00\xc2\x00\x50", host_status=0, driver_status=0x8, resid=0, duration=30, info=SG_INFO_CHECK}) = 0
[pid 26543] 14:11:09 ioctl(14, SG_IO, {interface_id='S', dxfer_direction=SG_DXFER_FROM_DEV, cmd_len=16, cmdp="\x85\x08\x2e\x00\xd0\x00\x01\x00\x00\x00\x4f\x00\xc2\x00\xb0\x00", mx_sb_len=32, iovec_count=0, dxfer_len=512, timeout=2000, flags=0, dxferp="\x10\x00\x01\x2f\x00\xc8\xc8\x00\x00\x00\x00\x00\x00\x00\x03\x27\x00\x8e\x8d\x6c\x07\x00\x00\x00\x00\x00\x04\x32\x00\x60\x60\x46"..., status=0x2, masked_status=0x1, msg_status=0, sb_len_wr=22, sbp="\x72\x01\x00\x1d\x00\x00\x00\x0e\x09\x0c\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x50", host_status=0, driver_status=0x8, resid=0, duration=18, info=SG_INFO_CHECK}) = 0
[pid 26543] 14:11:09 ioctl(14, SG_IO, {interface_id='S', dxfer_direction=SG_DXFER_NONE, cmd_len=16, cmdp="\x85\x06\x20\x00\xda\x00\x00\x00\x00\x00\x4f\x00\xc2\x00\xb0\x00", mx_sb_len=32, iovec_count=0, dxfer_len=0, timeout=2000, flags=0, status=0x2, masked_status=0x1, msg_status=0, sb_len_wr=22, sbp="\x72\x01\x00\x1d\x00\x00\x00\x0e\x09\x0c\x00\x00\x00\x00\x00\x00\x00\x4f\x00\xc2\x00\x50", host_status=0, driver_status=0x8, resid=0, duration=37, info=SG_INFO_CHECK}) = 0

相关内容