主页 / unix / 问题 / 435719
Accepted
sourcejedi
Asked: 2018-04-06 02:18:37 +0800 CST

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

  • 772
$ 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 错误，这些错误会导致从 suspend 恢复时崩溃。

内核版本：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 分钟。

linux-kernel scsi

1 个回答

  1. Best Answer

    udisks 每十分钟轮询一次驱动器，例如SMART数据。

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

    因此，在运行 udisks 时，可以预期ioerr_cnt每十分钟上升一次。

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

    （似乎fatrace没有显示该设备正在被 udisks 打开，因为它没有显示任何设备打开。请参阅：Why does `fatrace` not detection certain open events (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
    • 0

相关问题