<html dir="ltr">
<head>
<meta http-equiv="Content-Type" content="text/html; charset=iso-8859-1">
<style id="owaParaStyle" type="text/css">P {margin-top:0;margin-bottom:0;}</style>
</head>
<body ocsi="0" fpstyle="1">
<div style="direction: ltr;font-family: Tahoma;color: #000000;font-size: 10pt;">Hi All,<br>
On Friday 1 of the 4 I/O nodes in our lustre network began logging the following slow start_page_write errors for some OSTs:<br>
--------------------------------------------------- messages -----------------------------------------------------------------------------------<br>
Jul 15 12:55:32 IO-10 heartbeat: [21053]: info: Checking status of STONITH device [IPMI STONITH device ]<br>
Jul 15 12:55:32 IO-10 heartbeat: [16746]: info: Managed STONITH-stat process 21053 exited with return code 0.<br>
Jul 15 13:02:25 IO-10 kernel: Lustre: 18616:0:(filter_io.c:652:filter_preprw_write()) es1-OST000b: slow start_page_write 44s<br>
Jul 15 13:02:25 IO-10 kernel: Lustre: 18688:0:(filter_io_26.c:779:filter_commitrw_write()) es1-OST000b: slow direct_io 44s<br>
Jul 15 13:02:57 IO-10 kernel: Lustre: 18531:0:(filter_io.c:652:filter_preprw_write()) es1-OST000b: slow start_page_write 38s<br>
Jul 15 13:03:29 IO-10 kernel: Lustre: 18566:0:(filter_io_26.c:779:filter_commitrw_write()) es1-OST000b: slow direct_io 32s<br>
Jul 15 13:03:29 IO-10 kernel: host2: SRP abort called<br>
Jul 15 13:03:29 IO-10 last message repeated 4 times<br>
Jul 15 13:03:29 IO-10 kernel: host2: SRP reset_device called<br>
Jul 15 13:03:29 IO-10 kernel: host2: ib_srp: SRP reset_host called state 0 qp_err 0<br>
Jul 15 13:03:39 IO-10 kernel: sd 2:0:0:12: SCSI error: return code = 0x06000000<br>
Jul 15 13:03:39 IO-10 kernel: end_request: I/O error, dev sdag, sector 15012385240<br>
Jul 15 13:03:39 IO-10 kernel: device-mapper: multipath: Failing path 66:0.<br>
Jul 15 13:03:39 IO-10 kernel: sd 2:0:0:12: SCSI error: return code = 0x06000000<br>
Jul 15 13:03:39 IO-10 kernel: end_request: I/O error, dev sdag, sector 15012386176<br>
Jul 15 13:03:39 IO-10 kernel: sd 2:0:0:12: SCSI error: return code = 0x06000000<br>
Jul 15 13:03:39 IO-10 kernel: end_request: I/O error, dev sdag, sector 15012386696<br>
Jul 15 13:03:39 IO-10 kernel: sd 2:0:0:12: SCSI error: return code = 0x06000000<br>
Jul 15 13:03:39 IO-10 kernel: end_request: I/O error, dev sdag, sector 15012385256<br>
Jul 15 13:03:39 IO-10 kernel: sd 2:0:0:12: SCSI error: return code = 0x06000000<br>
Jul 15 13:03:39 IO-10 kernel: end_request: I/O error, dev sdag, sector 15012385568<br>
Jul 15 13:03:39 IO-10 multipathd: 66:0: mark as failed <br>
Jul 15 13:03:39 IO-10 multipathd: lun_12: remaining active paths: 1 <br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18538:0:(filter_io_26.c:779:filter_commitrw_write()) es1-OST000b: slow direct_io 50s<br>
Jul 15 13:04:35 IO-10 kernel: Lustre: 18447:0:(filter_io_26.c:779:filter_commitrw_write()) es1-OST000b: slow direct_io 31s<br>
Jul 15 13:04:35 IO-10 kernel: Lustre: 18525:0:(filter_io.c:652:filter_preprw_write()) es1-OST000b: slow start_page_write 46s<br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18598:0:(lustre_fsfilt.h:318:fsfilt_commit_wait()) es1-OST000b: slow journal start 56s<br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18393:0:(filter_io_26.c:792:filter_commitrw_write()) es1-OST000b: slow commitrw commit 56s<br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18393:0:(filter_io_26.c:792:filter_commitrw_write()) Skipped 1 previous similar message<br>
Jul 15 13:04:35 IO-10 kernel: Lustre: 18739:0:(lustre_fsfilt.h:318:fsfilt_commit_wait()) es1-OST000b: slow journal start 46s<br>
Jul 15 13:04:35 IO-10 kernel: Lustre: 18739:0:(filter_io_26.c:792:filter_commitrw_write()) es1-OST000b: slow commitrw commit 46s<br>
Jul 15 13:04:35 IO-10 kernel: Lustre: 18422:0:(lustre_fsfilt.h:318:fsfilt_commit_wait()) es1-OST000b: slow journal start 31s<br>
Jul 15 13:04:35 IO-10 kernel: Lustre: 18422:0:(lustre_fsfilt.h:318:fsfilt_commit_wait()) Skipped 5 previous similar messages<br>
Jul 15 13:04:35 IO-10 kernel: Lustre: 18422:0:(filter_io_26.c:792:filter_commitrw_write()) es1-OST000b: slow commitrw commit 31s<br>
Jul 15 13:04:35 IO-10 kernel: Lustre: 18422:0:(filter_io_26.c:792:filter_commitrw_write()) Skipped 5 previous similar messages<br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18644:0:(lustre_fsfilt.h:318:fsfilt_commit_wait()) es1-OST000b: slow journal start 56s<br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18644:0:(lustre_fsfilt.h:318:fsfilt_commit_wait()) Skipped 5 previous similar messages<br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18644:0:(filter_io_26.c:792:filter_commitrw_write()) es1-OST000b: slow commitrw commit 56s<br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18644:0:(filter_io_26.c:792:filter_commitrw_write()) Skipped 4 previous similar messages<br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18598:0:(lustre_fsfilt.h:318:fsfilt_commit_wait()) Skipped 4 previous similar messages<br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18766:0:(filter_io_26.c:779:filter_commitrw_write()) es1-OST000b: slow direct_io 55s<br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18766:0:(filter_io_26.c:779:filter_commitrw_write()) Skipped 1 previous similar message<br>
Jul 15 13:05:07 IO-10 kernel: Lustre: 18650:0:(filter_io_26.c:779:filter_commitrw_write()) es1-OST000b: slow direct_io 31s<br>
Jul 15 13:05:07 IO-10 kernel: Lustre: 18650:0:(filter_io_26.c:779:filter_commitrw_write()) Skipped 2 previous similar messages<br>
Jul 15 13:05:08 IO-10 kernel: host1: SRP abort called<br>
Jul 15 13:05:08 IO-10 kernel: host1: SRP reset_device called<br>
Jul 15 13:05:08 IO-10 kernel: host1: ib_srp: SRP reset_host called state 0 qp_err 0<br>
Jul 15 13:05:18 IO-10 kernel: sd 1:0:0:12: SCSI error: return code = 0x00000002<br>
Jul 15 13:05:18 IO-10 kernel: end_request: I/O error, dev sdm, sector 861112<br>
Jul 15 13:05:18 IO-10 kernel: device-mapper: multipath: Failing path 8:192.<br>
Jul 15 13:05:18 IO-10 kernel: Buffer I/O error on device dm-11, logical block 107639<br>
Jul 15 13:05:18 IO-10 kernel: lost page write due to I/O error on dm-11<br>
Jul 15 13:05:18 IO-10 kernel: LDISKFS-fs error (device dm-11): kmmpd: Error writing to MMP block<br>
Jul 15 13:05:18 IO-10 kernel: Remounting filesystem read-only<br>
Jul 15 13:05:18 IO-10 kernel: LustreError: 18499:0:(fsfilt-ldiskfs.c:438:fsfilt_ldiskfs_brw_start()) can't get handle for 99 credits: rc = -3<br>
0<br>
Jul 15 13:05:18 IO-10 kernel: Lustre: 18657:0:(filter_io_26.c:779:filter_commitrw_write()) es1-OST000b: slow direct_io 36s<br>
Jul 15 13:05:18 IO-10 multipathd: 8:192: mark as failed <br>
Jul 15 13:05:18 IO-10 kernel: Lustre: 18657:0:(filter_io_26.c:779:filter_commitrw_write()) Skipped 1 previous similar message<br>
Jul 15 13:05:18 IO-10 kernel: Buffer I/O error on device dm-11, logical block 79917<br>
Jul 15 13:05:18 IO-10 multipathd: lun_12: remaining active paths: 0 <br>
Jul 15 13:05:18 IO-10 kernel: lost page write due to I/O error on dm-11<br>
Jul 15 13:05:18 IO-10 kernel: Aborting journal on device dm-11.<br>
Jul 15 13:05:18 IO-10 kernel: LustreError: 19103:0:(obd.h:1188:obd_transno_commit_cb()) es1-OST000b: transno 608801934 commit error: 2<br>
<br>
------------------------------------------- end messages -------------------------------------------------------------------------<br>
<br>
<br>
I then tried to fsck -n one of the mentioned devices for inconsistencies at which point I noticed on a kernel panic. Rebooted the machine which appears to not be able to establish a connection or LNET:<br>
-----------------------------------------------------messages ---------------------------------------------------------------------<br>
<div>Jul 18 09:24:44 IO-10 OpenSM[28708]: /var/log/opensm.log log file opened <br>
Jul 18 09:24:44 IO-10 OpenSM[28708]: OpenSM 3.1.11 <br>
Jul 18 09:24:44 IO-10 OpenSM[28708]: Entering STANDBY state <br>
Jul 18 09:28:23 IO-10 run_srp_daemon[28757]: failed srp_daemon: [HCA=mlx4_0] [port=2] [exit status=110]. Will try to restart srp_daemon perio<br>
dically. No more warnings will be issued in the next 7200 seconds if the same problem repeats<br>
Jul 18 09:28:23 IO-10 run_srp_daemon[28763]: failed srp_daemon: [HCA=mlx4_0] [port=1] [exit status=110]. Will try to restart srp_daemon perio<br>
dically. No more warnings will be issued in the next 7200 seconds if the same problem repeats<br>
Jul 18 09:28:24 IO-10 run_srp_daemon[28769]: starting srp_daemon: [HCA=mlx4_0] [port=2]<br>
Jul 18 09:28:25 IO-10 run_srp_daemon[28782]: starting srp_daemon: [HCA=mlx4_0] [port=1]<br>
Jul 18 09:33:10 IO-10 kernel: megasas: 00.00.03.15-RH1 Wed Nov. 21 10:29:45 PST 2007<br>
Jul 18 09:33:10 IO-10 kernel: Lustre: OBD class driver, http://www.lustre.org/<br>
Jul 18 09:33:10 IO-10 kernel: Lustre Version: 1.6.6<br>
Jul 18 09:33:10 IO-10 kernel: Build Version: 1.6.6-1.6.6-ddn3.1-20090527173746<br>
Jul 18 09:33:10 IO-10 kernel: Lustre: 30493:0:(o2iblnd_modparams.c:324:kiblnd_tunables_init()) Concurrent sends 7 is lower than message queue<br>
size: 8, performance may drop slightly.<br>
Jul 18 09:33:10 IO-10 kernel: Lustre: Added LNI 10.1.0.229@o2ib [8/64]<br>
Jul 18 09:33:11 IO-10 kernel: Lustre: Lustre Client File System; http://www.lustre.org/<br>
Jul 18 09:33:34 IO-10 kernel: kjournald starting. Commit interval 5 seconds<br>
Jul 18 09:33:34 IO-10 kernel: LDISKFS-fs warning: checktime reached, running e2fsck is recommended<br>
Jul 18 09:33:34 IO-10 kernel: LDISKFS FS on dm-10, internal journal<br>
Jul 18 09:33:34 IO-10 kernel: LDISKFS-fs: recovery complete.<br>
Jul 18 09:33:34 IO-10 kernel: LDISKFS-fs: mounted filesystem with ordered data mode.<br>
Jul 18 09:33:34 IO-10 multipathd: dm-10: umount map (uevent) <br>
Jul 18 09:33:45 IO-10 kernel: kjournald starting. Commit interval 5 seconds<br>
Jul 18 09:33:45 IO-10 kernel: LDISKFS-fs warning: checktime reached, running e2fsck is recommended<br>
Jul 18 09:33:45 IO-10 kernel: LDISKFS FS on dm-10, internal journal<br>
Jul 18 09:33:45 IO-10 kernel: LDISKFS-fs: mounted filesystem with ordered data mode.<br>
Jul 18 09:33:45 IO-10 kernel: LDISKFS-fs: file extents enabled<br>
Jul 18 09:33:45 IO-10 kernel: LDISKFS-fs: mballoc enabled<br>
Jul 18 09:33:45 IO-10 kernel: LustreError: 137-5: UUID 'es1-OST000a_UUID' is not available for connect (no target)<br>
Jul 18 09:33:45 IO-10 kernel: LustreError: 30789:0:(ldlm_lib.c:1619:target_send_reply_msg()) @@@ processing error (-19) req@ffff8101a6992c00<br>
x5558026/t0 o8-><?>@<?>:0/0 lens 304/0 e 0 to 0 dl 1310999725 ref 1 fl Interpret:/0/0 rc -19/0<br>
Jul 18 09:33:45 IO-10 kernel: LustreError: 30789:0:(ldlm_lib.c:1619:target_send_reply_msg()) Skipped 2 previous similar messages<br>
Jul 18 09:33:45 IO-10 kernel: fsfilt_ldiskfs: no version for "ldiskfs_free_blocks" found: kernel tainted.<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: Filtering OBD driver; http://www.lustre.org/<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: 31834:0:(filter.c:868:filter_init_server_data()) RECOVERY: service es1-OST000a, 249 recoverable clients<br>
, last_rcvd 469616249<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: OST es1-OST000a now serving dev (es1-OST000a/15fae56a-7dae-ba24-4423-347c0a118367), but will be in reco<br>
very for at least 5:00, or until 249 clients reconnect. During this time new clients will not be allowed to connect. Recovery progress can be<br>
monitored by watching /proc/fs/lustre/obdfilter/es1-OST000a/recovery_status.<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: es1-OST000a.ost: set parameter quota_type=ug<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: Server es1-OST000a on device /dev/mpath/lun_11 has started<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: 30790:0:(ldlm_lib.c:1226:check_and_start_recovery_timer()) es1-OST000a: starting req@ffff8101a6992c00<br>
x5558026/t0 o8-><?>@<?>:0/0 lens 304/0 e 0 to 0 dl 1310999725 ref 1 fl Interpret:/0/0 rc -19/0<br>
Jul 18 09:33:45 IO-10 kernel: LustreError: 30789:0:(ldlm_lib.c:1619:target_send_reply_msg()) Skipped 2 previous similar messages<br>
Jul 18 09:33:45 IO-10 kernel: fsfilt_ldiskfs: no version for "ldiskfs_free_blocks" found: kernel tainted.<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: Filtering OBD driver; http://www.lustre.org/<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: 31834:0:(filter.c:868:filter_init_server_data()) RECOVERY: service es1-OST000a, 249 recoverable clients<br>
, last_rcvd 469616249<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: OST es1-OST000a now serving dev (es1-OST000a/15fae56a-7dae-ba24-4423-347c0a118367), but will be in reco<br>
very for at least 5:00, or until 249 clients reconnect. During this time new clients will not be allowed to connect. Recovery progress can be<br>
monitored by watching /proc/fs/lustre/obdfilter/es1-OST000a/recovery_status.<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: es1-OST000a.ost: set parameter quota_type=ug<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: Server es1-OST000a on device /dev/mpath/lun_11 has started<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: 30790:0:(ldlm_lib.c:1226:check_and_start_recovery_timer()) es1-OST000a: starting recovery timer<br>
Jul 18 09:33:45 IO-10 kernel: LustreError: 137-5: UUID 'es1-OST000b_UUID' is not available for connect (no target)<br>
Jul 18 09:33:45 IO-10 kernel: LustreError: Skipped 4 previous similar messages<br>
Jul 18 09:33:45 IO-10 kernel: LustreError: 30792:0:(ldlm_lib.c:1619:target_send_reply_msg()) @@@ processing error (-19) req@ffff8103185c9000<br>
x215076358/t0 o8-><?>@<?>:0/0 lens 304/0 e 0 to 0 dl 1310999725 ref 1 fl Interpret:/0/0 rc -19/0<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: 30794:0:(ldlm_lib.c:1567:target_queue_last_replay_reply()) es1-OST000a: 248 recoverable clients remain<br>
Jul 18 09:33:46 IO-10 kernel: Lustre: 30806:0:(ldlm_lib.c:1567:target_queue_last_replay_reply()) es1-OST000a: 247 recoverable clients remain<br>
Jul 18 09:33:46 IO-10 kernel: LustreError: 137-5: UUID 'es1-OST000e_UUID' is not available for connect (no target)<br>
Jul 18 09:33:46 IO-10 kernel: LustreError: 30815:0:(ldlm_lib.c:1619:target_send_reply_msg()) @@@ processing error (-19) req@ffff8102f093d000<br>
x220133374/t0 o8-><?>@<?>:0/0 lens 304/0 e 0 to 0 dl 1310999726 ref 1 fl Interpret:/0/0 rc -19/0<br>
Jul 18 09:33:46 IO-10 kernel: LustreError: 30815:0:(ldlm_lib.c:1619:target_send_reply_msg()) Skipped 11 previous similar messages<br>
Jul 18 09:33:46 IO-10 kernel: LustreError: Skipped 14 previous similar messages<br>
Jul 18 09:33:46 IO-10 kernel: Lustre: 30889:0:(ldlm_lib.c:1567:target_queue_last_replay_reply()) es1-OST000a: 245 recoverable clients remain<br>
Jul 18 09:33:46 IO-10 kernel: Lustre: 30889:0:(ldlm_lib.c:1567:target_queue_last_replay_reply()) Skipped 1 previous similar message<br>
Jul 18 09:33:47 IO-10 kernel: LustreError: 137-5: UUID 'es1-OST000b_UUID' is not available for connect (no target)<br>
Jul 18 09:33:47 IO-10 kernel: LustreError: 31004:0:(ldlm_lib.c:1619:target_send_reply_msg()) @@@ processing error (-19) req@ffff8102fea35450<br>
x33450807/t0 o8-><?>@<?>:0/0 lens 304/0 e 0 to 0 dl 1310999727 ref 1 fl Interpret:/0/0 rc -19/0<br>
Jul 18 09:33:47 IO-10 kernel: LustreError: 31004:0:(ldlm_lib.c:1619:target_send_reply_msg()) Skipped 47 previous similar messages<br>
Jul 18 09:33:47 IO-10 kernel: LustreError: Skipped 47 previous similar messages<br>
----------------------------------------------------------------------end messages ------------------------------------------------------------------------------------------<br>
<br>
I'm not seeing that Lustre is trying to recover at all. Any thoughts on where to go from here, Lustre (mounted at /scratch on clients) is starting to have problems cluster-wide.<br>
<br>
<br>
<br>
<div style="font-family: Tahoma; font-size: 13px;">
<div class="BodyFragment"><font size="2">
<div class="PlainText">Best Regards,<br>
--<br>
DaMiri Young<br>
System Engineer<br>
High Performance Computing Team<br>
CITC Academic Computing and User Services | UNT</div>
</font></div>
</div>
</div>
</div>
</body>
</html>