$ 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
:(
실제로 아무것도 하지 않고 약 1분 후:
$ 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
blktraceSCSI 명령을 모니터링하고 오류를 표시할 수 있어야 합니다. 잠시 동안 실행했는데 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 장치에 대해 표시되는 프로세스가 없는 것 같습니다. 그러나 오류가 발생할 때( cd /dev && sudo fatrace -c) 관련 open() 호출도 표시되지 않습니다.
일반적으로 이러한 이벤트(위에서 언급한 대로 6 ioctl과 5 ioerr) 사이의 간격은 정확히 10분입니다.
답변1
udisks는 10분마다 드라이버를 폴링합니다.영리한데이터.
나는 서로 다른 드라이브가 폴링할 수 있는 서로 다른 항목을 갖기를 원합니다. 이것은 의미가 있습니다. udisk는 특정 장치에서 어떤 SCSI 명령이 성공하거나 실패할지 미리 추측하지 못할 수도 있습니다.
따라서 udisk를 실행할 때 ioerr_cnt10분마다 상승할 것으로 예상하십시오.
나는하지 않을 것이다생각하다SMART 데이터나 유사한 데이터를 확인하기 위해 프로그램을 사용할 때마다 커널 로그에 오류가 표시됩니다. (비록 이러한 실패가 충분히 흥미롭지 않다는 것을 결정하기 위해 커널이 어떤 메커니즘을 사용하는지 모르지만). 지원되지 않는 기능으로 인해 오류가 발생했음을 알 수 있기 때문에 udisk 등이 오랜 재시도 또는 재설정(로그에 무언가 표시될 수 있음)을 수행하기를 원할 것이라고는 기대하지 않습니다.
( 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