Details
-
Bug
-
Resolution: Fixed
-
Major
-
Lustre 2.10.3
-
None
-
centos7, skylake, opa, zfs 0.7.6, lustre 2.10.3 + https://review.whamcloud.com/#/c/29992/. kernel nopti on servers, pti on clients, 3.10.0-693.17.1.el7.x86_64
-
3
-
9223372036854775807
Description
Hiya,
these appeared last night.
john100,101 are clients. arkle3,6 are OSS's. transom1 is running the fabric manager.
in light of the similar looking LU-9305 I thought I would create this ticket.
we run default (4M) rpcs on clients and servers. our OSTs are each 4 raidz3's in 1 zpool, and have recordsize=2M. 2 OSTs per OSS. 16 OSTs total.
I suppose it could be a OPA network glitch, but it affected 2 clients and 2 servers so that seems unlikely.
we have just moved from zfs 0.7.5 to zfs 0.7.6. we ran ior and mdtest after this change and they were fine. these errors occurred a couple of days after that.
Feb 19 23:45:12 arkle3 kernel: LustreError: 168-f: dagg-OST0005: BAD WRITE CHECKSUM: from 12345-192.168.44.200@o2ib44 inode [0x20000c02e:0x9ef:0x0] object 0x0:2683981 extent [331258364-335450111]: client csum efde5b36, server csum 54e81a18 Feb 19 23:45:12 john100 kernel: LNetError: 899:0:(lib-ptl.c:190:lnet_try_match_md()) Matching packet from 12345-192.168.44.33@o2ib44, match 1591386600741136 length 1048576 too big: 1048176 left, 1048176 allowed Feb 19 23:45:12 arkle3 kernel: LNet: Using FMR for registration Feb 19 23:45:12 arkle3 kernel: LustreError: 298612:0:(events.c:449:server_bulk_callback()) event type 5, status -61, desc ffff881764648600 Feb 19 23:45:12 arkle3 kernel: LustreError: 298612:0:(events.c:449:server_bulk_callback()) event type 3, status -61, desc ffff881764648600 Feb 19 23:45:12 arkle3 kernel: LustreError: 337237:0:(ldlm_lib.c:3242:target_bulk_io()) @@@ network error on bulk WRITE req@ffff881687561450 x1591386600741136/t0(0) o4->8c8018f7-2e02-6c2b-cbcf-29133ecabf02@192.168.44.200@o2ib44:173/0 lens 608/448 e 0 to 0 dl 1519044318 ref 1 fl Interpret:/0/0 rc 0/0 Feb 19 23:45:12 arkle3 kernel: Lustre: dagg-OST0005: Bulk IO write error with 8c8018f7-2e02-6c2b-cbcf-29133ecabf02 (at 192.168.44.200@o2ib44), client will retry: rc = -110 Feb 19 23:45:12 arkle3 kernel: LNet: Skipped 1 previous similar message Feb 19 23:45:12 john101 kernel: LNetError: 904:0:(lib-ptl.c:190:lnet_try_match_md()) Matching packet from 12345-192.168.44.36@o2ib44, match 1591895282655776 length 1048576 too big: 1048176 left, 1048176 allowed Feb 19 23:45:12 arkle6 kernel: LustreError: 298397:0:(events.c:449:server_bulk_callback()) event type 5, status -61, desc ffff8810cb714600 Feb 19 23:45:12 arkle6 kernel: LustreError: 298397:0:(events.c:449:server_bulk_callback()) event type 3, status -61, desc ffff8810cb714600 Feb 19 23:45:12 arkle6 kernel: LustreError: 42356:0:(ldlm_lib.c:3242:target_bulk_io()) @@@ network error on bulk WRITE req@ffff88276c3d5850 x1591895282655776/t0(0) o4->400cfa1c-7c7d-1d14-09ed-f6043574fd7c@192.168.44.201@o2ib44:173/0 lens 608/448 e 0 to 0 dl 1519044318 ref 1 fl Interpret:/0/0 rc 0/0 Feb 19 23:45:12 arkle6 kernel: Lustre: dagg-OST000b: Bulk IO write error with 400cfa1c-7c7d-1d14-09ed-f6043574fd7c (at 192.168.44.201@o2ib44), client will retry: rc = -110 Feb 19 23:45:12 john100 kernel: LustreError: 132-0: dagg-OST0005-osc-ffff88015a1ad800: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.44.33@o2ib44 inode [0x20000c02e:0x9ef:0x0] object 0x0:2683981 extent [331258364-335450111], original client csum efde5b36 (type 4), server csum 54e81a18 (type 4), client csum now efde5b36 Feb 19 23:45:12 john100 kernel: LustreError: 924:0:(osc_request.c:1611:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff880e7a9b4e00 x1591386600740944/t197580821951(197580821951) o4->dagg-OST0005-osc-ffff88015a1ad800@192.168.44.33@o2ib44:6/4 lens 608/416 e 0 to 0 dl 1519044319 ref 2 fl Interpret:RM/0/0 rc 0/0 Feb 19 23:45:13 arkle3 kernel: LustreError: 168-f: dagg-OST0005: BAD WRITE CHECKSUM: from 12345-192.168.44.200@o2ib44 inode [0x20000c02e:0x9ef:0x0] object 0x0:2683981 extent [331258364-335450111]: client csum efde5b36, server csum df7fda9d Feb 19 23:45:13 john100 kernel: LustreError: 132-0: dagg-OST0005-osc-ffff88015a1ad800: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.44.33@o2ib44 inode [0x20000c02e:0x9ef:0x0] object 0x0:2683981 extent [331258364-335450111], original client csum efde5b36 (type 4), server csum df7fda9d (type 4), client csum now efde5b36 Feb 19 23:45:13 john100 kernel: LustreError: 911:0:(osc_request.c:1611:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff8807492fe300 x1591386600747696/t197580821955(197580821955) o4->dagg-OST0005-osc-ffff88015a1ad800@192.168.44.33@o2ib44:6/4 lens 608/416 e 0 to 0 dl 1519044320 ref 2 fl Interpret:RM/0/0 rc 0/0 Feb 19 23:45:15 arkle3 kernel: LustreError: 168-f: dagg-OST0005: BAD WRITE CHECKSUM: from 12345-192.168.44.200@o2ib44 inode [0x20000c02e:0x9ef:0x0] object 0x0:2683981 extent [331258364-335450111]: client csum efde5b36, server csum 87da008a Feb 19 23:45:15 john100 kernel: LustreError: 132-0: dagg-OST0005-osc-ffff88015a1ad800: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.44.33@o2ib44 inode [0x20000c02e:0x9ef:0x0] object 0x0:2683981 extent [331258364-335450111], original client csum efde5b36 (type 4), server csum 87da008a (type 4), client csum now efde5b36 Feb 19 23:45:15 john100 kernel: LustreError: 910:0:(osc_request.c:1611:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff880eb3d51b00 x1591386600751360/t197580821956(197580821956) o4->dagg-OST0005-osc-ffff88015a1ad800@192.168.44.33@o2ib44:6/4 lens 608/416 e 0 to 0 dl 1519044322 ref 2 fl Interpret:RM/0/0 rc 0/0 Feb 19 23:45:18 arkle3 kernel: LustreError: 168-f: dagg-OST0005: BAD WRITE CHECKSUM: from 12345-192.168.44.200@o2ib44 inode [0x20000c02e:0x9ef:0x0] object 0x0:2683981 extent [331258364-335450111]: client csum efde5b36, server csum 1cc7a793 Feb 19 23:45:18 john100 kernel: LustreError: 132-0: dagg-OST0005-osc-ffff88015a1ad800: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.44.33@o2ib44 inode [0x20000c02e:0x9ef:0x0] object 0x0:2683981 extent [331258364-335450111], original client csum efde5b36 (type 4), server csum 1cc7a793 (type 4), client csum now efde5b36
full log attached.
there were hung and unkillable user processes on the 2 clients afterwards. a reboot of the 2 clients has cleared up the looping messages of the type shown below.
Feb 20 14:28:15 arkle6 kernel: LustreError: 298395:0:(events.c:449:server_bulk_callback()) event type 3, status -61, desc ffff882e25ef2c00 Feb 20 14:28:19 arkle3 kernel: LustreError: 298609:0:(events.c:449:server_bulk_callback()) event type 5, status -61, desc ffff88176544be00 Feb 20 14:28:19 arkle3 kernel: LustreError: 298611:0:(events.c:449:server_bulk_callback()) event type 5, status -61, desc ffff8814072e0200 Feb 20 14:28:19 arkle3 kernel: LustreError: 298609:0:(events.c:449:server_bulk_callback()) event type 3, status -61, desc ffff88176544be00 Feb 20 14:28:19 arkle3 kernel: LustreError: 298611:0:(events.c:449:server_bulk_callback()) event type 3, status -61, desc ffff8814072e0200 Feb 20 14:28:47 arkle6 kernel: LustreError: 298394:0:(events.c:449:server_bulk_callback()) event type 5, status -61, desc ffff882e25ef3800 Feb 20 14:28:47 arkle6 kernel: LustreError: 298394:0:(events.c:449:server_bulk_callback()) event type 3, status -61, desc ffff882e25ef3800 Feb 20 14:28:51 arkle3 kernel: LustreError: 298609:0:(events.c:449:server_bulk_callback()) event type 5, status -61, desc ffff881615f0f000 Feb 20 14:28:51 arkle3 kernel: LustreError: 298610:0:(events.c:449:server_bulk_callback()) event type 5, status -61, desc ffff880be3931c00 Feb 20 14:28:51 arkle3 kernel: LustreError: 298609:0:(events.c:449:server_bulk_callback()) event type 3, status -61, desc ffff881615f0f000
cheers,
robin
Attachments
Issue Links
Activity
Hi Robin,
From both client and server would be great, separated into two files respectively.
thanks
amir
Hi Amir,
the incidents are rare. the last one was 3 days ago. probably over-quota related. we've tried to reproduce them but haven't managed to with simple dd's etc.
I guess I could turn on 'net neterror' debug and write a script to tail syslog and automatically run dk's when it sees the next burst of CHECKSUM's.
does that sound ok?
do you want dk just from servers or clients too?
cheers,
robin
Is it possible to turn on net logging and capture logs for a short period of time when this happens:
lctl set_param debug=+"net neterror"
lctl dk > log
Hi Andreas,
on our big /dagg filesystem I left the zfs recordsize at 2MB. it's a significant performance loss to set it to 1M - halves the size of all the i/o's to disks.
however these events also happen to the /home lustre filesystem where the zfs recordsize is 1M and always has been. those are in the logs above.
oh, damn, looks like /sys/module/zfs/parameters/zfs_max_recordsize=2M for these /home filesystems though, even though nothing uses that. that must be a left over from testing.
I haven't tried to change the RPC size for anything, sorry. all the lustre filesystems in this cluster seem to be using max_pages_per_rpc=1024. is that the right number to look at? we haven't tweaked anything around that. I just assumed 4M was the default these days.
we aren't using any cap_mask= options for hfi1. on clients it is
options hfi1 sge_copy_mode=2 krcvqs=4 piothreshold=0 wss_threshold=70 max_mtu=10240 eager_buffer_size=4194304
and on lustre servers it's
options hfi1 sge_copy_mode=2 krcvqs=8 piothreshold=0 wss_threshold=70
with max_mtu=10240 being a driver default, and the default eager_buffer_size is 2097152. but AFAIK lustre's verbs doesn't use that eager_buffer stuff - it's for PSM2 comms I think.
I actually don't know what most of these options do. it's just what various Intel people and docs told us was good.
only krcvqs seems to impact performance (<=half a socket seems best), so we've tuned that a bit.
Oleg - yes it's a hdf5 library. we're looking into the hdf5 code and will try to communicate with the user and see what options they used when calling it in parallel. I suspect it uses whatever MPIIO uses, but haven't looked at either of those in years.
thanks for looking into this.
cheers,
robin
What is the hdf5 library (I assume by the H5 prefix) do you use for this io (if any), does it use direct IO internally by any chance?
Hi Robin, did you reduce the recordsize to 1MB on the filesystem? We haven't done any testing ourselves with larger recordsize. The clients would need to be remounted to also get a smaller RPC size (they default to RPC size == max blocksize for ZFS at mount).
Also, are you using TID RDMA (cap_mask=....) for your OPA connection? We've seen problems with that under load, and if yes it should be disabled.
a bunch more CHECKSUM and LNet errors today. this lot were again definitely associated with over quota. I don't know if all the incidents are though...
I guess I'd be very worried if these weren't purely over quota events, which is why the read checksum messages were very alarming.
any thoughts on whether these are just from quota events or not? is there any way we can easily tell that?
I'll attach messages for today's errors to this ticket in a min.
the user has many (~1100 so far) of the below in their job output. looks like they have ~127 write processes across their 28 nodes and 896 cores. the code is looping on the nodes trying to complete the writes.
HDF5-DIAG: Error detected in HDF5 (1.10.1) MPI-process 168:
#000: H5Dio.c line 269 in H5Dwrite(): can't prepare for writing data
major: Dataset
minor: Write failed
#001: H5Dio.c line 345 in H5D__pre_write(): can't write data
major: Dataset
minor: Write failed
#002: H5Dio.c line 791 in H5D__write(): can't write data
major: Dataset
minor: Write failed
#003: H5Dcontig.c line 642 in H5D__contig_write(): contiguous write failed
major: Dataset
minor: Write failed
#004: H5Dselect.c line 309 in H5D__select_write(): write error
major: Dataspace
minor: Write failed
#005: H5Dselect.c line 220 in H5D__select_io(): write error
major: Dataspace
minor: Write failed
#006: H5Dcontig.c line 1267 in H5D__contig_writevv(): can't perform vectorized sieve buffer write
major: Dataset
minor: Can't operate on object
#007: H5VM.c line 1500 in H5VM_opvv(): can't perform operation
major: Internal error (too specific to document in detail)
minor: Can't operate on object
#008: H5Dcontig.c line 1014 in H5D__contig_writevv_sieve_cb(): block write failed
major: Dataset
minor: Write failed
#009: H5Fio.c line 195 in H5F_block_write(): write through page buffer failed
major: Low-level I/O
minor: Write failed
#010: H5PB.c line 1041 in H5PB_write(): write through metadata accumulator failed
major: Page Buffering
minor: Write failed
#011: H5Faccum.c line 834 in H5F__accum_write(): file write failed
major: Low-level I/O
minor: Write failed
#012: H5FDint.c line 308 in H5FD_write(): driver write request failed
major: Virtual File Layer
minor: Write failed
#013: H5FDsec2.c line 810 in H5FD_sec2_write(): file write failed: time = Fri Mar 16 03:17:20 2018
, filename = './L35_N2650/snapshot_050.24.hdf5', file descriptor = 24, errno = 122, error message = 'Disk quota exceeded', buf = 0x2b07c54a3010, total write size = 31457280, bytes this sub-write = 31457280, bytes actually written = 184467440737052
major: Low-level I/O
minor: Write failed
cheers,
robin
Hi Nathaniel,
all messages for the lustre servers and from the 7 clients affected so far for all of 2018 have been uploaded.
grep for CHECKSUM
if you'd like console logs from these machines too then please let us know.
cheers,
robin
Below are instructions for uploading logs to our write-only ftp site:
Sometimes the diagnostic data collected as part of Lustre troubleshooting is too large to be attached to a JIRA ticket. For these cases, HPDD provides an anonymous write-only FTP upload service. In order to use this service, you'll need an FTP client (e.g. ncftp, ftp, etc.) and a JIRA issue. Use the 'uploads' directory and create a new subdirectory using your Jira issue as a name.
In the following example, there are three debug logs in a single directory and the JIRA issue LU-4242 has been created. After completing the upload, please update the relevant issue with a note mentioning the upload, so that our engineers know where to find your logs.
$ ls -lh total 333M -rw-r--r-- 1 mjmac mjmac 98M Feb 23 17:36 mds-debug -rw-r--r-- 1 mjmac mjmac 118M Feb 23 17:37 oss-00-debug -rw-r--r-- 1 mjmac mjmac 118M Feb 23 17:37 oss-01-debug $ ncftp ftp.hpdd.intel.com NcFTP 3.2.2 (Sep 04, 2008) by Mike Gleason (http://www.NcFTP.com/contact/). Connecting to 99.96.190.235... (vsFTPd 2.2.2) Logging in... Login successful. Logged in to ftp.hpdd.intel.com. ncftp / > cd uploads Directory successfully changed. ncftp /uploads > mkdir LU-4242 ncftp /uploads > cd LU-4242 Directory successfully changed. ncftp /uploads/LU-4242 > put * mds-debug: 97.66 MB 11.22 MB/s oss-00-debug: 117.19 MB 11.16 MB/s oss-01-debug: 117.48 MB 11.18 MB/s ncftp /uploads/LU-4242 >
Please note that this is a WRITE-ONLY FTP service, so you will not be able to see (with ls) the files or directories you've created, nor will you (or anyone other than HPDD staff) be able to see or read them.
Hi Amir,
I setup a script to tail syslog and run dk on anything that hits a CHECKSUM error.
however it doesn't appear safe to turn on +net.
I've seen 132 stack traces like these across all the servers and clients since I turned on +net this afternoon, so I've now turned it off.
I also have one client that looks permanently upset now (john50 is a client, arkle3 is an OSS)
I'll reboot the client as (IIRC) this has cleared up this kind of problem in the past
debug +neterror (a default) is still enabled and the dk will still catch that. hopefully that will be enough for you.
cheers,
robin